Bug in G1

Kirk Pepperdine kirk at kodewerk.com
Sun Jul 23 10:51:39 UTC 2017


Thanks for the information. I’ve shared the entire log with you on dropbox. Feel free to distribute it as you see fit.	

I see the to-space exhausted but there doesn’t appear to be a mixed collection involved. Below is a single sequence up to and including the Full.

Kind regards,
Kirk


2017-05-23T20:42:55.303-0400: 40580.396: Application time: 0.8539675 seconds
2017-05-23T20:42:55.304-0400: 40580.398: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 169869312 bytes, new threshold 15 (max 15)
- age   1:    3278808 bytes,    3278808 total
- age   2:   71278552 bytes,   74557360 total
- age   3:     533720 bytes,   75091080 total
- age   4:   12897544 bytes,   87988624 total
- age   5:     796672 bytes,   88785296 total
- age   6:     503288 bytes,   89288584 total
2017-05-23T20:42:55.363-0400: 40580.457: [SoftReference, 0 refs, 0.0010011 secs]2017-05-23T20:42:55.364-0400: 40580.458: [WeakReference, 367 refs, 0.0006136 secs]2017-05-23T20:42:55.365-0400: 40580.458: [FinalReference, 7659 refs, 0.0014460 secs]2017-05-23T20:42:55.366-0400: 40580.460: [PhantomReference, 0 refs, 0 refs, 0.0011060 secs]2017-05-23T20:42:55.367-0400: 40580.461: [JNI Weak Reference, 0.0000647 secs], 0.0669684 secs]
   [Parallel Time: 57.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40580398.1, Avg: 40580398.2, Max: 40580398.3, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.9, Max: 2.7, Diff: 1.0, Sum: 15.2]
      [Update RS (ms): Min: 15.2, Avg: 15.7, Max: 15.8, Diff: 0.6, Sum: 125.4]
         [Processed Buffers: Min: 44, Avg: 50.1, Max: 62, Diff: 18, Sum: 401]
      [Scan RS (ms): Min: 1.9, Avg: 2.0, Max: 2.1, Diff: 0.2, Sum: 15.9]
      [Code Root Scanning (ms): Min: 1.6, Avg: 1.7, Max: 1.7, Diff: 0.1, Sum: 13.5]
      [Object Copy (ms): Min: 36.0, Avg: 36.2, Max: 36.2, Diff: 0.2, Sum: 289.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.0]
      [GC Worker Total (ms): Min: 57.4, Avg: 57.5, Max: 57.6, Diff: 0.2, Sum: 460.3]
      [GC Worker End (ms): Min: 40580455.7, Avg: 40580455.7, Max: 40580455.8, Diff: 0.1]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.8 ms]
   [Other: 8.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.7 ms]
      [Ref Enq: 0.3 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 1.9 ms]
   [Eden: 2484.0M(2484.0M)->0.0B(3544.0M) Survivors: 98.0M->100.0M Heap: 5189.0M(7168.0M)->2708.0M(7168.0M)]
 [Times: user=0.45 sys=0.03, real=0.07 secs] 
