GC Timestamps in Java 6

[Y Srinivas Ramakrishna]

Just wanted to add the probably somewhat obvious footnote that even for stop-world
phases what's reported is process-virtual time; of course in that case the work done by
other threads in the process is a negligible fraction since most of the mutator
threads are stopped for most of that time-window. However, mutator  threads executing
native code (and therefore not stopped) or the so-called "watcher thread"
running in short bursts during a long collection, and/or some non-trivial work
done by the "coordinating" vm thread (rather than the gc worker threads) might
sometimes throw off your expectations by a bit.

-- ramki

----- Original Message -----
From: Y Srinivas Ramakrishna <Y.S.Ramakrishna at Sun.COM>
Date: Thursday, May 29, 2008 8:50 am
Subject: Re: GC Timestamps in Java 6
To: Nicolas Michael <email at nmichael.de>
Cc: hotspot-gc-dev at openjdk.java.net


> You are right that this represents the process virtual time (and 
> elapsed time)
> rather than lwp-virtual time. I agree that for the concurrent phases reporting
> lwp-virtual time over the lwp's doing the concurrent gc work would be 
> useful.
> 
> -- ramki
> 
> ----- Original Message -----
> From: Nicolas Michael <email at nmichael.de>
> Date: Thursday, May 29, 2008 2:29 am
> Subject: GC Timestamps in Java 6
> To: hotspot-gc-dev at openjdk.java.net
> 
> 
> > 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!
> >