Performance Tuning with Thread Dumps

As a follow on to my earlier tuning blog I whipped up a quick sample to make the Performance tuning with Thread dumps point clearer (see my previous blog). Take a look at the following code and make a guess at what you think the slowest part of the code is and why.

package softwareandstuff.performance;

import java.util.ArrayList;
import java.util.List;
import java.util.Random;

public class SomethingToRun {

 public void run() {
   List stuff = new ArrayList();
   Random r = new Random();
   long total = 0;
   long count = 0;
   while (true) {
     long start = System.currentTimeMillis();
     String s = " " + r.nextInt() + " " + r.nextInt();

     for (int i = 0; i < i =" 0;" 1000 ="="">

On my slow computer it took around 43 seconds per 1000.

Now use jps to find out what process id the little app has and do a "kill -3 " 10 to 20 times fast in succession.

Note: jps requires jdk1.5 to be installed. Figure out how to use task manager in windows or ps on unix based platforms if you are not on jdk1.5

steve:~ steve$  jps

7595 Jps
7594 SomethingToRun
7440 startup.jar

steve:~ steve$ kill -3 7594

Note: See the following link for more on how to do thread dumps and what they are A little on thread dumps

Should see something like the following:

Signal Dispatcher" daemon prio=9 tid=0x005098d0 nid=0x1820a00 waiting on condition [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x00509030 nid=0x180fc00 in Object.wait() [0xf0a04000..0xf0a04ab0]
at java.lang.Object.wait(Native Method)
- waiting on <0x266101e0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x266101e0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00508c40 nid=0x180ec00 in Object.wait() [0xf0983000..0xf0983ab0]
at java.lang.Object.wait(Native Method)
- waiting on <0x26610260> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x26610260> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x005013b0 nid=0x1804600 runnable [0xf07ff000..0xf08002c0]
at softwareandstuff.performance.SomethingToRun.run(SomethingToRun.java:25)
at softwareandstuff.performance.SomethingToRun.main(SomethingToRun.java:36)

"VM Thread" prio=9 tid=0x00508460 nid=0x1803c00 runnable

Note: ignore any thread that is in Object.wait() for now. In fact, searching on runnable is usually your best bet for skipping to the things that are interesting from a performance perspective.

My guess is what you will see is that a decent percentage of the time is spent in the remove call. hmmm, wonder why that is. Now go look at the implementation of remove on an ArrayList and it will all be clear. Now try using a linked list instead. For me that dropped it down to 6 seconds per 1000.

busy today but more to come...