<div><div dir="auto">I've seen G1 get into a similar loop.  Do you see any concurrent mark initiation? It's possible conc marking is still running and therefore mixed GCs aren't possible yet.  There are some ways to tune G1 to initiate concurrent marking sooner (or more "aggressively" with more conc GC threads), but would be good to first know if you're seeing that.</div><br><div class="gmail_quote"><div>On Sun, Jul 23, 2017 at 6:52 AM Kirk Pepperdine <<a href="mailto:kirk@kodewerk.com">kirk@kodewerk.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Thanks for the information. I’ve shared the entire log with you on dropbox. Feel free to distribute it as you see fit.<br>
<br>
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.<br>
<br>
Kind regards,<br>
Kirk<br>
<br>
<br>
2017-05-23T20:42:55.303-0400: 40580.396: Application time: 0.8539675 seconds<br>
2017-05-23T20:42:55.304-0400: 40580.398: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 169869312 bytes, new threshold 15 (max 15)<br>
- age   1:    3278808 bytes,    3278808 total<br>
- age   2:   71278552 bytes,   74557360 total<br>
- age   3:     533720 bytes,   75091080 total<br>
- age   4:   12897544 bytes,   87988624 total<br>
- age   5:     796672 bytes,   88785296 total<br>
- age   6:     503288 bytes,   89288584 total<br>
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]<br>
   [Parallel Time: 57.9 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40580398.1, Avg: 40580398.2, Max: 40580398.3, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.9, Max: 2.7, Diff: 1.0, Sum: 15.2]<br>
      [Update RS (ms): Min: 15.2, Avg: 15.7, Max: 15.8, Diff: 0.6, Sum: 125.4]<br>
         [Processed Buffers: Min: 44, Avg: 50.1, Max: 62, Diff: 18, Sum: 401]<br>
      [Scan RS (ms): Min: 1.9, Avg: 2.0, Max: 2.1, Diff: 0.2, Sum: 15.9]<br>
      [Code Root Scanning (ms): Min: 1.6, Avg: 1.7, Max: 1.7, Diff: 0.1, Sum: 13.5]<br>
      [Object Copy (ms): Min: 36.0, Avg: 36.2, Max: 36.2, Diff: 0.2, Sum: 289.2]<br>
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.0]<br>
      [GC Worker Total (ms): Min: 57.4, Avg: 57.5, Max: 57.6, Diff: 0.2, Sum: 460.3]<br>
      [GC Worker End (ms): Min: 40580455.7, Avg: 40580455.7, Max: 40580455.8, Diff: 0.1]<br>
   [Code Root Fixup: 0.2 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.8 ms]<br>
   [Other: 8.1 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 4.7 ms]<br>
      [Ref Enq: 0.3 ms]<br>
      [Redirty Cards: 0.3 ms]<br>
      [Humongous Register: 0.2 ms]<br>
      [Humongous Reclaim: 0.1 ms]<br>
      [Free CSet: 1.9 ms]<br>
   [Eden: 2484.0M(2484.0M)->0.0B(3544.0M) Survivors: 98.0M->100.0M Heap: 5189.0M(7168.0M)->2708.0M(7168.0M)]<br>
 [Times: user=0.45 sys=0.03, real=0.07 secs]<br>
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<br>
2017-05-23T20:42:59.372-0400: 40584.465: Application time: 4.0004774 seconds<br>
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<br>
2017-05-23T20:43:05.891-0400: 40590.984: Application time: 6.5149722 seconds<br>
2017-05-23T20:43:05.892-0400: 40590.985: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 239075328 bytes, new threshold 15 (max 15)<br>
- age   1:    4934368 bytes,    4934368 total<br>
- age   2:    2633808 bytes,    7568176 total<br>
- age   3:   71264464 bytes,   78832640 total<br>
- age   4:     527368 bytes,   79360008 total<br>
- age   5:   12893400 bytes,   92253408 total<br>
- age   6:     750128 bytes,   93003536 total<br>
- age   7:     432784 bytes,   93436320 total<br>
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]<br>
   [Parallel Time: 3599.9 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40590985.9, Avg: 40590986.0, Max: 40590986.1, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.3, Diff: 0.6, Sum: 15.2]<br>
      [Update RS (ms): Min: 68.3, Avg: 68.4, Max: 68.5, Diff: 0.2, Sum: 547.6]<br>
         [Processed Buffers: Min: 32, Avg: 49.0, Max: 72, Diff: 40, Sum: 392]<br>
      [Scan RS (ms): Min: 2.8, Avg: 2.9, Max: 3.0, Diff: 0.1, Sum: 23.2]<br>
      [Code Root Scanning (ms): Min: 2.4, Avg: 2.5, Max: 2.5, Diff: 0.1, Sum: 19.7]<br>
      [Object Copy (ms): Min: 3523.7, Avg: 3523.8, Max: 3523.9, Diff: 0.2, Sum: 28190.6]<br>
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 3599.6, Avg: 3599.7, Max: 3599.8, Diff: 0.2, Sum: 28797.6]<br>
      [GC Worker End (ms): Min: 40594585.6, Avg: 40594585.7, Max: 40594585.7, Diff: 0.1]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 1.2 ms]<br>
   [Other: 1265.8 ms]<br>
      [Evacuation Failure: 1248.2 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 12.4 ms]<br>
      [Ref Enq: 0.5 ms]<br>
      [Redirty Cards: 2.1 ms]<br>
      [Humongous Register: 0.2 ms]<br>
      [Humongous Reclaim: 0.1 ms]<br>
      [Free CSet: 1.5 ms]<br>
   [Eden: 3544.0M(3544.0M)->0.0B(976.0M) Survivors: 100.0M->456.0M Heap: 6274.3M(7168.0M)->5978.2M(7168.0M)]<br>
 [Times: user=13.58 sys=0.11, real=4.86 secs]<br>
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<br>
2017-05-23T20:43:11.762-0400: 40596.855: Application time: 1.0019247 seconds<br>
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<br>
2017-05-23T20:43:11.880-0400: 40596.973: Application time: 0.1164884 seconds<br>
2017-05-23T20:43:11.881-0400: 40596.974: [GC pause (G1 Humongous Allocation) (young) (initial-mark)<br>
Desired survivor size 94371840 bytes, new threshold 1 (max 15)<br>
- age   1:  477501112 bytes,  477501112 total<br>
- age   2:     182296 bytes,  477683408 total<br>
- age   3:      78880 bytes,  477762288 total<br>
- age   4:      45376 bytes,  477807664 total<br>
- age   5:      92304 bytes,  477899968 total<br>
- age   6:      75448 bytes,  477975416 total<br>
- age   7:      86752 bytes,  478062168 total<br>
- age   8:      71408 bytes,  478133576 total<br>
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]<br>
   [Parallel Time: 5446.3 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40596975.6, Avg: 40596975.7, Max: 40596975.8, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 2.9, Avg: 3.1, Max: 3.2, Diff: 0.3, Sum: 24.4]<br>
      [Update RS (ms): Min: 10.1, Avg: 10.3, Max: 10.5, Diff: 0.4, Sum: 82.6]<br>
         [Processed Buffers: Min: 33, Avg: 40.2, Max: 51, Diff: 18, Sum: 322]<br>
      [Scan RS (ms): Min: 30.7, Avg: 31.1, Max: 32.4, Diff: 1.8, Sum: 249.0]<br>
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 2.8]<br>
      [Object Copy (ms): Min: 5399.2, Avg: 5400.6, Max: 5400.9, Diff: 1.7, Sum: 43204.5]<br>
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.3]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 5445.5, Avg: 5445.6, Max: 5445.7, Diff: 0.2, Sum: 43565.0]<br>
      [GC Worker End (ms): Min: 40602421.3, Avg: 40602421.4, Max: 40602421.4, Diff: 0.1]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.8 ms]<br>
   [Other: 751.4 ms]<br>
      [Evacuation Failure: 728.5 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 17.8 ms]<br>
      [Ref Enq: 0.5 ms]<br>
      [Redirty Cards: 2.1 ms]<br>
      [Humongous Register: 0.1 ms]<br>
      [Humongous Reclaim: 0.2 ms]<br>
      [Free CSet: 0.8 ms]<br>
   [Eden: 878.0M(976.0M)->0.0B(1424.0M) Survivors: 456.0M->8192.0K Heap: 6856.2M(7168.0M)->6908.2M(7168.0M)]<br>
 [Times: user=11.66 sys=1.15, real=6.19 secs]<br>
