Thursday, June 28, 2007

On Optimization and Tuning

I came across reading the basic principles of optimization and performance tuning from two books, and I actually thought of sharing it here:

Chapter 1 of Java Performance Tuning:

Don't Tune What You Don't Need to Tune

The most efficient tuning you can do is not to alter what works well. As they say, "If it ain't broke, don't fix it." This may seem obvious, but the temptation to tweak something just because you have thought of an improvement has a tendency to override this obvious statement.

Item 37 of Effective Java Programming:

More computing sins are committed in the name of efficiency (without necessarily achieving it) than for any other single reason—including blind stupidity.

– William A. Wulf

We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil.

– Donald E. Knuth

We follow two rules in the matter of optimization:

Rule 1. Don't do it.
Rule 2 (for experts only). Don't do it yet—that is, not until you have a perfectly clear and unoptimized solution.

– M. A. Jackson

As mentioned in the book above, performance issues should be thought of while the application is being designed. Therefore,

  • A good design is very important. Spend more time on the design or spend even more time to get things really working happily one day
  • Don't do optimization if:
    • You have not gotten something working yet
    • The measurable gain is insignificant

- yc, reading

Sunday, June 24, 2007

Troubleshooting JVM, Part I

Part of my job is to provide support for the famous issue tracker JIRA. Sometimes, we will have to look into client's stack traces and thread dumps to troubleshoot some memory or locking issues which usually caused by third-party plug-ins, Lucene, etc.

One of the excellent articles I came across is "Of Thread dumps and stack traces" written by Rajiv Shivane. There are also some people who have given me some good pointers, like, Jed (one of my co-workers, the memory guy) who pointed me to "JDK 1.5 - Trouble-shooting and Diagnostic Guide" and Rob who lent me the book "Inside the Java 2 Virtual Machine". Some other good reads that you shouldn't miss are:
Anyway, I spent some time in the weekend to play around with java, jmap and jhat.

Note: jhat 1.1 doesn't recognize 64-bit dump, simply download JDK 1.6 and use the jhat 2.0 which shipped together with it.

I will go through an java.lang.OutOfMemoryError: Java heap space test I have done and give as detailed information as I can. I have demonstrated this to some people earlier on at work using one of the classic examples: String vs. StringBuffer.


public class TestStringBuffer{

public static void main(String[] args)
throws Exception{

StringBuffer sb = new StringBuffer();
String s = "foobar";
String which = args[1];

for(int i = 0; i < Integer.parseInt(args[0]); i++){
if(which.equals("sb"))
sb.append(s);
else
s += s;

System.out.println(System.currentTimeMillis() + ": " + i);
Thread.currentThread().sleep(500);
}
}
}

Using the StringBuffer way, the program remains alright even after 10K of iterations. However, it dies immediately with String concatenation around 23th iteration. Before we look deeper into this, here are two interesting JVM startup parameters that you would like to know:
  • -XX:+HeapDumpOnOutOfMemoryError, requests HotSpot to generate a binary dump when it runs out of memory.
  • -Xmx1024m, allocates 1GB of heap space
The jmap utility can be used to produce snapshot of the currently running JVM process. The jhat utility does something similar however in a post-mortem manner.

For instance, running jmap on the StringBuffer case:

yclian@kate:~/devels/test/java$ $JAVA_HOME/bin/jmap -histo 29237
Attaching to process ID 29237, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_09-b03
Iterating over heap. This may take a while...
Unknown oop at 0x00002b7df8296da0
Oop's klass is null
Object Histogram:

