Understanding High Object Copy Times

[Kirk Pepperdine]

Hi Nezih,

I’ve done some analysis of the offending record and I cannot see an obvious reason for the long pause. There is nothing extraordinary in the ergonomic records in that there are a number of other records that would appear to be doing more work in much less time. There appears to be good parallelization. The odd thing here is the termination times and termination attempt counts. Normally I would lean towards some external event either slowing or stalling the GC threads. However I can’t see any indication of that here. TTSP looks ok. The only things that stands out are the high number of threads and that this records contains far more vmops than any of the other records.
So, all I can offer here are a number of observations but nothing useful in the way of a conclusion or recommendation other than 200ms may be too aggressive a pause time goal (which has already been suggested).

Kind regards,
Kirk

2017-04-26T03:07:33.919-0700: 78547.003: [GC pause (G1 Evacuation Pause) (young) 78547.005: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 2064281, predicted base time: 384.97 ms, remaining time: 0.00 ms, target pause time: 200.00 ms]
 78547.005: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 224 regions, survivors: 32 regions, predicted young region time: 3043.54 ms]
 78547.005: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 224 regions, survivors: 32 regions, old: 0 regions, predicted pause time: 3428.51 ms, target pause time: 200.00 ms]

, 27.3281850 secs]
   [Parallel Time: 27275.9 ms, GC Workers: 33]

      [Object Copy (ms): Min: 22778.0, Avg: 23231.1, Max: 23669.7, Diff: 891.6, Sum: 766626.4]
      [Termination (ms): Min: 2968.4, Avg: 3407.0, Max: 3860.7, Diff: 892.4, Sum: 112430.8]
         [Termination Attempts: Min: 343562, Avg: 376083.3, Max: 407454, Diff: 63892, Sum: 12410750]
   [Eden: 7168.0M(7168.0M)->0.0B(7168.0M) Survivors: 1024.0M->1024.0M Heap: 133.3G(160.0G)->128.7G(160.0G)]
 [Times: user=901.06 sys=0.00, real=27.33 secs] 

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
78546.828: G1IncCollectionPause             [    4615         76            629    ]      [     2     8   144    33 27329    ]  3   
2017-04-26T03:08:01.250-0700: 78574.334: Total time for which application threads were stopped: 27.4382400 seconds, Stopping threads took: 0.0735482 seconds


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20170428/251f78df/attachment.htm>