2017-05-23T20:42:55.372-0400: 40580.465: Total time for which application threads were stopped: 0.0685303 seconds, Stopping threads took: 0.0001346 seconds
2017-05-23T20:42:59.372-0400: 40584.465: Application time: 4.0004774 seconds
2017-05-23T20:42:59.376-0400: 40584.469: Total time for which application threads were stopped: 0.0036324 seconds, Stopping threads took: 0.0023017 seconds
2017-05-23T20:43:05.891-0400: 40590.984: Application time: 6.5149722 seconds
2017-05-23T20:43:05.892-0400: 40590.985: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 239075328 bytes, new threshold 15 (max 15)
- age   1:    4934368 bytes,    4934368 total
- age   2:    2633808 bytes,    7568176 total
- age   3:   71264464 bytes,   78832640 total
- age   4:     527368 bytes,   79360008 total
- age   5:   12893400 bytes,   92253408 total
- age   6:     750128 bytes,   93003536 total
- age   7:     432784 bytes,   93436320 total
2017-05-23T20:43:09.493-0400: 40594.586: [SoftReference, 0 refs, 0.0067938 secs]2017-05-23T20:43:09.500-0400: 40594.593: [WeakReference, 0 refs, 0.0033881 secs]2017-05-23T20:43:09.503-0400: 40594.597: [FinalReference, 0 refs, 0.0005787 secs]2017-05-23T20:43:09.504-0400: 40594.597: [PhantomReference, 0 refs, 0 refs, 0.0011377 secs]2017-05-23T20:43:09.505-0400: 40594.598: [JNI Weak Reference, 0.0000618 secs] (to-space exhausted), 4.8672247 secs]
   [Parallel Time: 3599.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40590985.9, Avg: 40590986.0, Max: 40590986.1, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.3, Diff: 0.6, Sum: 15.2]
      [Update RS (ms): Min: 68.3, Avg: 68.4, Max: 68.5, Diff: 0.2, Sum: 547.6]
         [Processed Buffers: Min: 32, Avg: 49.0, Max: 72, Diff: 40, Sum: 392]
      [Scan RS (ms): Min: 2.8, Avg: 2.9, Max: 3.0, Diff: 0.1, Sum: 23.2]
      [Code Root Scanning (ms): Min: 2.4, Avg: 2.5, Max: 2.5, Diff: 0.1, Sum: 19.7]
      [Object Copy (ms): Min: 3523.7, Avg: 3523.8, Max: 3523.9, Diff: 0.2, Sum: 28190.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]
      [GC Worker Total (ms): Min: 3599.6, Avg: 3599.7, Max: 3599.8, Diff: 0.2, Sum: 28797.6]
      [GC Worker End (ms): Min: 40594585.6, Avg: 40594585.7, Max: 40594585.7, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.2 ms]
   [Other: 1265.8 ms]
      [Evacuation Failure: 1248.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 12.4 ms]
      [Ref Enq: 0.5 ms]
      [Redirty Cards: 2.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 1.5 ms]
   [Eden: 3544.0M(3544.0M)->0.0B(976.0M) Survivors: 100.0M->456.0M Heap: 6274.3M(7168.0M)->5978.2M(7168.0M)]
 [Times: user=13.58 sys=0.11, real=4.86 secs] 
2017-05-23T20:43:10.760-0400: 40595.853: Total time for which application threads were stopped: 4.8690628 seconds, Stopping threads took: 0.0002136 seconds
2017-05-23T20:43:11.762-0400: 40596.855: Application time: 1.0019247 seconds
2017-05-23T20:43:11.763-0400: 40596.856: Total time for which application threads were stopped: 0.0015356 seconds, Stopping threads took: 0.0003107 seconds
2017-05-23T20:43:11.880-0400: 40596.973: Application time: 0.1164884 seconds
2017-05-23T20:43:11.881-0400: 40596.974: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
Desired survivor size 94371840 bytes, new threshold 1 (max 15)
- age   1:  477501112 bytes,  477501112 total
- age   2:     182296 bytes,  477683408 total
- age   3:      78880 bytes,  477762288 total
- age   4:      45376 bytes,  477807664 total
- age   5:      92304 bytes,  477899968 total
- age   6:      75448 bytes,  477975416 total
- age   7:      86752 bytes,  478062168 total
- age   8:      71408 bytes,  478133576 total
2017-05-23T20:43:17.335-0400: 40602.428: [SoftReference, 0 refs, 0.0071133 secs]2017-05-23T20:43:17.342-0400: 40602.435: [WeakReference, 3 refs, 0.0007987 secs]2017-05-23T20:43:17.343-0400: 40602.436: [FinalReference, 182 refs, 0.0017603 secs]2017-05-23T20:43:17.345-0400: 40602.438: [PhantomReference, 0 refs, 0 refs, 0.0015961 secs]2017-05-23T20:43:17.346-0400: 40602.440: [JNI Weak Reference, 0.0000730 secs] (to-space exhausted), 6.1987667 secs]
   [Parallel Time: 5446.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40596975.6, Avg: 40596975.7, Max: 40596975.8, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 2.9, Avg: 3.1, Max: 3.2, Diff: 0.3, Sum: 24.4]
      [Update RS (ms): Min: 10.1, Avg: 10.3, Max: 10.5, Diff: 0.4, Sum: 82.6]
         [Processed Buffers: Min: 33, Avg: 40.2, Max: 51, Diff: 18, Sum: 322]
      [Scan RS (ms): Min: 30.7, Avg: 31.1, Max: 32.4, Diff: 1.8, Sum: 249.0]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 2.8]
      [Object Copy (ms): Min: 5399.2, Avg: 5400.6, Max: 5400.9, Diff: 1.7, Sum: 43204.5]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 5445.5, Avg: 5445.6, Max: 5445.7, Diff: 0.2, Sum: 43565.0]
      [GC Worker End (ms): Min: 40602421.3, Avg: 40602421.4, Max: 40602421.4, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.8 ms]
   [Other: 751.4 ms]
      [Evacuation Failure: 728.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 17.8 ms]
      [Ref Enq: 0.5 ms]
      [Redirty Cards: 2.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.8 ms]
   [Eden: 878.0M(976.0M)->0.0B(1424.0M) Survivors: 456.0M->8192.0K Heap: 6856.2M(7168.0M)->6908.2M(7168.0M)]
 [Times: user=11.66 sys=1.15, real=6.19 secs] 
