Iedereen kent java, javadoc en javac, maar er wordt nog een heel stel tools meegeleverd met de SDK’s van tegenwoordig.
Denk bijvoorbeeld aan de keytool waarmee je je certificaten en public/private keys beheert. Of apt, waarmee je @compile-time annotations kunt verwerken.
Ook zitten er handige debugging tools bij, zoals:
- jps
Geef een lijst van alle Java processen op dit systeem.
- jconsole
Op JMX gebaseerde GUI om Java applicaties mee te beheren.
- jstat
Toon performance gerichte statistieken voor een bepaald Java proces. Er zijn statistieken voor o.a. garbage collection, classloading en permspace.
- jinfo
Toon system properties en command line arguments.
- jmap
Maak een snapshot van de heap en schrijf die weg naar een file.
- jhat (JDK 6)
Genereer op basis van een jmap file een web interface om daarop rapportages uit te voeren. Bevat onder andere een flexibele OQL query tool om specifieke objecten te zoeken. Bijvoorbeeld alle gepoolede EJB Session Beans of strings die aan bepaalde eisen voldoen. Let op: Deze queries kunnen erg lang duren, afhankelijk van de grootte van de heap snapshot. Probeer voor de grap maar eens uit op een Eclipse snapshot.
- jstack (Niet in JDK 5 onder Windows en Linux Itanium)
Genereer een stack dump, dus een stack trace voor elke thread.
Al deze tools kunnen zowel voor een lokale als een remote JVM (bijvoorbeeld op een testserver) gebruikt worden. Dat maakt ze zeer geschikt voor concurrency issues, aangezien die lokaal vaak niet lastig reproduceren zijn.
Let op: Deze tools zijn allemaal experimenteel en worden niet ondersteund. jinfo heeft bijvoorbeeld onder Windows maar beperkte functionaliteit en jstack wordt onder Windows helemaal niet meegeleverd.
jstack
Vooral jstack is een handige tool. In JDK 5 was het niet echt bruikbaar, omdat de informatie niet echt overzichtelijk getoond werd. Bovendien was er alleen ondersteuning voor intrinsic locks (synchronized blokken) en niet voor expliciete locks. In JDK 6 wordt veel meer informatie getoond. Laten we bijvoorbeeld onderstaande code eens uitvoeren (vrijwel gegarandeerde deadlock).
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;
public class DeadLocker {
public static void main(String[] args) {
Lock lock1 = new ReentrantLock();
Lock lock2 = new ReentrantLock();
new Thread(new Worker(lock1, lock2), "Worker 1").start();
new Thread(new Worker(lock2, lock1), "Worker 2").start();
}
}
class Worker implements Runnable {
private Lock lock1, lock2;
public Worker(Lock lock1, Lock lock2) {
this.lock1 = lock1;
this.lock2 = lock2;
}
public void run() {
int i = 1;
for (;;) {
try {
lock1.lock();
try {
lock2.lock();
System.out.println("Iteration #" + i++);
} finally {
lock2.unlock();
}
} finally {
lock1.unlock();
}
}
}
}
Deze code start twee threads met beide een infinite loop. In die loop staan twee geneste lock constructies. Op zicht niet erg, behalve dat beide threads omgekeerd locken. Er is maar een klein beetje ongelukkige CPU scheduling nodig voor een deadlock (in dit voorbeeld vrijwel gegarandeerd door de infinite loop). Als op de plaats van de System.out.println() een dure operatie staat (zoals een DB query) wordt de kans op een deadlock nog groter.
Ik gebruik hier expliciete locks, maar met synchronized is het gedrag hetzelfde.
In dit voorbeeld is de fout nog wel te vinden, maar als dit tig niveau’s diep in een enterprise applicatie (eventueel gedeployed op een Java EE applicatieserver) gebeurt, wordt je niet gelukkig, want je ziet door de bomen het bos niet meer.
Gelukkig zijn er tools om je te helpen, ook in de standaard JDK.
Als we deze applicatie draaien, blijft het proces hangen (dat is namelijk het probleem van een deadlock). Dat proces zoeken we eerst op met het volgende commando.
C:\Users\Jan-Kees>jps
2516 Jps
3908 DeadLocker
Zoals je ziet, zijn er verschillende processen actief, waaronder ons DeadLocker proces. Het nummertje ervoor is het proces-id. Dit hebben we nodig voor de volgende stappen.
Dan gaan we met jstack kijken naar een JDK 5 thread dump. Helaas heb ik op deze computer Windows en daardoor geen jstack, maar als je gewoon de applicatie vanaf de command line opstart, kun je met CTRL+BREAK ook een thread dump maken. De output is vergelijkbaar met die van jstack. Dit is de thread dump onder JDK 5.
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_15-b04 mixed mode):
"DestroyJavaVM" prio=6 tid=0x00000000003ca7b0 nid=0x1274 waiting on condition [0x0000000000000000..0x000000000012f810]
"Worker 2" prio=6 tid=0x0000000005c1c7a0 nid=0x105c waiting on condition [0x000000000686f000..0x000000000686f910]
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:746)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1076)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:184)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:256)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:595)
"Worker 1" prio=6 tid=0x00000000002da5b0 nid=0xf38 waiting on condition [0x000000000676f000..0x000000000676f990]
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:746)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1076)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:184)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:256)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:595)
"Low Memory Detector" daemon prio=6 tid=0x0000000005c07a70 nid=0x129c runnable [0x0000000000000000..0x0000000000000000]
"CompilerThread1" daemon prio=10 tid=0x0000000005c073e0 nid=0x1188 waiting on condition [0x0000000000000000..0x000000000646ec60]
"CompilerThread0" daemon prio=10 tid=0x0000000005c05d50 nid=0x109c waiting on condition [0x0000000000000000..0x000000000636e7b0]
"AdapterThread" daemon prio=10 tid=0x0000000005bfffa0 nid=0xb04 waiting on condition [0x0000000000000000..0x0000000000000000]
"Signal Dispatcher" daemon prio=10 tid=0x000000000034ebc0 nid=0xf00 waiting on condition [0x0000000000000000..0x0000000000000000]
"Finalizer" daemon prio=8 tid=0x000000000034f710 nid=0x10c0 in Object.wait() [0x000000000606f000..0x000000000606f990]
at java.lang.Object.wait(Native Method)
- waiting on <0x000000003fec11a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
- locked <0x000000003fec11a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x000000000034f180 nid=0xd4c in Object.wait() [0x0000000005f6f000..0x0000000005f6f910]
at java.lang.Object.wait(Native Method)
- waiting on <0x000000003fec1020> (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 <0x000000003fec1020> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x000000000034eaa0 nid=0x7d0 runnable
"GC task thread#0 (ParallelGC)" prio=6 tid=0x00000000003cb7b0 nid=0x318 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x00000000003cb8f0 nid=0x1234 runnable
"VM Periodic Task Thread" prio=10 tid=0x00000000002d9770 nid=0x724 waiting on condition
Dit is al leuk. We hebben maar twee threads en twee lock objecten, dus we kunnen het probleem gemakkelijk terugvinden. Bij meer threads (zoals in een applicatieserver) wordt het veel lastiger. Alleen als je ervaring hebt op dit gebied EN je kent de applicatie door en door, dan kun je hier eventueel mee uit de voeten, maar in de meeste gevallen wil je meer informatie hebben. Je hebt namelijk geen zin om al die Object ID’s continu handmatig te moeten vergelijken.
Java 6 biedt meer info, in de vorm van een uitgebreidere jstack. Laten we het programma nog eens een keer opstarten, maar nu onder de nieuwe JDK.
Weer een keertje jps om te zien wat nu het proces-id is.
C:\Users\Jan-Kees>jps
4196 DeadLocker
4228 Jps
En daarna jstack [proces-id] (met Java 6 wordt wel een jstack voor Windows meegeleverd 
)
C:\Users\Jan-Kees>jstack 4196
2008-06-25 21:39:05
Full thread dump Java HotSpot(TM) Client VM (10.0-b22 mixed mode, sharing):
"DestroyJavaVM" prio=6 tid=0x00441c00 nid=0x100 waiting on condition [0x00000000..0x001bfd20]
java.lang.Thread.State: RUNNABLE
"Worker 2" prio=6 tid=0x00491800 nid=0x838 waiting on condition [0x04b2f000..0x04b2fae8]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x2456b800> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:619)
"Worker 1" prio=6 tid=0x00491000 nid=0x13e0 waiting on condition [0x04a9f000..0x04a9fb68]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x2456b828> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:619)
"Low Memory Detector" daemon prio=6 tid=0x00483800 nid=0xa40 runnable [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE
"CompilerThread0" daemon prio=10 tid=0x00477400 nid=0x76c waiting on condition [0x00000000..0x048ef914]
java.lang.Thread.State: RUNNABLE
"Attach Listener" daemon prio=10 tid=0x00474c00 nid=0xf94 runnable [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x0046bc00 nid=0x12b0 runnable [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x00462800 nid=0x12d0 in Object.wait() [0x0473f000..0x0473fa68]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x24540b28> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x24540b28> (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=0x00461800 nid=0x5fc in Object.wait() [0x046af000..0x046afae8]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x24540a30> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x24540a30> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x00460400 nid=0x1378 runnable
"VM Periodic Task Thread" prio=10 tid=0x00485000 nid=0x13dc waiting on condition
JNI global references: 604
Found one Java-level deadlock:
=============================
"Worker 2":
waiting for ownable synchronizer 0x2456b800, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
which is held by "Worker 1"
"Worker 1":
waiting for ownable synchronizer 0x2456b828, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
which is held by "Worker 2"
Java stack information for the threads listed above:
===================================================
"Worker 2":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x2456b800> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:619)
"Worker 1":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x2456b828> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:747)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
at Worker.run(DeadLocker.java:27)
at java.lang.Thread.run(Thread.java:619)
Found 1 deadlock.
Als je naar het laatste stuk kijkt, zie je dat er nu meer informatie getoond wordt. Hij geeft duidelijk aan dat hij een deadlock ontdekt heeft, namelijk tussen de threads “Worker 2″ en “Worker 1″. Je kunt zien dat “Worker 2″ op lock <0x2456b800> wacht (die in bezit is van “Worker 1″). Tegelijk wacht “Worker 1″ op <0x2456b828> (die in het bezit is van “Worker 2″).
Tip: Het is slim om af en toe eens een thread dump te maken van een draaiende applicatie, zelfs al is er op dat moment geen deadlock. Het geeft namelijk veel inzicht in het locking gedrag van je applicatie.