2017-05-23T20:43:18.080-0400: 40603.173: [GC concurrent-root-region-scan-start]<br>
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<br>
2017-05-23T20:43:18.080-0400: 40603.174: Application time: 0.0002882 seconds<br>
2017-05-23T20:43:18.114-0400: 40603.207: [GC concurrent-root-region-scan-end, 0.0339339 secs]<br>
2017-05-23T20:43:18.114-0400: 40603.207: [GC concurrent-mark-start]<br>
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<br>
2017-05-23T20:43:18.142-0400: 40603.236: Application time: 0.0005017 seconds<br>
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<br>
2017-05-23T20:43:18.144-0400: 40603.237: Application time: 0.0001781 seconds<br>
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<br>
2017-05-23T20:43:18.728-0400: 40603.821: Application time: 0.5835349 seconds<br>
2017-05-23T20:43:18.730-0400: 40603.823: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>
- age   1:    8388248 bytes,    8388248 total<br>
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]<br>
   [Parallel Time: 1084.5 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40603823.4, Avg: 40603823.5, Max: 40603823.6, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.7, Sum: 15.3]<br>
      [Update RS (ms): Min: 23.8, Avg: 24.0, Max: 24.2, Diff: 0.3, Sum: 191.7]<br>
         [Processed Buffers: Min: 49, Avg: 53.5, Max: 60, Diff: 11, Sum: 428]<br>
      [Scan RS (ms): Min: 1.0, Avg: 1.1, Max: 1.2, Diff: 0.2, Sum: 8.6]<br>
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]<br>
      [Object Copy (ms): Min: 1056.4, Avg: 1056.8, Max: 1057.2, Diff: 0.8, Sum: 8454.7]<br>
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]<br>
         [Termination Attempts: Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 30]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 1084.0, Avg: 1084.1, Max: 1084.2, Diff: 0.2, Sum: 8673.2]<br>
      [GC Worker End (ms): Min: 40604907.6, Avg: 40604907.7, Max: 40604907.7, Diff: 0.0]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.3 ms]<br>
   [Other: 171.7 ms]<br>
      [Evacuation Failure: 159.4 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 9.9 ms]<br>
      [Ref Enq: 0.6 ms]<br>
      [Redirty Cards: 0.6 ms]<br>
      [Humongous Register: 0.2 ms]<br>
      [Humongous Reclaim: 0.3 ms]<br>
      [Free CSet: 0.2 ms]<br>
   [Eden: 230.0M(1424.0M)->0.0B(1432.0M) Survivors: 8192.0K->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]<br>
 [Times: user=2.33 sys=0.34, real=1.26 secs]<br>
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<br>
2017-05-23T20:43:19.987-0400: 40605.080: Application time: 0.0003101 seconds<br>
2017-05-23T20:43:19.988-0400: 40605.082: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>
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]<br>
   [Parallel Time: 30.0 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40605081.9, Avg: 40605082.0, Max: 40605082.1, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.9, Avg: 2.0, Max: 2.5, Diff: 0.6, Sum: 16.1]<br>
      [Update RS (ms): Min: 27.3, Avg: 27.4, Max: 27.5, Diff: 0.2, Sum: 219.3]<br>
         [Processed Buffers: Min: 82, Avg: 87.4, Max: 92, Diff: 10, Sum: 699]<br>
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.4]<br>
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]<br>
      [GC Worker Total (ms): Min: 29.7, Avg: 29.8, Max: 29.9, Diff: 0.2, Sum: 238.5]<br>
      [GC Worker End (ms): Min: 40605111.8, Avg: 40605111.8, Max: 40605111.8, Diff: 0.0]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.2 ms]<br>
   [Other: 5.1 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 4.0 ms]<br>
      [Ref Enq: 0.2 ms]<br>
      [Redirty Cards: 0.2 ms]<br>
      [Humongous Register: 0.1 ms]<br>
      [Humongous Reclaim: 0.2 ms]<br>
      [Free CSet: 0.1 ms]<br>
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]<br>
 [Times: user=0.25 sys=0.00, real=0.04 secs]<br>
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<br>
2017-05-23T20:43:20.025-0400: 40605.118: Application time: 0.0002435 seconds<br>
2017-05-23T20:43:20.026-0400: 40605.119: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>
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]<br>
   [Parallel Time: 3.0 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40605119.3, Avg: 40605119.4, Max: 40605119.5, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.6, Avg: 1.8, Max: 2.6, Diff: 1.0, Sum: 14.8]<br>
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]<br>
         [Processed Buffers: Min: 0, Avg: 0.5, Max: 2, Diff: 2, Sum: 4]<br>
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]<br>
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]<br>
      [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.6, Diff: 0.6, Sum: 4.4]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 2.6, Avg: 2.6, Max: 2.7, Diff: 0.1, Sum: 21.1]<br>
      [GC Worker End (ms): Min: 40605122.0, Avg: 40605122.1, Max: 40605122.1, Diff: 0.1]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.3 ms]<br>
   [Other: 5.2 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 4.1 ms]<br>
      [Ref Enq: 0.3 ms]<br>
      [Redirty Cards: 0.3 ms]<br>
      [Humongous Register: 0.1 ms]<br>
      [Humongous Reclaim: 0.1 ms]<br>
      [Free CSet: 0.1 ms]<br>
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]<br>
 [Times: user=0.03 sys=0.00, real=0.01 secs]<br>
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<br>
2017-05-23T20:43:20.035-0400: 40605.128: Application time: 0.0002150 seconds<br>
2017-05-23T20:43:20.036-0400: 40605.129: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>
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]<br>
   [Parallel Time: 2.7 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40605129.6, Avg: 40605129.7, Max: 40605129.8, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.5, Diff: 0.8, Sum: 14.9]<br>
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]<br>
         [Processed Buffers: Min: 0, Avg: 0.6, Max: 1, Diff: 1, Sum: 5]<br>
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 1.3]<br>
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 2.5]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.5]<br>
      [GC Worker End (ms): Min: 40605132.1, Avg: 40605132.2, Max: 40605132.2, Diff: 0.0]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.3 ms]<br>
   [Other: 5.5 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 4.4 ms]<br>
      [Ref Enq: 0.3 ms]<br>
      [Redirty Cards: 0.3 ms]<br>
      [Humongous Register: 0.1 ms]<br>
      [Humongous Reclaim: 0.1 ms]<br>
      [Free CSet: 0.1 ms]<br>
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]<br>
 [Times: user=0.04 sys=0.00, real=0.01 secs]<br>
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<br>
2017-05-23T20:43:20.045-0400: 40605.139: Application time: 0.0001681 seconds<br>
2017-05-23T20:43:20.046-0400: 40605.140: [GC pause (G1 Evacuation Pause) (young)<br>
Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>
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]<br>
   [Parallel Time: 2.7 ms, GC Workers: 8]<br>
      [GC Worker Start (ms): Min: 40605139.9, Avg: 40605140.0, Max: 40605140.1, Diff: 0.2]<br>
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.8, Sum: 15.1]<br>
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]<br>
         [Processed Buffers: Min: 0, Avg: 0.4, Max: 1, Diff: 1, Sum: 3]<br>
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
      [Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]<br>
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 2.2]<br>
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br>
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br>
      [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.2]<br>
      [GC Worker End (ms): Min: 40605142.4, Avg: 40605142.4, Max: 40605142.5, Diff: 0.1]<br>
   [Code Root Fixup: 0.3 ms]<br>
   [Code Root Purge: 0.0 ms]<br>
   [Clear CT: 0.2 ms]<br>
   [Other: 5.1 ms]<br>
      [Choose CSet: 0.0 ms]<br>
      [Ref Proc: 4.1 ms]<br>
      [Ref Enq: 0.3 ms]<br>
      [Redirty Cards: 0.2 ms]<br>
      [Humongous Register: 0.1 ms]<br>
      [Humongous Reclaim: 0.1 ms]<br>
      [Free CSet: 0.1 ms]<br>
   [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7139.5M(7168.0M)->7139.5M(7168.0M)]<br>
 [Times: user=0.03 sys=0.01, real=0.01 secs]<br>
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<br>
2017-05-23T20:43:20.055-0400: 40605.148: Application time: 0.0001505 seconds<br>
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]<br>
   [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)]<br>
 [Times: user=13.22 sys=0.00, real=9.70 secs]<br>
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<br>
2017-05-23T20:43:29.760-0400: 40614.854: [GC concurrent-mark-abort]<br>
2017-05-23T20:43:29.763-0400: 40614.856: Application time: 0.0029444 seconds<br>
> On Jul 21, 2017, at 5:34 PM, Thomas Schatzl <<a href="mailto:thomas.schatzl@oracle.com" target="_blank">thomas.schatzl@oracle.com</a>> wrote:<br>
><br>
> Hi Kirk,<br>
><br>
> On Fri, 2017-07-21 at 10:34 +0300, Kirk Pepperdine wrote:<br>
>> Hi all,<br>
>><br>
>> A while back I mentioned to Erik at JFokus that I was seeing a<br>
>> puzzling behavior in the G1 where without any obvious failure, heap<br>
>> occupancy after collections would spike which would trigger a full<br>
>> which would (unexpectedly) completely recover everything down to the<br>
>> expected live set. Yesterday while working with Simone Bordet on the<br>
>> problem we came to the realization that we were seeing a pattern<br>
>> prior to the ramp up to the Full, Survivor space would be<br>
>> ergonomically resized to 0 -> 0. The only way to reset the situation<br>
>> was to run a full collection. In our minds this doesn’t make any<br>
>> sense to reset survivor space to 0. So far this is an observation<br>
>> from a single GC log but I recall seeing the pattern in many other<br>
>> logs. Before I go through the exercise of building a super grep to<br>
>> run over my G1 log repo I’d like to ask; under what conditions would<br>
>> it make sense to have the survivor space resized to 0? And if not,<br>
>>  would this be bug in G1? We tried reproducing the behavior in some<br>
>> test applications but I fear we often only see this happening in<br>
>> production applications that have been running for several days. It’s<br>
>> a behavior that I’ve seen in 1.7.0 and 1.8.0. No word on 9.<br>
><br>
>   sounds similar to <a href="https://bugs.openjdk.java.net/browse/JDK-8037500" rel="noreferrer" target="_blank">https://bugs.openjdk.java.net/browse/JDK-8037500</a>.<br>
> Could you please post the type of collections for a few more gcs before<br>
> the zero-sized ones? It would be particularly interesting if there is a<br>
> mixed gc with to-space exhaustion just before this sequence. And if<br>
> there are log messages with attempts to start marking too.<br>
><br>
> As for why that bug has been closed as "won't fix" because we do not<br>
> have a reproducer (any more) to test any changes in addition to the<br>
> stated reasons that the performance impact seemed minor at that time.<br>
><br>
> There have been some changes in how the next gc is calculated in 9 too,<br>
> so I do not know either if 9 is also affected (particularly one of<br>
> these young-only gc's would not be issued any more).<br>
><br>
> I can think of at least one more reasons other than stated in the CR<br>
> why this occurs at least for 8u60+ builds. There is the possibility<br>
> particularly in conjunction with humongous object allocation that after<br>
> starting the mutator, immediately afterwards a young gc that reclaims<br>
> zero space is issued, e.g.:<br>
><br>
> young-gc, has X regions left at the end, starts mutators<br>
> mutator 1 allocates exactly X regions as humongous objects<br>
> mutator 2 allocates, finds that there are no regions left, issues<br>
> young-gc request; in this young-gc eden and survivor are of obviously<br>
> of zero size<br>
> [...and so on...]<br>
><br>
> Note that this pattern could repeat multiple times as young gc may<br>
> reclaim space from humongous objects (eager reclaim!) until at some<br>
> point it ran into full gc.<br>
><br>
> The logging that shows humongous object allocation (something about<br>
> reaching threshold and starting marking) could confirm this situation.<br>
><br>
> No guarantees about that being the actual issue though.<br>
><br>
> Thanks,<br>
>   Thomas<br>
><br>
<br>
</blockquote></div></div><div dir="ltr">-- <br></div><div data-smartmail="gmail_signature">Sent from my phone</div>