2017-05-23T20:43:18.080-0400: 40603.173: [GC concurrent-root-region-scan-start]
2017-05-23T20:43:18.080-0400: 40603.173: Total time for which application threads were stopped: 6.2005443 seconds, Stopping threads took: 0.0002322 seconds
2017-05-23T20:43:18.080-0400: 40603.174: Application time: 0.0002882 seconds
2017-05-23T20:43:18.114-0400: 40603.207: [GC concurrent-root-region-scan-end, 0.0339339 secs]
2017-05-23T20:43:18.114-0400: 40603.207: [GC concurrent-mark-start]
2017-05-23T20:43:18.142-0400: 40603.235: Total time for which application threads were stopped: 0.0613820 seconds, Stopping threads took: 0.0001677 seconds
2017-05-23T20:43:18.142-0400: 40603.236: Application time: 0.0005017 seconds
2017-05-23T20:43:18.144-0400: 40603.237: Total time for which application threads were stopped: 0.0013197 seconds, Stopping threads took: 0.0001188 seconds
2017-05-23T20:43:18.144-0400: 40603.237: Application time: 0.0001781 seconds
2017-05-23T20:43:18.144-0400: 40603.238: Total time for which application threads were stopped: 0.0005735 seconds, Stopping threads took: 0.0000568 seconds
2017-05-23T20:43:18.728-0400: 40603.821: Application time: 0.5835349 seconds
2017-05-23T20:43:18.730-0400: 40603.823: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 94371840 bytes, new threshold 15 (max 15)
- age   1:    8388248 bytes,    8388248 total
2017-05-23T20:43:19.821-0400: 40604.914: [SoftReference, 0 refs, 0.0009673 secs]2017-05-23T20:43:19.822-0400: 40604.915: [WeakReference, 0 refs, 0.0006733 secs]2017-05-23T20:43:19.823-0400: 40604.916: [FinalReference, 0 refs, 0.0006260 secs]2017-05-23T20:43:19.823-0400: 40604.917: [PhantomReference, 0 refs, 0 refs, 0.0013002 secs]2017-05-23T20:43:19.825-0400: 40604.918: [JNI Weak Reference, 0.0000642 secs] (to-space exhausted), 1.2567408 secs]
   [Parallel Time: 1084.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40603823.4, Avg: 40603823.5, Max: 40603823.6, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.7, Sum: 15.3]
      [Update RS (ms): Min: 23.8, Avg: 24.0, Max: 24.2, Diff: 0.3, Sum: 191.7]
         [Processed Buffers: Min: 49, Avg: 53.5, Max: 60, Diff: 11, Sum: 428]
      [Scan RS (ms): Min: 1.0, Avg: 1.1, Max: 1.2, Diff: 0.2, Sum: 8.6]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
      [Object Copy (ms): Min: 1056.4, Avg: 1056.8, Max: 1057.2, Diff: 0.8, Sum: 8454.7]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
         [Termination Attempts: Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 30]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]
      [GC Worker Total (ms): Min: 1084.0, Avg: 1084.1, Max: 1084.2, Diff: 0.2, Sum: 8673.2]
      [GC Worker End (ms): Min: 40604907.6, Avg: 40604907.7, Max: 40604907.7, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 171.7 ms]
      [Evacuation Failure: 159.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 9.9 ms]
      [Ref Enq: 0.6 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.3 ms]
      [Free CSet: 0.2 ms]
   [Eden: 230.0M(1424.0M)->0.0B(1432.0M) Survivors: 8192.0K->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]
 [Times: user=2.33 sys=0.34, real=1.26 secs] 
