You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by forest_soup <ta...@gmail.com> on 2016/12/08 07:45:45 UTC
Very long young generation stop the world GC pause
Hi Shawn,
Thanks a lot for your response!
I'll use this mail thread on tracking the issue in JIRA
https://issues.apache.org/jira/browse/SOLR-9828 .
--
View this message in context: http://lucene.472066.n3.nabble.com/Very-long-young-generation-stop-the-world-GC-pause-tp4308911.html
Sent from the Solr - User mailing list archive at Nabble.com.
Re: Very long young generation stop the world GC pause
Posted by Shawn Heisey <ap...@elyograg.org>.
On 12/8/2016 1:06 AM, forest_soup 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?
While full GC is *typically* where long pauses happen, it can happen
with *any* collection.
The startup script in Solr 5.0 and later comes with GC tuning, so you
probably should not be messing with it at all. If you feel that you
must change the GC tuning to G1GC, perhaps you should try these settings
from my personal wiki page:
https://wiki.apache.org/solr/ShawnHeisey#Current_experiments
Also, I would strongly recommend that you drop your max heap to 31GB
instead of 32GB to change the pointer size, and that you investigate
whether you need a heap that large *at all*. The numbers I saw in your
log on the Jira issue did not indicate the need for that much heap
memory. After the long collection, your heap usage was only 3450MB. In
addition to reducing your heap size to a level that's more appropriate
to your Solr's needs, I would suggest that you try the GC tuning that
Solr has out of the box, which uses CMS.
Thanks,
Shawn
Re: Very long young generation stop the world GC pause
Posted by Greg Harris <ha...@gmail.com>.
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 <ta...@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.
>
Re: Very long young generation stop the world GC pause
Posted by Pushkar Raste <pu...@gmail.com>.
My guess is system time is high either due to lock contention (too many
parallel threads) or page faults.
Heap size was less than 6gb when this long pause occurred, and and young
generation was less than 2gb. Though lowering heap size would help I don't
think that is the root cause here
On Dec 9, 2016 3:02 AM, "Ere Maijala" <er...@helsinki.fi> wrote:
> Then again, if the load characteristics on the Solr instance differ e.g.
> by time of day, G1GC, in my experience, may have trouble adapting. For
> instance if your query load reduces drastically during the night, it may
> take a while for G1GC to catch up in the morning. What I've found useful
> from experience, and your mileage will probably vary, is to limit the young
> generation size with a large heap. With Xmx31G something like these could
> work:
>
> -XX:+UnlockExperimentalVMOptions \
> -XX:G1MaxNewSizePercent=5 \
>
> The aim here is to only limit the maximum and still allow some adaptation.
>
> --Ere
>
> 8.12.2016, 16.07, Pushkar Raste kirjoitti:
>
>> Disable all the G1GC tuning your are doing except for
>> ParallelRefProcEnabled
>>
>> G1GC is an adaptive algorithm and would keep tuning to reach the default
>> pause goal of 250ms which should be good for most of the applications.
>>
>> Can you also tell us how much RAM you have on your machine and if you have
>> swap enabled and being used?
>>
>> On Dec 8, 2016 8:53 AM, "forest_soup" <ta...@gmail.com> wrote:
>>
>> Besides, will those JVM options make it better?
>>> -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=10
>>>
>>>
>>>
>>> --
>>> View this message in context: http://lucene.472066.n3.
>>> nabble.com/Very-long-young-generation-stop-the-world-GC-
>>> pause-tp4308911p4308937.html
>>> Sent from the Solr - User mailing list archive at Nabble.com.
>>>
>>>
>>
Re: Very long young generation stop the world GC pause
Posted by Ere Maijala <er...@helsinki.fi>.
Then again, if the load characteristics on the Solr instance differ e.g.
by time of day, G1GC, in my experience, may have trouble adapting. For
instance if your query load reduces drastically during the night, it may
take a while for G1GC to catch up in the morning. What I've found useful
from experience, and your mileage will probably vary, is to limit the
young generation size with a large heap. With Xmx31G something like
these could work:
-XX:+UnlockExperimentalVMOptions \
-XX:G1MaxNewSizePercent=5 \
The aim here is to only limit the maximum and still allow some adaptation.
--Ere
8.12.2016, 16.07, Pushkar Raste kirjoitti:
> Disable all the G1GC tuning your are doing except for ParallelRefProcEnabled
>
> G1GC is an adaptive algorithm and would keep tuning to reach the default
> pause goal of 250ms which should be good for most of the applications.
>
> Can you also tell us how much RAM you have on your machine and if you have
> swap enabled and being used?
>
> On Dec 8, 2016 8:53 AM, "forest_soup" <ta...@gmail.com> wrote:
>
>> Besides, will those JVM options make it better?
>> -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=10
>>
>>
>>
>> --
>> View this message in context: http://lucene.472066.n3.
>> nabble.com/Very-long-young-generation-stop-the-world-GC-
>> pause-tp4308911p4308937.html
>> Sent from the Solr - User mailing list archive at Nabble.com.
>>
>
Re: Very long young generation stop the world GC pause
Posted by Steven Bower <sb...@alcyon.net>.
Also curious why such a large heap is required... If it's due to field
caches being loaded I'd highly recommend MMapDirectory (if not using
already) and turning on DocValues for all fields you plan to perform
sort/facet/analytics on.
steve
On Wed, Dec 21, 2016 at 9:25 AM Pushkar Raste <pu...@gmail.com>
wrote:
> You should probably have as small a swap as possible. I still feel long GCs
> are either due to swapping or thread contention.
>
> Did you try to remove all other G1GC tuning parameters except for the
> ParallelRefProcEnabled?
>
> On Dec 19, 2016 1:39 AM, "forest_soup" <ta...@gmail.com> wrote:
>
> > Sorry for my wrong memory. The swap is 16GB.
> >
> >
> >
> > --
> > View this message in context: http://lucene.472066.n3.
> > nabble.com/Very-long-young-generation-stop-the-world-GC-
> > pause-tp4308911p4310301.html
> > Sent from the Solr - User mailing list archive at Nabble.com.
> >
>
Re: Very long young generation stop the world GC pause
Posted by Pushkar Raste <pu...@gmail.com>.
You should probably have as small a swap as possible. I still feel long GCs
are either due to swapping or thread contention.
Did you try to remove all other G1GC tuning parameters except for the
ParallelRefProcEnabled?
On Dec 19, 2016 1:39 AM, "forest_soup" <ta...@gmail.com> wrote:
> Sorry for my wrong memory. The swap is 16GB.
>
>
>
> --
> View this message in context: http://lucene.472066.n3.
> nabble.com/Very-long-young-generation-stop-the-world-GC-
> pause-tp4308911p4310301.html
> Sent from the Solr - User mailing list archive at Nabble.com.
>
Re: Very long young generation stop the world GC pause
Posted by forest_soup <ta...@gmail.com>.
Sorry for my wrong memory. The swap is 16GB.
--
View this message in context: http://lucene.472066.n3.nabble.com/Very-long-young-generation-stop-the-world-GC-pause-tp4308911p4310301.html
Sent from the Solr - User mailing list archive at Nabble.com.
Re: Very long young generation stop the world GC pause
Posted by forest_soup <ta...@gmail.com>.
Thanks a lot, PushKar! And sorry for late response.
Our OS ram is 128GB. And we have 2 solr nodes on one machine. Each solr node
has max heap size 32GB.
And we do not have swap.
--
View this message in context: http://lucene.472066.n3.nabble.com/Very-long-young-generation-stop-the-world-GC-pause-tp4308911p4310291.html
Sent from the Solr - User mailing list archive at Nabble.com.
Re: Very long young generation stop the world GC pause
Posted by Pushkar Raste <pu...@gmail.com>.
Disable all the G1GC tuning your are doing except for ParallelRefProcEnabled
G1GC is an adaptive algorithm and would keep tuning to reach the default
pause goal of 250ms which should be good for most of the applications.
Can you also tell us how much RAM you have on your machine and if you have
swap enabled and being used?
On Dec 8, 2016 8:53 AM, "forest_soup" <ta...@gmail.com> wrote:
> Besides, will those JVM options make it better?
> -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=10
>
>
>
> --
> View this message in context: http://lucene.472066.n3.
> nabble.com/Very-long-young-generation-stop-the-world-GC-
> pause-tp4308911p4308937.html
> Sent from the Solr - User mailing list archive at Nabble.com.
>
Re: Very long young generation stop the world GC pause
Posted by forest_soup <ta...@gmail.com>.
Besides, will those JVM options make it better?
-XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=10
--
View this message in context: http://lucene.472066.n3.nabble.com/Very-long-young-generation-stop-the-world-GC-pause-tp4308911p4308937.html
Sent from the Solr - User mailing list archive at Nabble.com.
Re: Very long young generation stop the world GC pause
Posted by forest_soup <ta...@gmail.com>.
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.