Hi Erick,
Thanks for your response. It shows GC pauses in Solr GC logs (refer below solr
gc log where it shows 138.4138211 sec pause).
Seems like some bad query causes high memory allocation.
Further analyzing issue we found that asking for too many rows (e.g.
rows=10000000) can cause full GC problem as mentioned in below link. We had
some query which was asking for too many rows….so for now we have reduced
number rows. After changing this we don’t see any large GC Pause (Max GC pause
is 3-4 second). So seems like issue is resolved for now…But still please let me
know if you have any other suggestion which can help us to understand the root
cause…
https://wiki.apache.org/solr/SolrPerformanceProblems#GC_pause_problems
https://sbdevel.wordpress.com/2015/10/05/speeding-up-core-search/
Solr GC Log
==========
2018-01-04T12:13:40.346+0000: 140501.570:
[CMS-concurrent-abortable-preclean-start]
{Heap before GC invocations=8909 (full 1001):
par new generation total 10922688K, used 4187699K [0x0000000080000000,
0x00000003a0000000, 0x00000003a0000000)
eden space 8738176K, 41% used [0x0000000080000000, 0x000000015fb1f6d8,
0x0000000295560000)
from space 2184512K, 23% used [0x0000000295560000, 0x00000002b53cd8b8,
0x000000031aab0000)
to space 2184512K, 0% used [0x000000031aab0000, 0x000000031aab0000,
0x00000003a0000000)
concurrent mark-sweep generation total 39321600K, used 38082444K
[0x00000003a0000000, 0x0000000d00000000, 0x0000000d00000000)
Metaspace used 46676K, capacity 47372K, committed 50136K, reserved 51200K
2018-01-04T12:13:40.393+0000: 140501.618: [GC (Allocation Failure) 140501.618:
[CMS2018-01-04T12:13:40.534+0000: 140501.766:
[CMS-concurrent-abortable-preclean: 0.149/0.196 secs] [Times: user=0.41
sys=0.00, real=0.19 secs]
(concurrent mode failure): 38082444K->18127660K(39321600K), 138.3709254 secs]
42270144K->18127660K(50244288K), [Metaspace: 46676K->46676K(51200K)], 138.3746435
secs] [Times: user=12.75 sys=22.89, real=138.38 secs]
Heap after GC invocations=8910 (full 1002):
par new generation total 10922688K, used 0K [0x0000000080000000,
0x00000003a0000000, 0x00000003a0000000)
eden space 8738176K, 0% used [0x0000000080000000, 0x0000000080000000,
0x0000000295560000)
from space 2184512K, 0% used [0x0000000295560000, 0x0000000295560000,
0x000000031aab0000)
to space 2184512K, 0% used [0x000000031aab0000, 0x000000031aab0000,
0x00000003a0000000)
concurrent mark-sweep generation total 39321600K, used 18127660K
[0x00000003a0000000, 0x0000000d00000000, 0x0000000d00000000)
Metaspace used 46676K, capacity 47372K, committed 50136K, reserved 51200K
}
2018-01-04T12:15:58.772+0000: 140639.993: Total time for which application
threads were stopped: 138.4138211 seconds, Stopping threads took: 0.0369886
seconds
Regards,
Maulin
-----Original Message-----
From: Erick Erickson [mailto:erickerick...@gmail.com]
Sent: 31 January 2018 22:47
To: solr-user <solr-user@lucene.apache.org>
Subject: Re: Long GC Pauses
Just to double check, when you san you're seeing 60-200 sec GC pauses are you
looking at the GC logs (or using some kind of monitor) or is that the time it
takes the query to respond to the client? Because a single GC pause that long
on 40G is unusual no matter what. Another take on Jason's question is For all
the JVMs you're running, how much _total_ heap is allocated?
And how much physical memory is on the box? I generally start with _at least_
half the memory left to the OS....
These are fairly horrible, what generates such queries?
AND * AND *
Best,
Erick
On Wed, Jan 31, 2018 at 7:28 AM, Jason Gerlowski
<gerlowsk...@gmail.com<mailto:gerlowsk...@gmail.com>> wrote:
Hi Maulin,
To clarify, when you said "...allocated 40 GB RAM to each shard."
above, I'm going to assume you meant "to each node" instead. If you
actually did mean "to each shard" above, please correct me and anyone
who chimes in afterward.
Firstly, it's really hard to even take guesses about potential causes
or remediations without more details about your load characteristics
(average/peak QPS, index size, average document size, etc.). If no
one gives any satisfactory advice, please consider uploading
additional details to help us help you.
Secondly, I don't know anything about the load characteristics you're
putting on your Solr cluster, but I'm curious whether you've
experimented with lower RAM settings. Generally speaking, the more
RAM you have, the longer your GC pauses are likely to be (even with
the tuning that various GC settings provide). If you can get away
with giving the Solr process less RAM, you should see your GC pauses
shrink. Was 40GB chosen after some trial-and-error experimentation, or is it
something you could investigate?
For a bit more overview on this, see this slightly outdated (but still
useful) wiki page:
https://wiki.apache.org/solr/SolrPerformanceProblems#RAM
Hope that helps, even if just to disqualify some potential
causes/solutions to close in on a real fix.
Best,
Jason
On Wed, Jan 31, 2018 at 8:17 AM, Maulin Rathod
<mrat...@asite.com<mailto:mrat...@asite.com>> wrote:
Hi,
We are using solr cloud 6.1. We have around 20 collection on 4 nodes
(We have 2 shards and each shard have 2 replicas). We have allocated
40 GB RAM to each shard.
Intermittently we found long GC pauses (60 sec to 200 sec) due to
which solr stops responding and hence collections goes in recovering
mode. It takes minimum 5-10 minutes (sometime it takes more and we
have to restart the solr node) for recovering all collections. We are
using default GC setting (CMS) as per solr.cmd.
We tried different G1 GC to see if it help, but still we see long GC
pauses(60 sec to 200 sec) and also found that memory usage is more in
in case G1 GC.
What could be reason for long GC pauses and how can fix it?
Insufficient memory or problem with GC setting or something else? Any
suggestion would be greatly appreciated.
In our analysis, we also found some inefficient queries (which uses *
many times in query) in solr logs. Could it be reason for high memory usage?
Slow Query
--------------
INFO (qtp1239731077-498778) [c:documents s:shard1 r:core_node1
x:documents] o.a.s.c.S.Request [documents] webapp=/solr path=/select
params={df=summary&distrib=false&fl=id&shards.purpose=4&
start=0&fsv=true&sort=description+asc,id+desc&fq=&shard.url=
s1.asite.com:8983/solr/documents|s1r1.asite.com:
8983/solr/documents&rows=250&version=2&q=((id:(
REV78364_24705418+REV78364_24471492+REV78364_24471429+
REV78364_24470771+REV78364_24470271+))+OR+summary:((HPC*+
AND+*+AND+*+AND+OH1150*+AND+*+AND+*+AND+U0*+AND+*+AND+*+AND+
HGS*+AND+*+AND+*+AND+MDL*+AND+*+AND+*+AND+100067*+AND+*+AND+
-*+AND+Reinforcement*+AND+*+AND+Mode*)+))++AND++(title:((*
HPC\+\-\+OH1150\+\-\+U0\+\-\+HGS\+\-\+MDL\+\-\+100067\+-\+
Reinforcement\+Mode*)+))+AND+project_id:(-2+78243+78365+
78364)+AND+is_active:true+AND+((isLatest:(true)+AND+
isFolderActive:true+AND+isXref:false+AND+-document_
type_id:(3+7)+AND+((is_public:true+OR+distribution_list:
4858120+OR+folderadmin_list:4858120+OR+author_user_id:
4858120)+AND+((defaultAccess:(true)+OR+allowedUsers:(
4858120)+OR+allowedRoles:(6342201+172408+6336860)+OR+
combinationUsers:(4858120))+AND+-blockedUsers:(4858120))))
+OR+(isLatestRevPrivate:(true)+AND+allowedUsersForPvtRev:(
4858120)+AND+-folderadmin_list:(4858120)))&shards.tolerant=true&NOW=
1516786982952&isShard=true&wt=javabin} hits=0 status=0 QTime=83309
Regards,
Maulin
[CC Award Winners!]
