Not taking JavaDoc seriously can easily happen to any developer. Or maybe you haven’t read that specific part of it, you should better have read. If you did and cannot see a problem locally, you might be tempted to ignore it.
Here is an often ignored part from java.text.SimpleDateFormat JavaDoc:
* 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.
Perhaps that warning isn’t strong enough, because it reads: “It is recommended”.
This leads to this highly dangerous line of code I have seen in almost every project and is likely to produce hangs in concurrently accessed code.
private static final SimpleDataFormat DATE_FORMAT = new SimpleDateFormat("yyyy.MM.dd");
But it gets worse with System.gc().
There is no warning in the JavaDoc:
* Calling the gc method suggests that the Java Virtual * Machine expend effort toward recycling unused objects in order to * make the memory they currently occupy available for quick reuse. * When control returns from the method call, the Java Virtual * Machine has made a best effort to reclaim space from all discarded * objects.
Doesn’t sound too bad, does it? You should wonder what “suggests” and “best effert” really means. Perhaps you are tempted to use System.gc(), so you might look on the internet for other people using this, hoping for an explanation what in reality happens. You might find good insights on Stackoverflow. But what exactly this does nobody seems to know.
I think a picture tells more than thousand words:
We are looking at a pretty big system of one of our customers. It has 14GB of heap and we helped them to bring down the memory consumtion so that the app ran quite well. However there were still pretty long pause times (so called stop the world time). The graph was created from a Garbage Collection log and points us to the cause of the pause times. The blue line shows Garbage Collection activity. So why are there exactly 13 spikes with up to 35 seconds? All the other activity seems to be really fast.
The reason for those 13 spikes is simple: They all were caused by an invocation of System.gc().
So what happens? Calling System.gc() seems to effectively stop any optimization the GC is doing, forcing a full collection to start, rather than the optimized CMS Algorithm used.
Note: This system is using a Sun 188.8.131.52 64 bit HotSpot Server VM. GC is set to -XX:+UseConcMarkSweepGC and -XX:+UseParNewGC. System.gc() does not have to produce results like that. Your results might vary. However also others have reported, that when using CMS and System.gc() a Full GC is always performed.
If you cannot find yourself invoking System.gc(), they might hide deeply in a used library. To fix this, you can use the the server argument “-XX:+DisableExplicitGC”. This argument is also recommended by the SUN/Oracle performance tuning guide.