[prev in list] [next in list] [prev in thread] [next in thread]
List: openjdk-hotspot-gc-dev
Subject: Re: Bug in G1
From: Kirk Pepperdine <kirk () kodewerk ! com>
Date: 2017-07-24 19:43:59
Message-ID: 2479C8EB-F38C-4804-94E5-EC613BC6457E () kodewerk ! com
[Download RAW message or body]
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@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@kodewerk.com \
> <mailto:kirk@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@oracle.com \
> > <mailto:thomas.schatzl@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
> >
>
[Attachment #3 (unknown)]
<html><head><meta http-equiv="Content-Type" content="text/html \
charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; \
-webkit-line-break: after-white-space;" class="">Hi Monica et all…<div class=""><br \
class=""></div><div class="">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.</div><div class=""><br \
class=""></div><div class="">Kind regards,</div><div class="">Kirk</div><div \
class=""><br class=""><div><blockquote type="cite" class=""><div class="">On Jul 23, \
2017, at 9:09 PM, monica beckwith <<a href="mailto:monica.beckwith@gmail.com" \
class="">monica.beckwith@gmail.com</a>> wrote:</div><br \
class="Apple-interchange-newline"><div class=""><div dir="auto" class="">Hello Kirk \
and Thomas,<div dir="auto" class=""><br class=""></div><div dir="auto" class="">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?</div><div dir="auto" class=""><br \
class=""></div><div dir="auto" class="">Thanks,</div><div dir="auto" \
class="">Monica</div></div><div class="gmail_extra"><br class=""><div \
class="gmail_quote">On Jul 23, 2017 5:52 AM, "Kirk Pepperdine" <<a \
href="mailto:kirk@kodewerk.com" class="">kirk@kodewerk.com</a>> wrote:<br \
type="attribution" class=""><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 class=""> <br class="">
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 class=""> <br \
class=""> Kind regards,<br class="">
Kirk<br class="">
<br class="">
<br class="">
2017-05-23T20:42:55.303-0400: 40580.396: Application time: 0.8539675 seconds<br \
class=""> 2017-05-23T20:42:55.304-0400: 40580.398: [GC pause (G1 Evacuation Pause) \
(young)<br class=""> Desired survivor size 169869312 bytes, new threshold 15 (max \
15)<br class="">
- age 1: 3278808 bytes, 3278808 total<br \
class="">
- age 2: 71278552 bytes, 74557360 total<br \
class="">
- age 3: 533720 bytes, 75091080 total<br \
class="">
- age 4: 12897544 bytes, 87988624 total<br \
class="">
- age 5: 796672 bytes, 88785296 total<br \
class="">
- age 6: 503288 bytes, 89288584 total<br \
class=""> 2017-05-23T20:42:55.363-0400: 40580.457: [SoftReference, 0 refs, 0.0010011 \
secs]2017-05-23T20:42:55.364-<wbr class="">0400: 40580.458: [WeakReference, 367 refs, \
0.0006136 secs]2017-05-23T20:42:55.365-<wbr class="">0400: 40580.458: \
[FinalReference, 7659 refs, 0.0014460 secs]2017-05-23T20:42:55.366-<wbr \
class="">0400: 40580.460: [PhantomReference, 0 refs, 0 refs, 0.0011060 \
secs]2017-05-23T20:42:55.367-<wbr class="">0400: 40580.461: [JNI Weak Reference, \
0.0000647 secs], 0.0669684 secs]<br class=""> [Parallel Time: 57.9 ms, \
GC Workers: 8]<br class=""> [GC Worker Start (ms): Min: \
40580398.1, Avg: 40580398.2, Max: 40580398.3, Diff: 0.2]<br class=""> \
[Ext Root Scanning (ms): Min: 1.6, Avg: 1.9, Max: 2.7, Diff: 1.0, Sum: \
15.2]<br class=""> [Update RS (ms): Min: 15.2, Avg: 15.7, Max: \
15.8, Diff: 0.6, Sum: 125.4]<br class=""> \
[Processed Buffers: Min: 44, Avg: 50.1, Max: 62, Diff: 18, Sum: 401]<br \
class=""> [Scan RS (ms): Min: 1.9, Avg: 2.0, Max: 2.1, Diff: \
0.2, Sum: 15.9]<br class=""> [Code Root Scanning (ms): Min: 1.6, \
Avg: 1.7, Max: 1.7, Diff: 0.1, Sum: 13.5]<br class=""> [Object \
Copy (ms): Min: 36.0, Avg: 36.2, Max: 36.2, Diff: 0.2, Sum: 289.2]<br class=""> \
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: \
0.2]<br class=""> [Termination Attempts: Min: 1, \
Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> [GC Worker Other \
(ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.0]<br class=""> \
[GC Worker Total (ms): Min: 57.4, Avg: 57.5, Max: 57.6, Diff: 0.2, Sum: \
460.3]<br class=""> [GC Worker End (ms): Min: 40580455.7, Avg: \
40580455.7, Max: 40580455.8, Diff: 0.1]<br class=""> [Code Root Fixup: \
0.2 ms]<br class=""> [Code Root Purge: 0.0 ms]<br class="">
[Clear CT: 0.8 ms]<br class="">
[Other: 8.1 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 4.7 ms]<br class="">
[Ref Enq: 0.3 ms]<br class="">
[Redirty Cards: 0.3 ms]<br class="">
[Humongous Register: 0.2 ms]<br class="">
[Humongous Reclaim: 0.1 ms]<br class="">
[Free CSet: 1.9 ms]<br class="">
[Eden: 2484.0M(2484.0M)->0.0B(3544.<wbr class="">0M) Survivors: \
98.0M->100.0M Heap: 5189.0M(7168.0M)->2708.0M(<wbr class="">7168.0M)]<br \
class=""> [Times: user=0.45 sys=0.03, real=0.07 secs]<br class="">
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 \
class=""> 2017-05-23T20:42:59.372-0400: 40584.465: Application time: 4.0004774 \
seconds<br class=""> 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 class=""> 2017-05-23T20:43:05.891-0400: 40590.984: Application time: \
6.5149722 seconds<br class=""> 2017-05-23T20:43:05.892-0400: 40590.985: [GC pause (G1 \
Evacuation Pause) (young)<br class=""> Desired survivor size 239075328 bytes, new \
threshold 15 (max 15)<br class="">
- age 1: 4934368 bytes, 4934368 total<br \
class="">
- age 2: 2633808 bytes, 7568176 total<br \
class="">
- age 3: 71264464 bytes, 78832640 total<br \
class="">
- age 4: 527368 bytes, 79360008 total<br \
class="">
- age 5: 12893400 bytes, 92253408 total<br \
class="">
- age 6: 750128 bytes, 93003536 total<br \
class="">
- age 7: 432784 bytes, 93436320 total<br \
class=""> 2017-05-23T20:43:09.493-0400: 40594.586: [SoftReference, 0 refs, 0.0067938 \
secs]2017-05-23T20:43:09.500-<wbr class="">0400: 40594.593: [WeakReference, 0 refs, \
0.0033881 secs]2017-05-23T20:43:09.503-<wbr class="">0400: 40594.597: \
[FinalReference, 0 refs, 0.0005787 secs]2017-05-23T20:43:09.504-<wbr class="">0400: \
40594.597: [PhantomReference, 0 refs, 0 refs, 0.0011377 \
secs]2017-05-23T20:43:09.505-<wbr class="">0400: 40594.598: [JNI Weak Reference, \
0.0000618 secs] (to-space exhausted), 4.8672247 secs]<br class=""> \
[Parallel Time: 3599.9 ms, GC Workers: 8]<br class=""> [GC \
Worker Start (ms): Min: 40590985.9, Avg: 40590986.0, Max: 40590986.1, Diff: 0.2]<br \
class=""> [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.3, \
Diff: 0.6, Sum: 15.2]<br class=""> [Update RS (ms): Min: 68.3, \
Avg: 68.4, Max: 68.5, Diff: 0.2, Sum: 547.6]<br class=""> \
[Processed Buffers: Min: 32, Avg: 49.0, Max: 72, Diff: 40, Sum: 392]<br \
class=""> [Scan RS (ms): Min: 2.8, Avg: 2.9, Max: 3.0, Diff: \
0.1, Sum: 23.2]<br class=""> [Code Root Scanning (ms): Min: 2.4, \
Avg: 2.5, Max: 2.5, Diff: 0.1, Sum: 19.7]<br class=""> [Object \
Copy (ms): Min: 3523.7, Avg: 3523.8, Max: 3523.9, Diff: 0.2, Sum: 28190.6]<br \
class=""> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: \
0.2, Sum: 0.7]<br class=""> [Termination Attempts: \
Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> [GC \
Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]<br class=""> \
[GC Worker Total (ms): Min: 3599.6, Avg: 3599.7, Max: 3599.8, \
Diff: 0.2, Sum: 28797.6]<br class=""> [GC Worker End (ms): Min: \
40594585.6, Avg: 40594585.7, Max: 40594585.7, Diff: 0.1]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 1.2 ms]<br class="">
[Other: 1265.8 ms]<br class="">
[Evacuation Failure: 1248.2 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 12.4 ms]<br class="">
[Ref Enq: 0.5 ms]<br class="">
[Redirty Cards: 2.1 ms]<br class="">
[Humongous Register: 0.2 ms]<br class="">
[Humongous Reclaim: 0.1 ms]<br class="">
[Free CSet: 1.5 ms]<br class="">
[Eden: 3544.0M(3544.0M)->0.0B(976.0M) Survivors: 100.0M->456.0M \
Heap: 6274.3M(7168.0M)->5978.2M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=13.58 sys=0.11, real=4.86 secs]<br class=""> 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 class=""> 2017-05-23T20:43:11.762-0400: \
40596.855: Application time: 1.0019247 seconds<br class=""> \
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 \
class=""> 2017-05-23T20:43:11.880-0400: 40596.973: Application time: 0.1164884 \
seconds<br class=""> 2017-05-23T20:43:11.881-0400: 40596.974: [GC pause (G1 Humongous \
Allocation) (young) (initial-mark)<br class=""> Desired survivor size 94371840 bytes, \
new threshold 1 (max 15)<br class="">
- age 1: 477501112 bytes, 477501112 total<br class="">
- age 2: 182296 bytes, 477683408 total<br \
class="">
- age 3: 78880 bytes, 477762288 total<br \
class="">
- age 4: 45376 bytes, 477807664 total<br \
class="">
- age 5: 92304 bytes, 477899968 total<br \
class="">
- age 6: 75448 bytes, 477975416 total<br \
class="">
- age 7: 86752 bytes, 478062168 total<br \
class="">
- age 8: 71408 bytes, 478133576 total<br \
class=""> 2017-05-23T20:43:17.335-0400: 40602.428: [SoftReference, 0 refs, 0.0071133 \
secs]2017-05-23T20:43:17.342-<wbr class="">0400: 40602.435: [WeakReference, 3 refs, \
0.0007987 secs]2017-05-23T20:43:17.343-<wbr class="">0400: 40602.436: \
[FinalReference, 182 refs, 0.0017603 secs]2017-05-23T20:43:17.345-<wbr class="">0400: \
40602.438: [PhantomReference, 0 refs, 0 refs, 0.0015961 \
secs]2017-05-23T20:43:17.346-<wbr class="">0400: 40602.440: [JNI Weak Reference, \
0.0000730 secs] (to-space exhausted), 6.1987667 secs]<br class=""> \
[Parallel Time: 5446.3 ms, GC Workers: 8]<br class=""> [GC \
Worker Start (ms): Min: 40596975.6, Avg: 40596975.7, Max: 40596975.8, Diff: 0.2]<br \
class=""> [Ext Root Scanning (ms): Min: 2.9, Avg: 3.1, Max: 3.2, \
Diff: 0.3, Sum: 24.4]<br class=""> [Update RS (ms): Min: 10.1, \
Avg: 10.3, Max: 10.5, Diff: 0.4, Sum: 82.6]<br class=""> \
[Processed Buffers: Min: 33, Avg: 40.2, Max: 51, Diff: 18, Sum: 322]<br \
class=""> [Scan RS (ms): Min: 30.7, Avg: 31.1, Max: 32.4, Diff: \
1.8, Sum: 249.0]<br class=""> [Code Root Scanning (ms): Min: \
0.1, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 2.8]<br class=""> \
[Object Copy (ms): Min: 5399.2, Avg: 5400.6, Max: 5400.9, Diff: 1.7, Sum: 43204.5]<br \
class=""> [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: \
0.3, Sum: 1.3]<br class=""> [Termination Attempts: \
Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> [GC \
Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br class=""> \
[GC Worker Total (ms): Min: 5445.5, Avg: 5445.6, Max: 5445.7, \
Diff: 0.2, Sum: 43565.0]<br class=""> [GC Worker End (ms): Min: \
40602421.3, Avg: 40602421.4, Max: 40602421.4, Diff: 0.1]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 0.8 ms]<br class="">
[Other: 751.4 ms]<br class="">
[Evacuation Failure: 728.5 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 17.8 ms]<br class="">
[Ref Enq: 0.5 ms]<br class="">
[Redirty Cards: 2.1 ms]<br class="">
[Humongous Register: 0.1 ms]<br class="">
[Humongous Reclaim: 0.2 ms]<br class="">
[Free CSet: 0.8 ms]<br class="">
[Eden: 878.0M(976.0M)->0.0B(1424.0M) Survivors: 456.0M->8192.0K \
Heap: 6856.2M(7168.0M)->6908.2M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=11.66 sys=1.15, real=6.19 secs]<br class=""> 2017-05-23T20:43:18.080-0400: \
40603.173: [GC concurrent-root-region-scan-<wbr class="">start]<br class=""> \
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 \
class=""> 2017-05-23T20:43:18.080-0400: 40603.174: Application time: 0.0002882 \
seconds<br class=""> 2017-05-23T20:43:18.114-0400: 40603.207: [GC \
concurrent-root-region-scan-<wbr class="">end, 0.0339339 secs]<br class=""> \
2017-05-23T20:43:18.114-0400: 40603.207: [GC concurrent-mark-start]<br class=""> \
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 \
class=""> 2017-05-23T20:43:18.142-0400: 40603.236: Application time: 0.0005017 \
seconds<br class=""> 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 class=""> 2017-05-23T20:43:18.144-0400: 40603.237: Application time: \
0.0001781 seconds<br class=""> 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 class=""> 2017-05-23T20:43:18.728-0400: 40603.821: Application \
time: 0.5835349 seconds<br class=""> 2017-05-23T20:43:18.730-0400: 40603.823: [GC \
pause (G1 Evacuation Pause) (young)<br class=""> Desired survivor size 94371840 \
bytes, new threshold 15 (max 15)<br class="">
- age 1: 8388248 bytes, 8388248 total<br \
class=""> 2017-05-23T20:43:19.821-0400: 40604.914: [SoftReference, 0 refs, 0.0009673 \
secs]2017-05-23T20:43:19.822-<wbr class="">0400: 40604.915: [WeakReference, 0 refs, \
0.0006733 secs]2017-05-23T20:43:19.823-<wbr class="">0400: 40604.916: \
[FinalReference, 0 refs, 0.0006260 secs]2017-05-23T20:43:19.823-<wbr class="">0400: \
40604.917: [PhantomReference, 0 refs, 0 refs, 0.0013002 \
secs]2017-05-23T20:43:19.825-<wbr class="">0400: 40604.918: [JNI Weak Reference, \
0.0000642 secs] (to-space exhausted), 1.2567408 secs]<br class=""> \
[Parallel Time: 1084.5 ms, GC Workers: 8]<br class=""> [GC \
Worker Start (ms): Min: 40603823.4, Avg: 40603823.5, Max: 40603823.6, Diff: 0.2]<br \
class=""> [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, \
Diff: 0.7, Sum: 15.3]<br class=""> [Update RS (ms): Min: 23.8, \
Avg: 24.0, Max: 24.2, Diff: 0.3, Sum: 191.7]<br class=""> \
[Processed Buffers: Min: 49, Avg: 53.5, Max: 60, Diff: 11, Sum: 428]<br \
class=""> [Scan RS (ms): Min: 1.0, Avg: 1.1, Max: 1.2, Diff: \
0.2, Sum: 8.6]<br class=""> [Code Root Scanning (ms): Min: 0.1, \
Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]<br class=""> [Object \
Copy (ms): Min: 1056.4, Avg: 1056.8, Max: 1057.2, Diff: 0.8, Sum: 8454.7]<br \
class=""> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: \
0.2, Sum: 1.0]<br class=""> [Termination Attempts: \
Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 30]<br class=""> [GC \
Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]<br class=""> \
[GC Worker Total (ms): Min: 1084.0, Avg: 1084.1, Max: 1084.2, \
Diff: 0.2, Sum: 8673.2]<br class=""> [GC Worker End (ms): Min: \
40604907.6, Avg: 40604907.7, Max: 40604907.7, Diff: 0.0]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 0.3 ms]<br class="">
[Other: 171.7 ms]<br class="">
[Evacuation Failure: 159.4 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 9.9 ms]<br class="">
[Ref Enq: 0.6 ms]<br class="">
[Redirty Cards: 0.6 ms]<br class="">
[Humongous Register: 0.2 ms]<br class="">
[Humongous Reclaim: 0.3 ms]<br class="">
[Free CSet: 0.2 ms]<br class="">
[Eden: 230.0M(1424.0M)->0.0B(1432.0M) Survivors: 8192.0K->0.0B \
Heap: 7139.5M(7168.0M)->7139.5M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=2.33 sys=0.34, real=1.26 secs]<br class=""> 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 class=""> 2017-05-23T20:43:19.987-0400: \
40605.080: Application time: 0.0003101 seconds<br class=""> \
2017-05-23T20:43:19.988-0400: 40605.082: [GC pause (G1 Evacuation Pause) (young)<br \
class=""> Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br \
class=""> 2017-05-23T20:43:20.020-0400: 40605.113: [SoftReference, 0 refs, 0.0008856 \
secs]2017-05-23T20:43:20.020-<wbr class="">0400: 40605.114: [WeakReference, 0 refs, \
0.0005588 secs]2017-05-23T20:43:20.021-<wbr class="">0400: 40605.114: \
[FinalReference, 0 refs, 0.0006006 secs]2017-05-23T20:43:20.022-<wbr class="">0400: \
40605.115: [PhantomReference, 0 refs, 0 refs, 0.0010837 \
secs]2017-05-23T20:43:20.023-<wbr class="">0400: 40605.116: [JNI Weak Reference, \
0.0000610 secs], 0.0356212 secs]<br class=""> [Parallel Time: 30.0 ms, \
GC Workers: 8]<br class=""> [GC Worker Start (ms): Min: \
40605081.9, Avg: 40605082.0, Max: 40605082.1, Diff: 0.2]<br class=""> \
[Ext Root Scanning (ms): Min: 1.9, Avg: 2.0, Max: 2.5, Diff: 0.6, Sum: \
16.1]<br class=""> [Update RS (ms): Min: 27.3, Avg: 27.4, Max: \
27.5, Diff: 0.2, Sum: 219.3]<br class=""> \
[Processed Buffers: Min: 82, Avg: 87.4, Max: 92, Diff: 10, Sum: 699]<br \
class=""> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: \
0.0, Sum: 0.0]<br class=""> [Code Root Scanning (ms): Min: 0.0, \
Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> [Object \
Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.4]<br class=""> \
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: \
1.1]<br class=""> [Termination Attempts: Min: 1, \
Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> [GC Worker Other \
(ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]<br class=""> \
[GC Worker Total (ms): Min: 29.7, Avg: 29.8, Max: 29.9, Diff: 0.2, Sum: \
238.5]<br class=""> [GC Worker End (ms): Min: 40605111.8, Avg: \
40605111.8, Max: 40605111.8, Diff: 0.0]<br class=""> [Code Root Fixup: \
0.3 ms]<br class=""> [Code Root Purge: 0.0 ms]<br class="">
[Clear CT: 0.2 ms]<br class="">
[Other: 5.1 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 4.0 ms]<br class="">
[Ref Enq: 0.2 ms]<br class="">
[Redirty Cards: 0.2 ms]<br class="">
[Humongous Register: 0.1 ms]<br class="">
[Humongous Reclaim: 0.2 ms]<br class="">
[Free CSet: 0.1 ms]<br class="">
[Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: \
7139.5M(7168.0M)->7139.5M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=0.25 sys=0.00, real=0.04 secs]<br class=""> 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 class=""> 2017-05-23T20:43:20.025-0400: \
40605.118: Application time: 0.0002435 seconds<br class=""> \
2017-05-23T20:43:20.026-0400: 40605.119: [GC pause (G1 Evacuation Pause) (young)<br \
class=""> Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br \
class=""> 2017-05-23T20:43:20.030-0400: 40605.123: [SoftReference, 0 refs, 0.0009405 \
secs]2017-05-23T20:43:20.031-<wbr class="">0400: 40605.124: [WeakReference, 0 refs, \
0.0005771 secs]2017-05-23T20:43:20.032-<wbr class="">0400: 40605.125: \
[FinalReference, 0 refs, 0.0005766 secs]2017-05-23T20:43:20.032-<wbr class="">0400: \
40605.125: [PhantomReference, 0 refs, 0 refs, 0.0011847 \
secs]2017-05-23T20:43:20.033-<wbr class="">0400: 40605.127: [JNI Weak Reference, \
0.0000549 secs], 0.0087717 secs]<br class=""> [Parallel Time: 3.0 ms, GC \
Workers: 8]<br class=""> [GC Worker Start (ms): Min: 40605119.3, \
Avg: 40605119.4, Max: 40605119.5, Diff: 0.2]<br class=""> [Ext \
Root Scanning (ms): Min: 1.6, Avg: 1.8, Max: 2.6, Diff: 1.0, Sum: 14.8]<br class=""> \
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: \
0.2]<br class=""> [Processed Buffers: Min: 0, Avg: \
0.5, Max: 2, Diff: 2, Sum: 4]<br class=""> [Scan RS (ms): Min: \
0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]<br class=""> [Code \
Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> \
[Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: \
1.1]<br class=""> [Termination (ms): Min: 0.0, Avg: 0.6, Max: \
0.6, Diff: 0.6, Sum: 4.4]<br class=""> [Termination \
Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> \
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br \
class=""> [GC Worker Total (ms): Min: 2.6, Avg: 2.6, Max: 2.7, \
Diff: 0.1, Sum: 21.1]<br class=""> [GC Worker End (ms): Min: \
40605122.0, Avg: 40605122.1, Max: 40605122.1, Diff: 0.1]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 0.3 ms]<br class="">
[Other: 5.2 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 4.1 ms]<br class="">
[Ref Enq: 0.3 ms]<br class="">
[Redirty Cards: 0.3 ms]<br class="">
[Humongous Register: 0.1 ms]<br class="">
[Humongous Reclaim: 0.1 ms]<br class="">
[Free CSet: 0.1 ms]<br class="">
[Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: \
7139.5M(7168.0M)->7139.5M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=0.03 sys=0.00, real=0.01 secs]<br class=""> 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 class=""> 2017-05-23T20:43:20.035-0400: \
40605.128: Application time: 0.0002150 seconds<br class=""> \
2017-05-23T20:43:20.036-0400: 40605.129: [GC pause (G1 Evacuation Pause) (young)<br \
class=""> Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br \
class=""> 2017-05-23T20:43:20.040-0400: 40605.133: [SoftReference, 0 refs, 0.0010156 \
secs]2017-05-23T20:43:20.041-<wbr class="">0400: 40605.134: [WeakReference, 0 refs, \
0.0006580 secs]2017-05-23T20:43:20.042-<wbr class="">0400: 40605.135: \
[FinalReference, 0 refs, 0.0006435 secs]2017-05-23T20:43:20.042-<wbr class="">0400: \
40605.136: [PhantomReference, 0 refs, 0 refs, 0.0012604 \
secs]2017-05-23T20:43:20.044-<wbr class="">0400: 40605.137: [JNI Weak Reference, \
0.0000513 secs], 0.0087896 secs]<br class=""> [Parallel Time: 2.7 ms, GC \
Workers: 8]<br class=""> [GC Worker Start (ms): Min: 40605129.6, \
Avg: 40605129.7, Max: 40605129.8, Diff: 0.2]<br class=""> [Ext \
Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.5, Diff: 0.8, Sum: 14.9]<br class=""> \
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: \
0.2]<br class=""> [Processed Buffers: Min: 0, Avg: \
0.6, Max: 1, Diff: 1, Sum: 5]<br class=""> [Scan RS (ms): Min: \
0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> [Code \
Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> \
[Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: \
1.3]<br class=""> [Termination (ms): Min: 0.0, Avg: 0.3, Max: \
0.4, Diff: 0.4, Sum: 2.5]<br class=""> [Termination \
Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> \
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br \
class=""> [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, \
Diff: 0.2, Sum: 19.5]<br class=""> [GC Worker End (ms): Min: \
40605132.1, Avg: 40605132.2, Max: 40605132.2, Diff: 0.0]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 0.3 ms]<br class="">
[Other: 5.5 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 4.4 ms]<br class="">
[Ref Enq: 0.3 ms]<br class="">
[Redirty Cards: 0.3 ms]<br class="">
[Humongous Register: 0.1 ms]<br class="">
[Humongous Reclaim: 0.1 ms]<br class="">
[Free CSet: 0.1 ms]<br class="">
[Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: \
7139.5M(7168.0M)->7139.5M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=0.04 sys=0.00, real=0.01 secs]<br class=""> 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 class=""> 2017-05-23T20:43:20.045-0400: \
40605.139: Application time: 0.0001681 seconds<br class=""> \
2017-05-23T20:43:20.046-0400: 40605.140: [GC pause (G1 Evacuation Pause) (young)<br \
class=""> Desired survivor size 94371840 bytes, new threshold 15 (max 15)<br \
class=""> 2017-05-23T20:43:20.050-0400: 40605.144: [SoftReference, 0 refs, 0.0008321 \
secs]2017-05-23T20:43:20.051-<wbr class="">0400: 40605.145: [WeakReference, 0 refs, \
0.0006103 secs]2017-05-23T20:43:20.052-<wbr class="">0400: 40605.145: \
[FinalReference, 0 refs, 0.0007194 secs]2017-05-23T20:43:20.053-<wbr class="">0400: \
40605.146: [PhantomReference, 0 refs, 0 refs, 0.0010705 \
secs]2017-05-23T20:43:20.054-<wbr class="">0400: 40605.147: [JNI Weak Reference, \
0.0000508 secs], 0.0084107 secs]<br class=""> [Parallel Time: 2.7 ms, GC \
Workers: 8]<br class=""> [GC Worker Start (ms): Min: 40605139.9, \
Avg: 40605140.0, Max: 40605140.1, Diff: 0.2]<br class=""> [Ext \
Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.8, Sum: 15.1]<br class=""> \
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: \
0.1]<br class=""> [Processed Buffers: Min: 0, Avg: \
0.4, Max: 1, Diff: 1, Sum: 3]<br class=""> [Scan RS (ms): Min: \
0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> [Code \
Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br class=""> \
[Object Copy (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: \
1.1]<br class=""> [Termination (ms): Min: 0.0, Avg: 0.3, Max: \
0.4, Diff: 0.4, Sum: 2.2]<br class=""> [Termination \
Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]<br class=""> \
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]<br \
class=""> [GC Worker Total (ms): Min: 2.3, Avg: 2.4, Max: 2.5, \
Diff: 0.2, Sum: 19.2]<br class=""> [GC Worker End (ms): Min: \
40605142.4, Avg: 40605142.4, Max: 40605142.5, Diff: 0.1]<br class=""> \
[Code Root Fixup: 0.3 ms]<br class=""> [Code Root Purge: 0.0 \
ms]<br class=""> [Clear CT: 0.2 ms]<br class="">
[Other: 5.1 ms]<br class="">
[Choose CSet: 0.0 ms]<br class="">
[Ref Proc: 4.1 ms]<br class="">
[Ref Enq: 0.3 ms]<br class="">
[Redirty Cards: 0.2 ms]<br class="">
[Humongous Register: 0.1 ms]<br class="">
[Humongous Reclaim: 0.1 ms]<br class="">
[Free CSet: 0.1 ms]<br class="">
[Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: \
7139.5M(7168.0M)->7139.5M(<wbr class="">7168.0M)]<br class=""> [Times: \
user=0.03 sys=0.01, real=0.01 secs]<br class=""> 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 class=""> 2017-05-23T20:43:20.055-0400: \
40605.148: Application time: 0.0001505 seconds<br class=""> \
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-<wbr class="">0400: 40607.541: [WeakReference, 5626 \
refs, 0.0008068 secs]2017-05-23T20:43:22.448-<wbr class="">0400: 40607.541: \
[FinalReference, 4015 refs, 0.0015169 secs]2017-05-23T20:43:22.450-<wbr \
class="">0400: 40607.543: [PhantomReference, 1 refs, 372 refs, 0.0001585 \
secs]2017-05-23T20:43:22.450-<wbr class="">0400: 40607.543: [JNI Weak Reference, \
0.0000963 secs] 7139M->2327M(7168M), 9.7036499 secs]<br class=""> \
[Eden: 0.0B(1432.0M)->0.0B(1432.0M) Survivors: 0.0B->0.0B Heap: \
7139.5M(7168.0M)->2327.6M(<wbr class="">7168.0M)], [Metaspace: \
108907K->108428K(1150976K)]<br class=""> [Times: user=13.22 sys=0.00, \
real=9.70 secs]<br class=""> 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 class=""> 2017-05-23T20:43:29.760-0400: 40614.854: [GC \
concurrent-mark-abort]<br class=""> 2017-05-23T20:43:29.763-0400: 40614.856: \
Application time: 0.0029444 seconds<br class=""> > On Jul 21, 2017, at 5:34 PM, \
Thomas Schatzl <<a href="mailto:thomas.schatzl@oracle.com" \
class="">thomas.schatzl@oracle.com</a>> wrote:<br class=""> ><br class="">
> Hi Kirk,<br class="">
><br class="">
> On Fri, 2017-07-21 at 10:34 +0300, Kirk Pepperdine wrote:<br class="">
>> Hi all,<br class="">
>><br class="">
>> A while back I mentioned to Erik at JFokus that I was seeing a<br class="">
>> puzzling behavior in the G1 where without any obvious failure, heap<br \
class=""> >> occupancy after collections would spike which would trigger a \
full<br class=""> >> which would (unexpectedly) completely recover everything \
down to the<br class=""> >> expected live set. Yesterday while working with \
Simone Bordet on the<br class=""> >> problem we came to the realization that we \
were seeing a pattern<br class=""> >> prior to the ramp up to the Full, \
Survivor space would be<br class=""> >> ergonomically resized to 0 -> 0. The \
only way to reset the situation<br class=""> >> was to run a full collection. \
In our minds this doesn't make any<br class=""> >> sense to reset survivor \
space to 0. So far this is an observation<br class=""> >> from a single GC log \
but I recall seeing the pattern in many other<br class=""> >> logs. Before I go \
through the exercise of building a super grep to<br class=""> >> run over my G1 \
log repo I'd like to ask; under what conditions would<br class=""> >> it make \
sense to have the survivor space resized to 0? And if not,<br class=""> \
>> would this be bug in G1? We tried reproducing the behavior in some<br \
class=""> >> test applications but I fear we often only see this happening \
in<br class=""> >> production applications that have been running for several \
days. It's<br class=""> >> a behavior that I've seen in 1.7.0 and 1.8.0. No \
word on 9.<br class=""> ><br class="">
> sounds similar to <a \
href="https://bugs.openjdk.java.net/browse/JDK-8037500" rel="noreferrer" \
target="_blank" class="">https://bugs.openjdk.java.net/<wbr \
class="">browse/JDK-8037500</a>.<br class=""> > Could you please post the type of \
collections for a few more gcs before<br class=""> > the zero-sized ones? It would \
be particularly interesting if there is a<br class=""> > mixed gc with to-space \
exhaustion just before this sequence. And if<br class=""> > there are log messages \
with attempts to start marking too.<br class=""> ><br class="">
> As for why that bug has been closed as "won't fix" because we do not<br \
class=""> > have a reproducer (any more) to test any changes in addition to the<br \
class=""> > stated reasons that the performance impact seemed minor at that \
time.<br class=""> ><br class="">
> There have been some changes in how the next gc is calculated in 9 too,<br \
class=""> > so I do not know either if 9 is also affected (particularly one of<br \
class=""> > these young-only gc's would not be issued any more).<br class="">
><br class="">
> I can think of at least one more reasons other than stated in the CR<br \
class=""> > why this occurs at least for 8u60+ builds. There is the possibility<br \
class=""> > particularly in conjunction with humongous object allocation that \
after<br class=""> > starting the mutator, immediately afterwards a young gc that \
reclaims<br class=""> > zero space is issued, e.g.:<br class="">
><br class="">
> young-gc, has X regions left at the end, starts mutators<br class="">
> mutator 1 allocates exactly X regions as humongous objects<br class="">
> mutator 2 allocates, finds that there are no regions left, issues<br class="">
> young-gc request; in this young-gc eden and survivor are of obviously<br \
class=""> > of zero size<br class="">
> [...and so on...]<br class="">
><br class="">
> Note that this pattern could repeat multiple times as young gc may<br class="">
> reclaim space from humongous objects (eager reclaim!) until at some<br class="">
> point it ran into full gc.<br class="">
><br class="">
> The logging that shows humongous object allocation (something about<br class="">
> reaching threshold and starting marking) could confirm this situation.<br \
class=""> ><br class="">
> No guarantees about that being the actual issue though.<br class="">
><br class="">
> Thanks,<br class="">
> Thomas<br class="">
><br class="">
<br class="">
</blockquote></div></div>
</div></blockquote></div><br class=""></div></body></html>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic