Bug in G1
Kirk Pepperdine
kirk at kodewerk.com
Mon Jul 24 19:43:59 UTC 2017
Hi Monica et all…
I see this bug in all versions of 7 and 8. I can put up more GC logs once I get to a more stable internet connection.
Kind regards,
Kirk
> On Jul 23, 2017, at 9:09 PM, monica beckwith <monica.beckwith at gmail.com> wrote:
>
> Hello Kirk and Thomas,
>
> I think the problem is that the heap is not sized to accommodate the humongous objects. I think this log is post 8 update 40, and that's why you see those young collections at the lowest young occupancy since it's trying to reclaim humongous regions. Kirk, can you please show a log prior to 8u40?
>
> Thanks,
> Monica
>
> On Jul 23, 2017 5:52 AM, "Kirk Pepperdine" <kirk at kodewerk.com <mailto:kirk at kodewerk.com>> wrote:
> 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 <mailto: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 <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
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20170724/ee64d917/attachment.htm>
More information about the hotspot-gc-dev
mailing list