timings reported on ParNew GC log line
Charlie Hunt
charlesjhunt at gmail.com
Wed Sep 4 16:03:17 UTC 2013
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 ...
More information about the hotspot-gc-dev
mailing list