GC Timestamps in Java 6

[Nicolas Michael]

Hi Jon,

see inline.

Jon Masamitsu schrieb:
> 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.

Ok, I see.

> 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 :).

Never looked at it that way! ;-) That's an interesting point.

However, for our application we always keep spare ressources and 
configure the number of threads (mutator / concurrent gc) in such a way 
that a concurrent gc will never steal all cpu from our application. And, 
we're running on large multi-way servers. In fact, our mutators aren't 
slowed down by concurrent gc's at all (or: at least not measurable). So, 
for us it's not really of much importance to see our application's cpu 
time during concurrent collections. But I understand that this may be 
different for other customers.

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

Sure!

Although, for my use-case, it would be more interesting to see the cpu 
time for the gc threads. If our application is slowed down because of 
GC, we have lot's of other means to notice that. However, it is much 
more difficult to measure the cpu time for garbage collection. What I do 
from time to time is do pstack's to find out which the gc threads are, 
then do a prstat to see the total cpu time per LWP and add this up... 
Comparing this to the total process time gives me the "overhead" for 
garbage collection in terms of cpu usage. This is an interesting measure 
for us. I thought I may get this information from these additional times 
in the gc log when I first saw the new output.


Anyway, this isn't that important. As I described above, we have other 
ways in getting this information. I was just wondering whether it was 
intended that way.

Thanks for your background information,
Nick.


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