understanding CMS logs

[Y. Srinivas Ramakrishna]

Hi Shane --

I transferred the snippet from below  for easy reference:-

>> Log excerpts:
>> 2011-04-05T19:20:38.944-0400: 164034.340: [CMS-concurrent-mark:
>> 25.221/43.448 secs] [Times: user=283.46 sys=8.05, real=43.44 secs]
>>
>> 2011-04-05T19:20:51.735-0400: 164047.131: [CMS-concurrent-preclean:
>> 10.211/17.222 secs] [Times: user=72.78 sys=2.24, real=17.22 secs]
>>
...

> I'm having trouble reconciling the timings in the following log entries.
> Could someone please explain?  Take the first example (concurrent mark).
> The cpu time was ~ 25 seconds, elapsed time was ~ 43 seconds.  So how can
> "user" time be 283 seconds?  There are only 2 Parallel CMS threads.  I would
> think User time would be more along the lines of 50 seconds.  Obviously
> there is something that I'm misinterpreting.

Yes and no. The interpretation that CMS conc mark took about 25 s wall clock
time executing, out of a total wall clock time of 43 seconds in indeed
correct). It is also correct that there are only 2 marking threads.

The [Times:...] part is however misleading in the sense that it is the
time for the whole JVM process, not just the virtual time for the marking
threads. In other words, for the real elapsed time of 43 seconds, the
entire process executed 283.6 virtual seconds in used mode and
8.05 virtual seconds in system mode.

I agree that this can be misleading as presented because it may be
interpreted as virtual time attrributed just to the marking threads,
which is what you did.

>
>
> Also, If cpu time is 25 seconds but elapsed time is 43 seconds, does that
> mean the CM spent 18 seconds doing something other than executing on CPU?

That's correct. Typically, what might happen is that some amount of time may be
spent for foreground GC (scavenge) work, or waiting for locks, during which
time the marking threads may not be running. Also this time is an upper limit
on the actual time that they may have been executing on cpu because they are
calculated by means of bracketing hi-res timers, rather than as virtual cpu
time.

> I'm wondering if some condition is extending the CM execution time because
> it cannot obtain adequate cpu resources.

One would have to look at the complete logs to understand.
You'd first want to total up all of the foreground GC time spent in
between and see how much of balance is left from those 18 seconds.
There may be other STW operations 9such as bulk bias revocation)
that might also interrupt the concurrent marking, as well as, may
be (but am not certin without checking the code) direct allocations
into the old generation or class loading which can cause allocation
into the perm gen.

-- ramki

>
>
> GC Threads:
> "Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x000000005f598000
> nid=0x2ab5 runnable
> "Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x000000005f59a000
> nid=0x2ab6 runnable
> "Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x000000005f59c000
> nid=0x2ab7 runnable
> "Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x000000005f59d800
> nid=0x2ab8 runnable
> "Gang worker#4 (Parallel GC Threads)" prio=10 tid=0x000000005f59f800
> nid=0x2ab9 runnable
> "Gang worker#5 (Parallel GC Threads)" prio=10 tid=0x000000005f5a1800
> nid=0x2aba runnable
> "Gang worker#6 (Parallel GC Threads)" prio=10 tid=0x000000005f5a3000
> nid=0x2abb runnable
> "Gang worker#7 (Parallel GC Threads)" prio=10 tid=0x000000005f5a5000
> nid=0x2abc runnable
>
> "Concurrent Mark-Sweep GC Thread" prio=10 tid=0x000000005f698800 nid=0x2ac3
> runnable
> "Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x000000005f694800
> nid=0x2ac1 runnable
> "Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x000000005f696800
> nid=0x2ac2 runnable
>
>
> Thanks!
>
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use