2017-05-23T20:43:19.987-0400: 40605.080: Total time for which application threads were stopped: 1.2587489 seconds, Stopping threads took: 0.0002182 seconds
2017-05-23T20:43:19.987-0400: 40605.080: Application time: 0.0003101 seconds
2017-05-23T20:43:19.988-0400: 40605.082: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 94371840 bytes, new threshold 15 (max 15)
2017-05-23T20:43:20.020-0400: 40605.113: [SoftReference, 0 refs, 0.0008856 secs]2017-05-23T20:43:20.020-0400: 40605.114: [WeakReference, 0 refs, 0.0005588 secs]2017-05-23T20:43:20.021-0400: 40605.114: [FinalReference, 0 refs, 0.0006006 secs]2017-05-23T20:43:20.022-0400: 40605.115: [PhantomReference, 0 refs, 0 refs, 0.0010837 secs]2017-05-23T20:43:20.023-0400: 40605.116: [JNI Weak Reference, 0.0000610 secs], 0.0356212 secs]
   [Parallel Time: 30.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40605081.9, Avg: 40605082.0, Max: 40605082.1, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.9, Avg: 2.0, Max: 2.5, Diff: 0.6, Sum: 16.1]
      [Update RS (ms): Min: 27.3, Avg: 27.4, Max: 27.5, Diff: 0.2, Sum: 219.3]
         [Processed Buffers: Min: 82, Avg: 87.4, Max: 92, Diff: 10, Sum: 699]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]
      [GC Worker Total (ms): Min: 29.7, Avg: 29.8, Max: 29.9, Diff: 0.2, Sum: 238.5]
      [GC Worker End (ms): Min: 40605111.8, Avg: 40605111.8, Max: 40605111.8, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 5.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.0 ms]
      [Ref Enq: 0.2 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]
 [Times: user=0.25 sys=0.00, real=0.04 secs] 
