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