Bug in G1

monica beckwith monica.beckwith at gmail.com
Sun Jul 23 19:09:14 UTC 2017


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> 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>
> 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
> >
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20170723/8ed0c5e0/attachment.htm>


More information about the hotspot-gc-dev mailing list