timings reported on ParNew GC log line

[Simone Bordet]

Hi,

On Wed, Sep 4, 2013 at 6:03 PM, Charlie Hunt <charlesjhunt at gmail.com> 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?

Maybe CPU time stolen by the VM hypervisor ?

-- 
Simone Bordet
http://bordet.blogspot.com
---
Finally, no matter how good the architecture and design are,
to deliver bug-free software with optimal performance and reliability,
the implementation technique must be flawless.   Victoria Livschitz