Size Count Class description
-------------------------------------------------------
500112 4121 * ConstMethodKlass
433192 4121 * MethodKlass
303824 283 * ConstantPoolKlass
269816 6117 * SymbolKlass
214688 265 * ConstantPoolCacheKlass
183776 283 * InstanceKlassKlass
108768 1044 char[]
83368 455 byte[]
61248 348 java.lang.Class
52096 462 java.lang.Object[]
31400 785 java.lang.String
29168 413 short[]
19584 295 int[]
18720 36 * ObjArrayKlassKlass
15048 213 java.lang.Object[]
7616 136 java.nio.HeapCharBuffer
4592 82 java.nio.HeapByteBuffer
4160 8 * TypeArrayKlassKlass
2784 58 java.util.Hashtable$Entry
2248 31 java.lang.String[]
2128 14 java.util.HashMap$Entry[]
2080 65 java.lang.StringBuilder
2064 10 java.util.Hashtable$Entry[]
2000 10 * KlassKlass
1792 14 java.lang.reflect.Field
1320 11 java.lang.reflect.Constructor
1056 22 java.util.Locale
1040 2 * ArrayKlassKlass
936 9 java.net.URL
864 6 java.lang.Thread
768 12 java.util.HashMap
736 23 java.io.File
696 21 java.lang.Class[]
672 12 java.io.ObjectStreamField
672 21 java.lang.StringBuffer
...
Heap traversal took 2.054 seconds.

And for the String case:
yclian@kate:~/devels/test/java$ $JAVA_HOME/bin/jmap -histo 29336
Attaching to process ID 29336, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_09-b03
Iterating over heap. This may take a while...
Object Histogram:

Size Count Class description
-------------------------------------------------------
906039672 578 char[]
501216 4132 * ConstMethodKlass
434336 4132 * MethodKlass
304728 284 * ConstantPoolKlass
270328 6127 * SymbolKlass
214688 265 * ConstantPoolCacheKlass
184336 284 * InstanceKlassKlass
71072 351 byte[]
61424 349 java.lang.Class
51216 446 java.lang.Object[]
28960 411 short[]
22520 563 java.lang.String
19088 291 int[]
18720 36 * ObjArrayKlassKlass
13784 202 java.lang.Object[]
4160 8 * TypeArrayKlassKlass
2736 57 java.util.Hashtable$Entry
2128 14 java.util.HashMap$Entry[]
2000 10 * KlassKlass
1936 27 java.lang.String[]
1536 12 java.lang.reflect.Field
1344 7 java.util.Hashtable$Entry[]
1320 11 java.lang.reflect.Constructor
1056 22 java.util.Locale
1040 2 * ArrayKlassKlass
864 6 java.lang.Thread
768 12 java.util.HashMap
728 7 java.net.URL
672 12 java.io.ObjectStreamField
640 10 java.util.LinkedHashMap$Entry
448 8 java.lang.ref.SoftReference
448 7 java.lang.ref.Finalizer
432 9 java.util.HashMap$Entry
384 6 java.util.Hashtable
360 9 java.util.Vector
352 10 java.lang.Class[]
288 3 java.util.jar.JarFile
272 17 java.lang.Object
264 7 java.io.ObjectStreamField[]
256 8 java.io.ExpiringCache$Entry
240 3 sun.nio.cs.UTF_8$Encoder
240 3 java.nio.DirectByteBuffer
216 3 sun.misc.Cleaner
208 2 sun.nio.cs.StreamEncoder$CharsetSE
200 5 java.util.ArrayList
192 3 sun.misc.URLClassPath$JarLoader
176 2 java.io.ExpiringCache$1
160 4 sun.reflect.NativeConstructorAccessorImpl
152 4 java.lang.reflect.Constructor[]
152 1 java.lang.ThreadLocal$ThreadLocalMap$Entry[]
152 1 java.lang.reflect.Method
144 3 java.lang.OutOfMemoryError
...
Heap traversal took 1.323 seconds.

char[], 108768 vs. 906039672. Clear example why String concatenation should be discouraged ;-). The histogram is very useful in identifying memory leakage as it shows you the size and number of instances created for a specific object type. jhat also allows you to generate some other information such as heap summary and permgen statistics, run it with the -h parameter for more information.

Let's examine the binary heap dump produced by the OutOfMemoryError using jhat.

