GC Timestamps in Java 6

[Y Srinivas Ramakrishna]

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