2017-05-23T20:43:20.024-0400: 40605.118: Total time for which application threads were stopped: 0.0372043 seconds, Stopping threads took: 0.0001640 seconds
2017-05-23T20:43:20.025-0400: 40605.118: Application time: 0.0002435 seconds
2017-05-23T20:43:20.026-0400: 40605.119: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 94371840 bytes, new threshold 15 (max 15)
2017-05-23T20:43:20.030-0400: 40605.123: [SoftReference, 0 refs, 0.0009405 secs]2017-05-23T20:43:20.031-0400: 40605.124: [WeakReference, 0 refs, 0.0005771 secs]2017-05-23T20:43:20.032-0400: 40605.125: [FinalReference, 0 refs, 0.0005766 secs]2017-05-23T20:43:20.032-0400: 40605.125: [PhantomReference, 0 refs, 0 refs, 0.0011847 secs]2017-05-23T20:43:20.033-0400: 40605.127: [JNI Weak Reference, 0.0000549 secs], 0.0087717 secs]
   [Parallel Time: 3.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40605119.3, Avg: 40605119.4, Max: 40605119.5, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.8, Max: 2.6, Diff: 1.0, Sum: 14.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 0.5, Max: 2, Diff: 2, Sum: 4]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.6, Diff: 0.6, Sum: 4.4]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 2.6, Avg: 2.6, Max: 2.7, Diff: 0.1, Sum: 21.1]
      [GC Worker End (ms): Min: 40605122.0, Avg: 40605122.1, Max: 40605122.1, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 5.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.1 ms]
      [Ref Enq: 0.3 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
2017-05-23T20:43:20.035-0400: 40605.128: Total time for which application threads were stopped: 0.0102350 seconds, Stopping threads took: 0.0000635 seconds
2017-05-23T20:43:20.035-0400: 40605.128: Application time: 0.0002150 seconds
2017-05-23T20:43:20.036-0400: 40605.129: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 94371840 bytes, new threshold 15 (max 15)
2017-05-23T20:43:20.040-0400: 40605.133: [SoftReference, 0 refs, 0.0010156 secs]2017-05-23T20:43:20.041-0400: 40605.134: [WeakReference, 0 refs, 0.0006580 secs]2017-05-23T20:43:20.042-0400: 40605.135: [FinalReference, 0 refs, 0.0006435 secs]2017-05-23T20:43:20.042-0400: 40605.136: [PhantomReference, 0 refs, 0 refs, 0.0012604 secs]2017-05-23T20:43:20.044-0400: 40605.137: [JNI Weak Reference, 0.0000513 secs], 0.0087896 secs]
   [Parallel Time: 2.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40605129.6, Avg: 40605129.7, Max: 40605129.8, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.5, Diff: 0.8, Sum: 14.9]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 0.6, Max: 1, Diff: 1, Sum: 5]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 1.3]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 2.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.5]
      [GC Worker End (ms): Min: 40605132.1, Avg: 40605132.2, Max: 40605132.2, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 5.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.4 ms]
      [Ref Enq: 0.3 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]
 [Times: user=0.04 sys=0.00, real=0.01 secs] 
2017-05-23T20:43:20.045-0400: 40605.138: Total time for which application threads were stopped: 0.0101403 seconds, Stopping threads took: 0.0000614 seconds
2017-05-23T20:43:20.045-0400: 40605.139: Application time: 0.0001681 seconds
2017-05-23T20:43:20.046-0400: 40605.140: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 94371840 bytes, new threshold 15 (max 15)
2017-05-23T20:43:20.050-0400: 40605.144: [SoftReference, 0 refs, 0.0008321 secs]2017-05-23T20:43:20.051-0400: 40605.145: [WeakReference, 0 refs, 0.0006103 secs]2017-05-23T20:43:20.052-0400: 40605.145: [FinalReference, 0 refs, 0.0007194 secs]2017-05-23T20:43:20.053-0400: 40605.146: [PhantomReference, 0 refs, 0 refs, 0.0010705 secs]2017-05-23T20:43:20.054-0400: 40605.147: [JNI Weak Reference, 0.0000508 secs], 0.0084107 secs]
   [Parallel Time: 2.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 40605139.9, Avg: 40605140.0, Max: 40605140.1, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.8, Sum: 15.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.4, Max: 1, Diff: 1, Sum: 3]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 2.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.2]
      [GC Worker End (ms): Min: 40605142.4, Avg: 40605142.4, Max: 40605142.5, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 5.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.1 ms]
      [Ref Enq: 0.3 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]
 [Times: user=0.03 sys=0.01, real=0.01 secs] 
