Full GC real time is much more that user+sys times

Question

We have a Web Java based application running on JBoss with allowed maximum heap size of about 1.2 GB (total machine physical memory is 2 GB). At some point the application stops responding (to clients) for several minutes. After some analysis we found out that the culprit is the Full GC. Here's an excerpt from the verbose GC log:

74477.402: [Full GC [PSYoungGen: 3648K->0K(332160K)] [PSOldGen: 778476K->589497K(819200K)] 782124K->589497K(1151360K) [PSPermGen: 102671K->102671K(171328K)], 646.1546860 secs] [Times: user=3.84 sys=3.72, real=646.17 secs]

What I don't understand is how is it possible that the real time spent on Full GC is about 11 minutes (646 seconds), while user+sys times are just 7.5 seconds. 7.5 seconds sound to me much more logical time to spend for cleaning <200 MB from the old generation. Where does all the other time go?

Thanks a lot.

Answer 1

Where does all the other time go?

It is most likely that your application is causing virtual memory thrashing. Basically, your application needs significantly more pages of virtual memory than there are physical pages available to hold them. As a result, it is spending most of the time waiting for vm pages to be read from and written to disc.

For more information, read this wikipedia page.

The cure is to either reduce virtual memory usage or increase the amount of physical memory on the system. For example, you could:

• run fewer applications on the machine,
• reduce Java application heap sizes, or
• if you are running in a virtual, increase the virtual's allocation of physical memory.

(Note however that reducing the JVM heap size can be a two-edged sword. If you reduce the heap size too much the application will either die from OutOfMemoryErrors, spend too much time garbage collecting, or suffer from not being able to cache things effectively.)