Bug in G1
Vitaly Davidovich
vitalyd at gmail.com
Sun Jul 23 16:43:50 UTC 2017
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.
On Sun, Jul 23, 2017 at 6: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
> >
>
> --
Sent from my phone
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20170723/c25c1852/attachment.htm>
More information about the hotspot-gc-dev
mailing list