GC Timestamps in Java 6

[Nicolas Michael]

Hi,

you have introduced some additional timestamps in the gc logs with Java 6,
showing cpu time (user and system) as well as elapsed time. When I ran some CMS
tests where I changed the number of CMS threads, I've noticed that those numbers
don't show what I originally expected... 

For a STW collection, this new output is quite nice:
966.697: [GC 966.698: [ParNew: 260292K->65536K(262144K), 0.1426038 secs]
1090657K->898209K(1368064K), 0.1429749 secs] [Times: user=1.88 sys=0.06,
real=0.14 secs] 
The collection took 0.14 secs, and the ParNew threads consumed 1.88+0.06=1.94
seconds cpu time. With 16 ParNew threads that I had configured, each single
thread was therefore on a cpu for most of the time (they consumed 1.94 out of
16*0.14=2.24 theoretically possible cpu seconds). That's nice to know!

However, for concurrent activities, this output is a little confusing:
2319.981: [CMS-concurrent-mark: 3.487/3.487 secs] [Times: user=54.12 sys=0.78,
real=3.49 secs] 
The concurrent mark took 3.49 seconds, ok. Now I would expect the "user" and
"sys" times to reflect the cpu time consumed for concurrent marking (the sum
over all parallel CMS threads). In this example, I had 8 parallel CMS threads
configured (plus the "coordinator" CMS thread). But 9 threads cannot consume 55
cpu seconds within 3.5 real seconds. So I guess this cpu time reported as "user"
and "sys" is consumed by *all* threads of the JVM, including the mutator
threads. Which would make sense (the numbers would fit), but is a rather
meaningless information...

Probably it is intended that way. But I think those times would be more usefull
if they reflected *only* the gc activities. When I look at a gc log, I would
like to see how much time (elapsed as well as cpu cycles) are spent for *garbage
collection*, without cpu time spent for my mutator threads.

What do you think?

Nick.

PS: Thanks Tony for pointing me to this discussion
list!