2017-05-23T20:43:20.055-0400: 40605.148: Total time for which application threads were stopped: 0.0097185 seconds, Stopping threads took: 0.0001029 seconds
2017-05-23T20:43:20.055-0400: 40605.148: Application time: 0.0001505 seconds
2017-05-23T20:43:20.056-0400: 40605.149: [Full GC (Allocation Failure) 2017-05-23T20:43:22.446-0400: 40607.540: [SoftReference, 1667 refs, 0.0003772 secs]2017-05-23T20:43:22.447-0400: 40607.541: [WeakReference, 5626 refs, 0.0008068 secs]2017-05-23T20:43:22.448-0400: 40607.541: [FinalReference, 4015 refs, 0.0015169 secs]2017-05-23T20:43:22.450-0400: 40607.543: [PhantomReference, 1 refs, 372 refs, 0.0001585 secs]2017-05-23T20:43:22.450-0400: 40607.543: [JNI Weak Reference, 0.0000963 secs] 7139M->2327M(7168M), 9.7036499 secs]
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->2327.6M(7168.0M)], [Metaspace: 108907K->108428K(1150976K)]
 [Times: user=13.22 sys=0.00, real=9.70 secs] 
2017-05-23T20:43:29.760-0400: 40614.853: Total time for which application threads were stopped: 9.7047785 seconds, Stopping threads took: 0.0000566 seconds
2017-05-23T20:43:29.760-0400: 40614.854: [GC concurrent-mark-abort]
2017-05-23T20:43:29.763-0400: 40614.856: Application time: 0.0029444 seconds
> On Jul 21, 2017, at 5:34 PM, Thomas Schatzl <thomas.schatzl at oracle.com> wrote:
> 
> Hi Kirk,
> 
> On Fri, 2017-07-21 at 10:34 +0300, Kirk Pepperdine wrote:
>> Hi all,
>> 
>> A while back I mentioned to Erik at JFokus that I was seeing a
>> puzzling behavior in the G1 where without any obvious failure, heap
>> occupancy after collections would spike which would trigger a full
>> which would (unexpectedly) completely recover everything down to the
>> expected live set. Yesterday while working with Simone Bordet on the
>> problem we came to the realization that we were seeing a pattern
>> prior to the ramp up to the Full, Survivor space would be
>> ergonomically resized to 0 -> 0. The only way to reset the situation
>> was to run a full collection. In our minds this doesn’t make any
>> sense to reset survivor space to 0. So far this is an observation
>> from a single GC log but I recall seeing the pattern in many other
>> logs. Before I go through the exercise of building a super grep to
>> run over my G1 log repo I’d like to ask; under what conditions would
>> it make sense to have the survivor space resized to 0? And if not,
>>  would this be bug in G1? We tried reproducing the behavior in some
>> test applications but I fear we often only see this happening in
>> production applications that have been running for several days. It’s
>> a behavior that I’ve seen in 1.7.0 and 1.8.0. No word on 9.
> 
>   sounds similar to https://bugs.openjdk.java.net/browse/JDK-8037500.
> Could you please post the type of collections for a few more gcs before
> the zero-sized ones? It would be particularly interesting if there is a
> mixed gc with to-space exhaustion just before this sequence. And if
> there are log messages with attempts to start marking too.
> 
> As for why that bug has been closed as "won't fix" because we do not
> have a reproducer (any more) to test any changes in addition to the
> stated reasons that the performance impact seemed minor at that time.
> 
> There have been some changes in how the next gc is calculated in 9 too,
> so I do not know either if 9 is also affected (particularly one of
> these young-only gc's would not be issued any more).
> 
> I can think of at least one more reasons other than stated in the CR
> why this occurs at least for 8u60+ builds. There is the possibility
> particularly in conjunction with humongous object allocation that after
> starting the mutator, immediately afterwards a young gc that reclaims
> zero space is issued, e.g.:
> 
> young-gc, has X regions left at the end, starts mutators
> mutator 1 allocates exactly X regions as humongous objects
> mutator 2 allocates, finds that there are no regions left, issues
> young-gc request; in this young-gc eden and survivor are of obviously
> of zero size
> [...and so on...]
> 
> Note that this pattern could repeat multiple times as young gc may
> reclaim space from humongous objects (eager reclaim!) until at some
> point it ran into full gc.
> 
> The logging that shows humongous object allocation (something about
> reaching threshold and starting marking) could confirm this situation.
> 
> No guarantees about that being the actual issue though.
> 
> Thanks,
>   Thomas
> 




More information about the hotspot-gc-dev mailing list