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 Joe Obernberger <jo...@gmail.com> on 2019/02/12 14:35:50 UTC
Solr 7.7.0 - Garbage Collection issue
Yesterday, we upgraded our 40 node cluster from solr 7.6.0 to solr
7.7.0. This morning, all the nodes are using 1200+% of CPU. It looks
like it's in garbage collection. We did reduce our HDFS cache size from
11G to 6G, but other than that, no other parameters were changes.
Top shows:
top - 09:33:40 up 14 days, 23:22, 1 user, load average: 21.08, 20.97,
20.69
Tasks: 617 total, 1 running, 616 sleeping, 0 stopped, 0 zombie
Cpu(s): 60.9%us, 0.6%sy, 12.9%ni, 25.0%id, 0.6%wa, 0.0%hi, 0.1%si,
0.0%st
Mem: 99015716k total, 98627164k used, 388552k free, 187892k buffers
Swap: 33554428k total, 152900k used, 33401528k free, 17086000k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
39586 solr 20 0 42.0g 25g 13m S 1275.4 27.0 12935:57 java
Earlier yesterday when we first fired it up, it was taking int he 4
second range, now it's in the 60 second range:
[Times: user=0.86 sys=0.02, real=0.06 secs]
2019-02-12T09:16:20.740-0500: 62300.935: Total time for which
application threads were stopped: 0.0638071 seconds, Stopping threads
took: 0.0003274 seconds
2019-02-12T09:16:21.216-0500: 62301.411: Total time for which
application threads were stopped: 0.0011279 seconds, Stopping threads
took: 0.0003174 seconds
2019-02-12T09:16:21.805-0500: 62301.999: Total time for which
application threads were stopped: 0.0010905 seconds, Stopping threads
took: 0.0003168 seconds
2019-02-12T09:16:22.175-0500: 62302.369: Total time for which
application threads were stopped: 0.0011335 seconds, Stopping threads
took: 0.0002635 seconds
2019-02-12T09:16:25.249-0500: 62305.444: Total time for which
application threads were stopped: 0.0014435 seconds, Stopping threads
took: 0.0004507 seconds
2019-02-12T09:16:26.254-0500: 62306.449: Total time for which
application threads were stopped: 0.0011393 seconds, Stopping threads
took: 0.0003034 seconds
2019-02-12T09:16:26.434-0500: 62306.629: Total time for which
application threads were stopped: 0.0011275 seconds, Stopping threads
took: 0.0002968 seconds
2019-02-12T09:16:55.540-0500: 62335.735: Total time for which
application threads were stopped: 0.0012155 seconds, Stopping threads
took: 0.0003023 seconds
2019-02-12T09:16:55.542-0500: 62335.737: Total time for which
application threads were stopped: 0.0007474 seconds, Stopping threads
took: 0.0002297 seconds
2019-02-12T09:16:55.543-0500: 62335.737: Total time for which
application threads were stopped: 0.0005585 seconds, Stopping threads
took: 0.0001380 seconds
2019-02-12T09:16:55.543-0500: 62335.738: Total time for which
application threads were stopped: 0.0006552 seconds, Stopping threads
took: 0.0001907 seconds
2019-02-12T09:17:00.553-0500: 62340.747: Total time for which
application threads were stopped: 0.0011875 seconds, Stopping threads
took: 0.0002851 seconds
2019-02-12T09:17:00.553-0500: 62340.748: Total time for which
application threads were stopped: 0.0004486 seconds, Stopping threads
took: 0.0000693 seconds
2019-02-12T09:17:00.554-0500: 62340.749: Total time for which
application threads were stopped: 0.0006729 seconds, Stopping threads
took: 0.0002604 seconds
2019-02-12T09:17:00.555-0500: 62340.749: Total time for which
application threads were stopped: 0.0006151 seconds, Stopping threads
took: 0.0002310 seconds
2019-02-12T09:17:00.556-0500: 62340.750: Total time for which
application threads were stopped: 0.0006812 seconds, Stopping threads
took: 0.0003049 seconds
2019-02-12T09:17:00.557-0500: 62340.752: Total time for which
application threads were stopped: 0.0015586 seconds, Stopping threads
took: 0.0002212 seconds
2019-02-12T09:17:09.901-0500: 62350.095: Total time for which
application threads were stopped: 0.0013066 seconds, Stopping threads
took: 0.0004304 seconds
2019-02-12T09:17:10.195-0500: 62350.390: Total time for which
application threads were stopped: 0.0011006 seconds, Stopping threads
took: 0.0002573 seconds
{Heap before GC invocations=791 (full 0):
garbage-first heap total 19922944K, used 17336353K
[0x0000000240000000, 0x0000000241002600, 0x00000007c0000000)
region size 16384K, 357 young (5849088K), 19 survivors (311296K)
Metaspace used 90791K, capacity 93476K, committed 93696K,
reserved 1132544K
class space used 10929K, capacity 11487K, committed 11520K,
reserved 1048576K
2019-02-12T09:17:10.288-0500: 62350.482: [GC pause (G1 Evacuation Pause)
(young)
Desired survivor size 377487360 bytes, new threshold 15 (max 15)
- age 1: 105613200 bytes, 105613200 total
- age 2: 57166352 bytes, 162779552 total
- age 3: 25396792 bytes, 188176344 total
- age 4: 17067152 bytes, 205243496 total
- age 5: 32136016 bytes, 237379512 total
- age 6: 9642888 bytes, 247022400 total
- age 7: 5979880 bytes, 253002280 total
- age 8: 7996344 bytes, 260998624 total
- age 9: 3940072 bytes, 264938696 total
- age 10: 9720808 bytes, 274659504 total
- age 11: 8797424 bytes, 283456928 total
- age 12: 2599280 bytes, 286056208 total
- age 13: 9197304 bytes, 295253512 total
- age 14: 2616704 bytes, 297870216 total
- age 15: 8565352 bytes, 306435568 total
, 0.0540664 secs]
[Parallel Time: 47.3 ms, GC Workers: 16]
[GC Worker Start (ms): Min: 62350482.7, Avg: 62350482.8, Max:
62350483.0, Diff: 0.3]
[Ext Root Scanning (ms): Min: 0.6, Avg: 0.9, Max: 2.6, Diff: 2.0,
Sum: 14.7]
[Update RS (ms): Min: 1.3, Avg: 2.8, Max: 3.1, Diff: 1.8, Sum: 44.2]
[Processed Buffers: Min: 2, Avg: 9.8, Max: 26, Diff: 24, Sum: 157]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:
0.0, Sum: 0.0]
[Object Copy (ms): Min: 42.9, Avg: 43.0, Max: 43.1, Diff: 0.2,
Sum: 688.3]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 17]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1,
Sum: 1.2]
[GC Worker Total (ms): Min: 46.6, Avg: 46.9, Max: 47.0, Diff:
0.4, Sum: 749.6]
[GC Worker End (ms): Min: 62350529.6, Avg: 62350529.7, Max:
62350529.8, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 6.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 3.8 ms]
[Ref Enq: 0.4 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 0.7 ms]
[Eden: 5408.0M(5408.0M)->0.0B(5376.0M) Survivors: 304.0M->320.0M
Heap: 16.5G(19.0G)->11.3G(19.0G)]
Heap after GC invocations=792 (full 0):
garbage-first heap total 19922944K, used 11821182K
[0x0000000240000000, 0x0000000241002600, 0x00000007c0000000)
region size 16384K, 20 young (327680K), 20 survivors (327680K)
Metaspace used 90791K, capacity 93476K, committed 93696K,
reserved 1132544K
class space used 10929K, capacity 11487K, committed 11520K,
reserved 1048576K
}
[Times: user=0.77 sys=0.01, real=0.06 secs]
Parameters are:
GC_TUNE="-XX:+UseG1GC \
-XX:MaxDirectMemorySize=6g \
-XX:+PerfDisableSharedMem \
-XX:+ParallelRefProcEnabled \
-XX:G1HeapRegionSize=16m \
-XX:MaxGCPauseMillis=300 \
-XX:InitiatingHeapOccupancyPercent=75 \
-XX:+UseLargePages \
-XX:ParallelGCThreads=16 \
-XX:-ResizePLAB \
-XX:+AggressiveOpts"
Anything I can try / change?
Thank you!
-Joe
Re: Solr 7.7.0 - Garbage Collection issue
Posted by Joe Obernberger <jo...@gmail.com>.
Reverted back to 7.6.0 - same settings, but now I do not encounter the
large CPU usage.
-Joe
On 2/12/2019 12:37 PM, Joe Obernberger wrote:
> Thank you Shawn. Yes, I used the settings off of your site. I've
> restarted the cluster and the CPU usage is back up again. Looking at
> it now, it doesn't appear to be GC related.
> Full log from one of the nodes that is pegging 13 CPU cores:
>
> http://lovehorsepower.com/solr_gc.log.0.current
>
> Thank you For the gceasy.io site - that is very slick! I'll use that
> in the future. I can try using the standard settings, but again - at
> this point it doesn't look GC related to me?
>
> -Joe
>
> On 2/12/2019 11:35 AM, Shawn Heisey wrote:
>> On 2/12/2019 7:35 AM, Joe Obernberger wrote:
>>> Yesterday, we upgraded our 40 node cluster from solr 7.6.0 to solr
>>> 7.7.0. This morning, all the nodes are using 1200+% of CPU. It
>>> looks like it's in garbage collection. We did reduce our HDFS cache
>>> size from 11G to 6G, but other than that, no other parameters were
>>> changes.
>>
>> Your message included a small excerpt from the GC log. That is not
>> helpful. We will need the entire GC log, possibly more than one log.
>> The log or logs should fully cover the timeframe where the problem
>> occurs. Full disclosure: Once obtained, I would use this website to
>> analyze GC log data:
>>
>> http://gceasy.io
>>
>>> Parameters are:
>>>
>>> GC_TUNE="-XX:+UseG1GC \
>>> -XX:MaxDirectMemorySize=6g \
>>> -XX:+PerfDisableSharedMem \
>>> -XX:+ParallelRefProcEnabled \
>>> -XX:G1HeapRegionSize=16m \
>>> -XX:MaxGCPauseMillis=300 \
>>> -XX:InitiatingHeapOccupancyPercent=75 \
>>> -XX:+UseLargePages \
>>> -XX:ParallelGCThreads=16 \
>>> -XX:-ResizePLAB \
>>> -XX:+AggressiveOpts"
>>
>> Looks like you've chosen to use G1 settings very similar to what I
>> put on my wiki page:
>>
>> https://wiki.apache.org/solr/ShawnHeisey#Current_experiments
>>
>> Those settings are not intended to be a canonical resource that
>> everyone can use. Your heap size is different than what I was using
>> when I worked on that, so you may need different settings.
>>
>> Have you considered not using your own GC tuning, letting Solr's
>> start script handle that?
>>
>> With the limited information available, my initial guess is that you
>> need a larger heap, that Java is spending all its time freeing up
>> enough memory to keep the program running.
>>
>> Thanks,
>> Shawn
>>
>> ---
>> This email has been checked for viruses by AVG.
>> https://www.avg.com
>>
Re: Solr 7.7.0 - Garbage Collection issue
Posted by Joe Obernberger <jo...@gmail.com>.
Thank you Shawn. Yes, I used the settings off of your site. I've
restarted the cluster and the CPU usage is back up again. Looking at it
now, it doesn't appear to be GC related.
Full log from one of the nodes that is pegging 13 CPU cores:
http://lovehorsepower.com/solr_gc.log.0.current
Thank you For the gceasy.io site - that is very slick! I'll use that in
the future. I can try using the standard settings, but again - at this
point it doesn't look GC related to me?
-Joe
On 2/12/2019 11:35 AM, Shawn Heisey wrote:
> On 2/12/2019 7:35 AM, Joe Obernberger wrote:
>> Yesterday, we upgraded our 40 node cluster from solr 7.6.0 to solr
>> 7.7.0. This morning, all the nodes are using 1200+% of CPU. It looks
>> like it's in garbage collection. We did reduce our HDFS cache size
>> from 11G to 6G, but other than that, no other parameters were changes.
>
> Your message included a small excerpt from the GC log. That is not
> helpful. We will need the entire GC log, possibly more than one log.
> The log or logs should fully cover the timeframe where the problem
> occurs. Full disclosure: Once obtained, I would use this website to
> analyze GC log data:
>
> http://gceasy.io
>
>> Parameters are:
>>
>> GC_TUNE="-XX:+UseG1GC \
>> -XX:MaxDirectMemorySize=6g \
>> -XX:+PerfDisableSharedMem \
>> -XX:+ParallelRefProcEnabled \
>> -XX:G1HeapRegionSize=16m \
>> -XX:MaxGCPauseMillis=300 \
>> -XX:InitiatingHeapOccupancyPercent=75 \
>> -XX:+UseLargePages \
>> -XX:ParallelGCThreads=16 \
>> -XX:-ResizePLAB \
>> -XX:+AggressiveOpts"
>
> Looks like you've chosen to use G1 settings very similar to what I put
> on my wiki page:
>
> https://wiki.apache.org/solr/ShawnHeisey#Current_experiments
>
> Those settings are not intended to be a canonical resource that
> everyone can use. Your heap size is different than what I was using
> when I worked on that, so you may need different settings.
>
> Have you considered not using your own GC tuning, letting Solr's start
> script handle that?
>
> With the limited information available, my initial guess is that you
> need a larger heap, that Java is spending all its time freeing up
> enough memory to keep the program running.
>
> Thanks,
> Shawn
>
> ---
> This email has been checked for viruses by AVG.
> https://www.avg.com
>
Re: Solr 7.7.0 - Garbage Collection issue
Posted by Shawn Heisey <ap...@elyograg.org>.
On 2/12/2019 7:35 AM, Joe Obernberger wrote:
> Yesterday, we upgraded our 40 node cluster from solr 7.6.0 to solr
> 7.7.0. This morning, all the nodes are using 1200+% of CPU. It looks
> like it's in garbage collection. We did reduce our HDFS cache size from
> 11G to 6G, but other than that, no other parameters were changes.
Your message included a small excerpt from the GC log. That is not
helpful. We will need the entire GC log, possibly more than one log.
The log or logs should fully cover the timeframe where the problem
occurs. Full disclosure: Once obtained, I would use this website to
analyze GC log data:
http://gceasy.io
> Parameters are:
>
> GC_TUNE="-XX:+UseG1GC \
> -XX:MaxDirectMemorySize=6g \
> -XX:+PerfDisableSharedMem \
> -XX:+ParallelRefProcEnabled \
> -XX:G1HeapRegionSize=16m \
> -XX:MaxGCPauseMillis=300 \
> -XX:InitiatingHeapOccupancyPercent=75 \
> -XX:+UseLargePages \
> -XX:ParallelGCThreads=16 \
> -XX:-ResizePLAB \
> -XX:+AggressiveOpts"
Looks like you've chosen to use G1 settings very similar to what I put
on my wiki page:
https://wiki.apache.org/solr/ShawnHeisey#Current_experiments
Those settings are not intended to be a canonical resource that everyone
can use. Your heap size is different than what I was using when I
worked on that, so you may need different settings.
Have you considered not using your own GC tuning, letting Solr's start
script handle that?
With the limited information available, my initial guess is that you
need a larger heap, that Java is spending all its time freeing up enough
memory to keep the program running.
Thanks,
Shawn