GC Timestamps in Java 6
Y Srinivas Ramakrishna
Y.S.Ramakrishna at Sun.COM
Thu May 29 15:50:19 UTC 2008
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.
----- 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
> 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
> 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
> 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?
> PS: Thanks Tony for pointing me to this discussion
More information about the hotspot-gc-dev