Om de een of andere reden zie je nog steeds vaak dat mensen hun SimpleDateFormat instanties in members verpakken.

DOE DIT NIET!

De Javadoc van SimpleDateFormat zegt heel duidelijk dat de klasse niet thread safe is en dus ook niet op zo’n manier gebruikt mag worden.
http://java.sun.com/j2se/1.4.2/docs/api/java/text/SimpleDateFormat.html#synchronization

Date formats are not synchronized. It is recommended to create separate format instances for each thread. If multiple threads access a format concurrently, it must be synchronized externally.

Dit is niet alleen een theoretisch probleem, maar kan tot hele vreemde bugs leiden, zoals:

• OutOfBoundsExceptions op positie 13 (in een datum :S),
• java.lang.NumberFormatException: For input string: “”,
• java.lang.NumberFormatException: multiple points,
• java.lang.NumberFormatException: empty String,
• Of gewoon verkeerde output (invoer 11-11-1911, output 11-01-0001).

Dit waren gewoon een paar voorbeeldjes uit wat test runs. Er zullen vast nog wel vreemdere fouten kunnen optreden. Bovendien komen dergelijke bugs vaak alleen in productie (onder hoge load) aan het licht, waardoor het nog vervelender wordt.

Dus maak nooit meer private static final SimpleDateFormat SDF = new SimpleDateFormat(“dd-MM-yyyy”); constructies, tenzij je alle aanroepen naar dat object synchronized maakt.

Maar dit laatste is ook geen optie, om twee redenen.

1. Creatie van SimpleDateFormat objecten is heel goedkoop, dus er is eigenlijk geen reden om ze te hergebruiken/poolen. Bovendien, als je ze op stack niveau gebruikt, kan de compiler en de Java runtime het veel efficiënter verwerken.
2. Synchronized blokken zijn op zichzelf niet meer duur, zeker niet vanaf Java SE 6. Het grote nadeel van synchronized blijft echter nog steeds staan, namelijk dat meerdere threads het code block niet parallel uit kunnen voeren, waardoor je een bottleneck introduceert.

Dus zorg dat je je SimpleDateFormat klassen op stack niveau houdt.

Eventueel, als je ECHT veel instanties aan moet maken, kun je naar pool maken. Zorg wel dat die pool stack confined is, zoals een ThreadLocal. Voorbeeld:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

import java.text.ParseException;
import java.text.SimpleDateFormat;
 
public class MultiThread {
	public static final FormatterPool	POOL	= new FormatterPool();
 
	public static void main(String[] args) {
		for (int i = 0; i < 50; i++) {
			new Thread(new Worker()).start();
		}
	}
 
}
 
class Worker implements Runnable {
 
	public void run() {
		try {
			SimpleDateFormat sdf = MultiThread.POOL.get();
			System.out.println(sdf.format(sdf.parse("11-11-1911")));
		} catch (ParseException e) {
			e.printStackTrace();
		} catch (Throwable t) {
			t.printStackTrace();
		}
	}
}
 
import java.text.SimpleDateFormat;
 
public class FormatterPool extends ThreadLocal<SimpleDateFormat> {
 
	private static final SimpleDateFormat	SDF	= new SimpleDateFormat("dd-MM-yyyy");
 
	@Override
	protected SimpleDateFormat initialValue() {
		return new SimpleDateFormat("dd-MM-yyyy");
	}
 
}

Let op bij het gebruik van ThreadLocal. De initialValue bevat in sommige Java versies nog bugs.

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.