java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid29613.hprof ...
Heap dump file created [403190555 bytes in 31.321 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

jhat is one of the best tools comes together with JVM. It starts a HTTP server and provides you a simple interface which enables you to inspect the heap dump with your favorite browser.


Since we were talking about histogram, we will look into histogram again using the jhat interface.

Class Instance Count Total Size
class [C 564 402716036
class [B 350 67135
class java.lang.Class 336 48384
class [S 411 25126
class [I 291 16760
class [Ljava.lang.Object; 202 12168
class java.lang.String 552 11040
class [Ljava.util.HashMap$Entry; 14 2016
class [Ljava.lang.String; 27 1720
class java.util.Hashtable$Entry 57 1596
class [Ljava.util.Hashtable$Entry; 7 1288
class java.lang.reflect.Constructor 8 776
class java.lang.Thread 6 744
class java.util.Locale 22 704
class java.net.URL 7 616
class java.util.HashMap 12 576
class java.io.ObjectStreamField 12 444
class java.util.LinkedHashMap$Entry 10 440
class java.lang.ref.Finalizer 7 336
class java.lang.ref.SoftReference 8 320
class java.util.Hashtable 6 288
class java.util.HashMap$Entry 9 252
class java.util.jar.JarFile 3 222
class [Ljava.io.ObjectStreamField; 7 208
class java.util.Vector 9 180
class java.nio.DirectByteBuffer 3 168
class sun.misc.Cleaner 3 168
class [Ljava.lang.Class; 7 152

So, it actually produces something similar with what we have seen earlier. Except the slightly different use of notation, e.g. class [C, class [B, etc. Just if you are unsure:
  • class [C is char[]
  • class [B is byte[]
  • class [Z is boolean[]
  • class [S is short[]
  • class [I is int[]
  • class [J is long[]
  • class [D is double[]
  • class [Lpackage.ClassName is package.ClassName[]
  • class [[Lpackage.ClassName is package.ClassName[][]
And therefore, don't be panicked when you see ([[ID[Ljava/lang/String)Z in the stack trace next time. It is simply just boolean foo(int[][], double, String[]).

Clicking into one of the hyper-links (of course, it works just on my machine), for instance, class [C will bring me to a page as captured in the screenshot below:


The page gives you more details of the class, such as: loader, subclasses, static/instance data members, instances, references, etc.

I will end this blog entry at this point and I would expect you to spend some time to do some research on it too :-). When I start writing again for Part II, I will be sharing some thread dump tips that I have collected.

- yc, dumped

Sunday, June 3, 2007

Separation of Concerns

Aspect Oriented Programming (AOP), something which you might be familiar with if you are a Spring/Hibernate lover. It is definitely something new to me.

I spent some of my weekends looking for AOP articles and books. Graham O'Regan's article demonstrates how powerful AOP is and how it can be easily done using AspectWerkz. Naveen Balani's article shows you how Spring does it so that you do not need to add similar lines of code to obtain a Hibernate session to begin a transaction. Spring also

Just as you might not have an idea what AOP is:

It is a solution to the problem of creating clean and well-encapsulated without extraneous functionality.

Explained by Joseph and Nicholas in the book "Mastering AspectJ – Aspect-Oriented Programming in Java". You can find a sample chapter of the book from this link. The introduction explains how Object Oriented programming (OOP) came into play when procedural and functional programming turned ugly and how AOP fills in the blanks of OOP.

Some keywords of AOP are: Advice, Aspect, Cross-cutting concerns, Join points, Point-cut

I am not too sure how AOP can be applied to complicated frameworks such as webMethods. I certainly not a big fan of writing codes to deal with the core API to open and close connection for every transaction that I make. I got around this in my earliest webMethods related project by writing some Plain Old Java Objects (POJOs), Data Access Objects (DAOs) and Data Transfer Objects (DTOs). But they still took me quite some time and I would not know how complicated they could be if someone raised some new concerns.

I am new to Mule but I certainly love how lightweight it is and its support for regular POJOs and Spring embedment.

- yc, aspected