GC Timestamps in Java 6

[Jon Masamitsu]

Nick,

My main motivation for this additional information was
to have some way for the user to see that the JVM
was swapping during GC.   Before this addition the
only way was that we would hear from the user that
GC pauses of seconds had turned into GC pauses
of mintues.   Swapping was our first guess but only
a guess.  For the stop-the-world collections the
numbers output do that for us.

Regarding the numbers for the concurrent phases,
I gave less thought to them but did think about
them some.  I recall that I liked them from the
point of view that they gave me information about
how much time the concurrent collections was
stealing from the application.   You went through the
numbers for your example

2319.981: [CMS-concurrent-mark: 3.487/3.487 secs] [Times: user=54.12 
sys=0.78, real=3.49 secs]

and concluded that GC was not consuming all the time.
For a concurrent phase, that's a conformt for me :).

Does this make any sense?    I had to consciously add the
code to print out the times for the concurrent phases so
I know I thought about it but perhaps not hard enough.

Jon

Nicolas Michael wrote:

>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!
>
>  
>