<html><head></head><body dir="auto" style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;"><div class="ApplePlainTextBody">Hi all,<br><br>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.<br><br>Kind regards,<br>Kirk<br><br><br>2017-05-23T18:23:43.259-0400: 32228.353: [GC pause (G1 Evacuation Pause) (young)<br>Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>- age 1: 18873584 bytes, 18873584 total<br>2017-05-23T18:23:44.429-0400: 32229.523: [SoftReference, 0 refs, 0.0010544 secs]2017-05-23T18:23:44.430-0400: 32229.524: [WeakReference, 0 refs, 0.0006052 secs]2017-05-23T18:23:44.431-0400: 32229.524: [FinalReference, 0 refs, 0.0006467 secs]2017-05-23T18:23:44.432-0400: 32229.525: [PhantomReference, 0 refs, 0 refs, 0.0013639 secs]2017-05-23T18:23:44.433-0400: 32229.526: [JNI Weak Reference, 0.0000769 secs] (to-space exhausted), 1.3183739 secs]<br> [Parallel Time: 1168.2 ms, GC Workers: 8]<br> [GC Worker Start (ms): Min: 32228353.1, Avg: 32228353.6, Max: 32228354.2, Diff: 1.1]<br> [Ext Root Scanning (ms): Min: 0.9, Avg: 1.6, Max: 2.8, Diff: 1.9, Sum: 13.1]<br> [Update RS (ms): Min: 18.6, Avg: 31.4, Max: 35.7, Diff: 17.1, Sum: 250.9]<br> [Processed Buffers: Min: 22, Avg: 38.2, Max: 58, Diff: 36, Sum: 306]<br> [Scan RS (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 4.8]<br> [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br> [Object Copy (ms): Min: 1122.5, Avg: 1132.7, Max: 1147.6, Diff: 25.1, Sum: 9061.4]<br> [Termination (ms): Min: 0.0, Avg: 1.0, Max: 6.5, Diff: 6.5, Sum: 7.6]<br> [Termination Attempts: Min: 1, Avg: 1.8, Max: 7, Diff: 6, Sum: 14]<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: 1166.9, Avg: 1167.4, Max: 1168.0, Diff: 1.1, Sum: 9339.3]<br> [GC Worker End (ms): Min: 32229521.0, Avg: 32229521.0, Max: 32229521.1, 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: 149.6 ms]<br> [Evacuation Failure: 141.3 ms]<br> [Choose CSet: 0.0 ms]<br> [Ref Proc: 4.8 ms]<br> [Ref Enq: 0.6 ms]<br> [Redirty Cards: 1.9 ms]<br> [Humongous Register: 0.2 ms]<br> [Humongous Reclaim: 0.2 ms]<br> [Free CSet: 0.2 ms]<br> [Eden: 192.0M(1414.0M)->0.0B(1432.0M) Survivors: 18.0M->0.0B Heap: 7130.3M(7168.0M)->7130.3M(7168.0M)]<br> [Times: user=2.34 sys=0.33, real=1.32 secs] <br>2017-05-23T18:23:44.578-0400: 32229.671: Total time for which application threads were stopped: 1.3202387 seconds, Stopping threads took: 0.0002459 seconds<br>2017-05-23T18:23:44.578-0400: 32229.672: Application time: 0.0001752 seconds<br>2017-05-23T18:23:44.579-0400: 32229.673: [GC pause (G1 Evacuation Pause) (young)<br>Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>2017-05-23T18:23:44.616-0400: 32229.710: [SoftReference, 0 refs, 0.0011017 secs]2017-05-23T18:23:44.617-0400: 32229.711: [WeakReference, 0 refs, 0.0008938 secs]2017-05-23T18:23:44.618-0400: 32229.712: [FinalReference, 0 refs, 0.0007558 secs]2017-05-23T18:23:44.619-0400: 32229.712: [PhantomReference, 0 refs, 0 refs, 0.0015099 secs]2017-05-23T18:23:44.621-0400: 32229.714: [JNI Weak Reference, 0.0001007 secs], 0.0429276 secs]<br> [Parallel Time: 35.1 ms, GC Workers: 8]<br> [GC Worker Start (ms): Min: 32229673.0, Avg: 32229673.1, Max: 32229673.2, Diff: 0.2]<br> [Ext Root Scanning (ms): Min: 2.3, Avg: 3.1, Max: 4.2, Diff: 1.9, Sum: 24.5]<br> [Update RS (ms): Min: 29.8, Avg: 30.8, Max: 31.4, Diff: 1.6, Sum: 246.3]<br> [Processed Buffers: Min: 31, Avg: 84.5, Max: 109, Diff: 78, Sum: 676]<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.4, Diff: 0.3, Sum: 1.2]<br> [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.9, Diff: 0.9, Sum: 5.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.0, Max: 0.1, Diff: 0.0, Sum: 0.4]<br> [GC Worker Total (ms): Min: 34.6, Avg: 34.7, Max: 34.8, Diff: 0.2, Sum: 277.7]<br> [GC Worker End (ms): Min: 32229707.8, Avg: 32229707.8, Max: 32229707.8, Diff: 0.0]<br> [Code Root Fixup: 0.4 ms]<br> [Code Root Purge: 0.0 ms]<br> [Clear CT: 0.3 ms]<br> [Other: 7.1 ms]<br> [Choose CSet: 0.0 ms]<br> [Ref Proc: 5.6 ms]<br> [Ref Enq: 0.3 ms]<br> [Redirty Cards: 0.3 ms]<br> [Humongous Register: 0.1 ms]<br> [Humongous Reclaim: 0.3 ms]<br> [Free CSet: 0.1 ms]<br> [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7130.3M(7168.0M)->7130.3M(7168.0M)]<br> [Times: user=0.25 sys=0.01, real=0.04 secs] <br>2017-05-23T18:23:44.623-0400: 32229.716: Total time for which application threads were stopped: 0.0445157 seconds, Stopping threads took: 0.0000741 seconds<br>2017-05-23T18:23:44.623-0400: 32229.716: Application time: 0.0002351 seconds<br>2017-05-23T18:23:44.625-0400: 32229.718: [GC pause (G1 Evacuation Pause) (young)<br>Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>2017-05-23T18:23:44.629-0400: 32229.722: [SoftReference, 0 refs, 0.0010577 secs]2017-05-23T18:23:44.630-0400: 32229.723: [WeakReference, 0 refs, 0.0007176 secs]2017-05-23T18:23:44.630-0400: 32229.724: [FinalReference, 0 refs, 0.0006657 secs]2017-05-23T18:23:44.631-0400: 32229.724: [PhantomReference, 0 refs, 0 refs, 0.0013225 secs]2017-05-23T18:23:44.633-0400: 32229.726: [JNI Weak Reference, 0.0000608 secs], 0.0093163 secs]<br> [Parallel Time: 2.6 ms, GC Workers: 8]<br> [GC Worker Start (ms): Min: 32229718.2, Avg: 32229718.3, Max: 32229718.4, Diff: 0.2]<br> [Ext Root Scanning (ms): Min: 1.9, Avg: 2.0, Max: 2.4, Diff: 0.6, Sum: 16.4]<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.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.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.2, Max: 0.3, Diff: 0.3, Sum: 1.4]<br> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]<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.6]<br> [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.3]<br> [GC Worker End (ms): Min: 32229720.6, Avg: 32229720.7, Max: 32229720.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: 6.2 ms]<br> [Choose CSet: 0.0 ms]<br> [Ref Proc: 4.9 ms]<br> [Ref Enq: 0.3 ms]<br> [Redirty Cards: 0.3 ms]<br> [Humongous Register: 0.2 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: 7130.3M(7168.0M)->7130.3M(7168.0M)]<br> [Times: user=0.04 sys=0.00, real=0.01 secs] <br>2017-05-23T18:23:44.634-0400: 32229.727: Total time for which application threads were stopped: 0.0111086 seconds, Stopping threads took: 0.0000831 seconds<br>2017-05-23T18:23:44.634-0400: 32229.728: Application time: 0.0001943 seconds<br>2017-05-23T18:23:44.635-0400: 32229.729: [GC pause (G1 Evacuation Pause) (young)<br>Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br>2017-05-23T18:23:44.640-0400: 32229.733: [SoftReference, 0 refs, 0.0009254 secs]2017-05-23T18:23:44.641-0400: 32229.734: [WeakReference, 0 refs, 0.0005093 secs]2017-05-23T18:23:44.641-0400: 32229.734: [FinalReference, 0 refs, 0.0006326 secs]2017-05-23T18:23:44.642-0400: 32229.735: [PhantomReference, 0 refs, 0 refs, 0.0012809 secs]2017-05-23T18:23:44.643-0400: 32229.736: [JNI Weak Reference, 0.0000571 secs], 0.0088644 secs]<br> [Parallel Time: 2.7 ms, GC Workers: 8]<br> [GC Worker Start (ms): Min: 32229729.0, Avg: 32229729.1, Max: 32229729.2, Diff: 0.2]<br> [Ext Root Scanning (ms): Min: 1.8, Avg: 1.9, Max: 2.4, Diff: 0.6, Sum: 15.6]<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.2, Max: 1, Diff: 1, Sum: 2]<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.3]<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.1, Sum: 0.5]<br> [GC Worker Total (ms): Min: 2.2, Avg: 2.3, Max: 2.4, Diff: 0.2, Sum: 18.8]<br> [GC Worker End (ms): Min: 32229731.4, Avg: 32229731.4, Max: 32229731.4, 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.6 ms]<br> [Choose CSet: 0.0 ms]<br> [Ref Proc: 4.5 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: 7130.3M(7168.0M)->7130.3M(7168.0M)]<br> [Times: user=0.03 sys=0.00, real=0.01 secs] <br>2017-05-23T18:23:44.645-0400: 32229.738: Total time for which application threads were stopped: 0.0102139 seconds, Stopping threads took: 0.0000748 seconds<br>2017-05-23T18:23:44.645-0400: 32229.738: Application time: 0.0001619 seconds<br>2017-05-23T18:23:44.646-0400: 32229.739: [Full GC (Allocation Failure) 2017-05-23T18:23:47.903-0400: 32232.996: [SoftReference, 1716 refs, 0.0003858 secs]2017-05-23T18:23:47.903-0400: 32232.997: [WeakReference, 5976 refs, 0.0008711 secs]2017-05-23T18:23:47.904-0400: 32232.998: [FinalReference, 7405 refs, 0.0024551 secs]2017-05-23T18:23:47.907-0400: 32233.000: [PhantomReference, 1 refs, 372 refs, 0.0002147 secs]2017-05-23T18:23:47.907-0400: 32233.000: [JNI Weak Reference, 0.0000963 secs] 7130M->2838M(7168M), 12.1445105 secs]<br> [Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: 7130.3M(7168.0M)->2838.1M(7168.0M)], [Metaspace: 108777K->108210K(1150976K)]<br> [Times: user=16.85 sys=0.00, real=12.15 secs] </div></body></html>