What's The Difference Between Java GC Log Lines? ("Total time for which..." vs "[GC")

Question

Java Version: 1.6.0_20

I'm seeing the following in my logs, and I'm trying to figure out the difference beween the first line and the subsequent lines. As far as I know, they are both minor GC related, however there isn't a 1-to-1 between them as there usually is in other GC tutorials I've read. I know how to interpret the first line, and the second is pretty obvious as well, but what is the difference between the two events?

30171.470: [GC 30171.470: [ParNew: 32704K->64K(32704K), 0.0055740 secs] 1575471K->1545444K(3145664K), 0.0056610 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
Total time for which application threads were stopped: 0.0060020 seconds
Total time for which application threads were stopped: 0.0003300 seconds
Total time for which application threads were stopped: 0.0000740 seconds
Total time for which application threads were stopped: 0.0002630 seconds
Total time for which application threads were stopped: 0.0002640 seconds
Total time for which application threads were stopped: 0.0000760 seconds
... Snipped 35 similar lines ...
Total time for which application threads were stopped: 0.0006710 seconds
Total time for which application threads were stopped: 0.0000870 seconds
Total time for which application threads were stopped: 0.0002710 seconds
Total time for which application threads were stopped: 0.0000770 seconds
Total time for which application threads were stopped: 0.0002810 seconds
Total time for which application threads were stopped: 0.0002680 seconds
Total time for which application threads were stopped: 0.0000770 seconds
30289.137: [GC 30289.137: [ParNew: 32704K->63K(32704K), 0.0063990 secs] 1578084K->1548229K(3145664K), 0.0064890 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

Thanks for your help!

Answer 1

The "...application threads.." messages are controlled by PrintGCApplicationStoppedTime. Whenever the JVM reaches the end of a safepoint operation, it will check to see if it should print how long the app was stopped during that operation.

The name of the flag is somewhat misleading in that it isn't specifically related to GC. For example, if you also run with the PrintSafepointStatistics flag, you'll likely see that the majority of the VM operations are RevokeBias. The GC related ops will be named something like GenCollectForAllocation.