Java garbage collection "real" time is much bigger than "user" +"system"

Question

That's how full gc with verbose gc enabled looks like -

13463.547: [Full GC [PSYoungGen: 323053K->0K(325952K)]
           [PSOldGen: 653170K->331738K(655360K)] 976224K->331738K(981312K)
           [PSPermGen: 238715K->238715K(264448K)], 385.4631490 secs]
           [Times: user=2.19 sys=1.35, real=385.50 secs]

How can the real time be so much bigger than user + sys?

My first thought was that garbage collector is waiting for a resource, but this resource does not seem to be IO or CPU, as "top" output doesn't show any cpu or memory problems when the gc occurs.

Answer 1

For a full collection to occur, you need to stop all the threads. (One of the reasons it call a stop the world collection)

Stopping all your threads can take a long time, esp if you have thousands of them. Each thread has to reach a "safepoint" to stop it.

This sort of behaviour usually means you have too many threads. You might also consider ConcurrenntMarkSweep collector or the new G1 collector which doesn't need to stop the application as often.

Answer 2

Try reading this (more links included to whitepaper): Java 1.5 GC Internals.
I guess most things are still valid for Java's 1.6 VM and it gives a great insight as how the GC works.
Also, read this: Tuning JVM's 1.6 Heap space
( there is also another white paper link with an illustrative benchmark but I just can't find it :( :/
I'll try and see if it pops up somewhere but I guess it's located somewhere in Oracle's website )

In general, don't get freaky. Try and experiment with different options based by some rationale and see how it works. Unless you have a > 10% performance gain and your application is critical try not to mingle with a lot of details.
The reason is simple: A simple code rewrite in just a few LOCs may change dramatically your GC's behaviour.
Take your time and have fun! :)