Your gun (not quite smoking yet, we still need the fingerprints) is this:
[Times: user=0.00 sys=94.28, real=97.19 secs]
Normal GC pauses are generally almost entirely user CPU, very short and
multiprocessor. Something else is sometimes happening with either the JVM
or OS which is causing this process to be single threaded, blocked and
being executed by system CPU -- ie: lower level processing unrelated to a
normal GC of Solr. This is non normal GC behavior and probably not going to
be fixed by any JVM parameter changes (but you can always try). Any unusual
disk or network IO? You need to understand what else is going on with your
system at the same moment in time this happens. You might see if you can do
an strace to see what its trying to do.
On Thu, Dec 8, 2016 at 12:06 AM, forest_soup <tanglin0...@gmail.com> wrote:
> As you can see in the gc log, the long GC pause is not a full GC. It's a
> young generation GC instead.
> In our case, full gc is fast and young gc got some long stw pause.
> Do you have any comments on that, as we usually believe full gc may cause
> longer pause, but young generation should be ok?
>
> 2016-11-22T20:43:16.463+0000: 2942054.509: Total time for which application
> threads were stopped: 0.0029195 seconds, Stopping threads took: 0.0000804
> seconds
> {Heap before GC invocations=2246 (full 0):
> garbage-first heap total 26673152K, used 4683965K [0x00007f0c10000000,
> 0x00007f0c108065c0, 0x00007f1410000000)
> region size 8192K, 162 young (1327104K), 17 survivors (139264K)
> Metaspace used 56487K, capacity 57092K, committed 58368K, reserved
> 59392K
> 2016-11-22T20:43:16.555+0000: 2942054.602: [GC pause (G1 Evacuation Pause)
> (young)
> Desired survivor size 88080384 bytes, new threshold 15 (max 15)
> - age 1: 28176280 bytes, 28176280 total
> - age 2: 5632480 bytes, 33808760 total
> - age 3: 9719072 bytes, 43527832 total
> - age 4: 6219408 bytes, 49747240 total
> - age 5: 4465544 bytes, 54212784 total
> - age 6: 3417168 bytes, 57629952 total
> - age 7: 5343072 bytes, 62973024 total
> - age 8: 2784808 bytes, 65757832 total
> - age 9: 6538056 bytes, 72295888 total
> - age 10: 6368016 bytes, 78663904 total
> - age 11: 695216 bytes, 79359120 total
> , 97.2044320 secs]
> [Parallel Time: 19.8 ms, GC Workers: 18]
> [GC Worker Start (ms): Min: 2942054602.1, Avg: 2942054604.6, Max:
> 2942054612.7, Diff: 10.6]
> [Ext Root Scanning (ms): Min: 0.0, Avg: 2.4, Max: 6.7, Diff: 6.7,
> Sum:
> 43.5]
> [Update RS (ms): Min: 0.0, Avg: 3.0, Max: 15.9, Diff: 15.9, Sum:
> 54.0]
> [Processed Buffers: Min: 0, Avg: 10.7, Max: 39, Diff: 39, Sum:
> 192]
> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
> Sum: 0.0]
> [Object Copy (ms): Min: 0.1, Avg: 9.2, Max: 13.4, Diff: 13.3, Sum:
> 165.9]
> [Termination (ms): Min: 0.0, Avg: 2.5, Max: 2.7, Diff: 2.7, Sum:
> 44.1]
> [Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 27]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum:
> 0.6]
> [GC Worker Total (ms): Min: 9.0, Avg: 17.1, Max: 19.7, Diff: 10.6,
> Sum: 308.7]
> [GC Worker End (ms): Min: 2942054621.8, Avg: 2942054621.8, Max:
> 2942054621.8, Diff: 0.0]
> [Code Root Fixup: 0.1 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.2 ms]
> [Other: 97184.3 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 8.5 ms]
> [Ref Enq: 0.2 ms]
> [Redirty Cards: 0.2 ms]
> [Humongous Register: 0.1 ms]
> [Humongous Reclaim: 0.1 ms]
> [Free CSet: 0.4 ms]
> [Eden: 1160.0M(1160.0M)->0.0B(1200.0M) Survivors: 136.0M->168.0M Heap:
> 4574.2M(25.4G)->3450.8M(26.8G)]
> Heap after GC invocations=2247 (full 0):
> garbage-first heap total 28049408K, used 3533601K [0x00007f0c10000000,
> 0x00007f0c10806b00, 0x00007f1410000000)
> region size 8192K, 21 young (172032K), 21 survivors (172032K)
> Metaspace used 56487K, capacity 57092K, committed 58368K, reserved
> 59392K
> }
> [Times: user=0.00 sys=94.28, real=97.19 secs]
> 2016-11-22T20:44:53.760+0000: 2942151.806: Total time for which application
> threads were stopped: 97.2053747 seconds, Stopping threads took: 0.0001373
> seconds
>
>
>
> --
> View this message in context: http://lucene.472066.n3.
> nabble.com/Very-long-young-generation-stop-the-world-GC-
> pause-tp4308911p4308912.html
> Sent from the Solr - User mailing list archive at Nabble.com.
>
