timings reported on ParNew GC log line

[Bengt Rutisson]

Hi Charlie,

My guess is that the OS has scheduled out the VM thread for a while in 
favor of some other process on the machine. The user time is the CPU 
time that the VM threads got and that is close to what ParNew reports 
for the GC time. We start the TraceCPUTime (that reports [Times: 
user=0.78 sys=0.00, real=2.05 secs]) before we start the GCTraceTime. If 
the VM thread is scheduled out by the OS between these two timers I 
guess you could get this result.

Are there many other processes running on the same machine?

Having said that, we have seen a couple of cases where the real time can 
get very high. So there might be some VM issue here as well. It would be 
interesting to know if you manage to figure out what is going on.

hths,
Bengt

On 9/4/13 6:03 PM, Charlie Hunt wrote:
> I've run across a ParNew GC log line that I find rather confusing.  Anyone have thoughts as to why there's is such a large gap between the amount of GC time reported by ParNew and "real" CPU time, as in more than 2x difference?
>
> 2013-09-03T21:05:38.414+0000: 25098.985: [GC 25100.950: [ParNew
> Desired survivor size 536870912 bytes, new threshold 15 (max 15)
> - age   1:   55063504 bytes,   55063504 total
> - age   2:   27589472 bytes,   82652976 total
> - age   3:        272 bytes,   82653248 total
> - age   4:   24777360 bytes,  107430608 total
> - age   5:    7970968 bytes,  115401576 total
> - age   6:    3612880 bytes,  119014456 total
> - age   8:    5269600 bytes,  124284056 total
> - age   9:    3627344 bytes,  127911400 total
> - age  10:    1863024 bytes,  129774424 total
> - age  11:    1742592 bytes,  131517016 total
> - age  12:    1050352 bytes,  132567368 total
> - age  13:     613208 bytes,  133180576 total
> - age  14:     555584 bytes,  133736160 total
> - age  15:     379392 bytes,  134115552 total
> : 5393950K->183981K(6291456K), 0.0834570 secs] 7421013K->2211282K(11534336K), 0.0844990 secs] [Times: user=0.78 sys=0.00, real=2.05 secs]
>
> I'm accustomed to seeing a log line that shows real CPU time as a rounding of the GC elapsed time, such as this one:
> 2013-09-03T21:05:40.468+0000: 25101.039: [GC 25101.039: [ParNew
> Desired survivor size 536870912 bytes, new threshold 15 (max 15)
> - age   1:      22784 bytes,      22784 total
> - age   2:   53874496 bytes,   53897280 total
> - age   3:   27562000 bytes,   81459280 total
> - age   4:        272 bytes,   81459552 total
> - age   5:   24787424 bytes,  106246976 total
> - age   6:    7966416 bytes,  114213392 total
> - age   7:    3612880 bytes,  117826272 total
> - age   9:    5269672 bytes,  123095944 total
> - age  10:    3626376 bytes,  126722320 total
> - age  11:    1863024 bytes,  128585344 total
> - age  12:    1742320 bytes,  130327664 total
> - age  13:    1050352 bytes,  131378016 total
> - age  14:     613208 bytes,  131991224 total
> - age  15:     555584 bytes,  132546808 total
> : 184402K->193112K(6291456K), 0.0664320 secs] 2211703K->2220785K(11534336K), 0.8669920 secs] [Times: user=0.74 sys=0.00, real=0.87 secs]
>
> Is there something that's being captured in "real" CPU that's not being caught / reported in the ParNew GC elapsed time?
>
> thanks,
>
> charlie ...
>