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 Rallavagu <ra...@gmail.com> on 2016/09/16 15:40:33 UTC
slow updates/searches
Solr 5.4.1 with embedded jetty single shard - NRT
Looking in logs, noticed that there are high QTimes for Queries and
round same time high response times for updates. These are not during
"commit" or "softCommit" but when client application is sending updates.
Wondering how updates could impact query performance. What are the
options for tuning? Thanks.
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
Hi Erick,
Yes. Apparently, there is work to do with phrase queries. As I continue
to debug, noticed that a multi word phrase query is CPU bound as it
certainly works "hard". Are there any optimizations to consider?
On 9/29/16 8:14 AM, Erick Erickson wrote:
> bq: The QTimes increase as the number of words in a phrase increase
>
> Well, there's more work to do as the # of words increases, and if you
> have large slops there's more work yet.
>
> Best,
> Erick
>
> On Wed, Sep 28, 2016 at 5:54 PM, Rallavagu <ra...@gmail.com> wrote:
>> Thanks Erick.
>>
>> I have added queries for "firstSearcher" and "newSearcher". After startup,
>> pmap shows well populated mmap entries and have better QTimes than before.
>>
>> However, phrase queries (edismax with pf2) are still sluggish. The QTimes
>> increase as the number of words in a phrase increase. None of the mmap
>> "warming" seem to have any impact on this. Am I missing anything? Thanks.
>>
>> On 9/24/16 5:20 PM, Erick Erickson wrote:
>>>
>>> Hmm..
>>>
>>> About <1>: Yep, GC is one of the "more art than science" bits of
>>> Java/Solr. Siiiggggh.
>>>
>>> About <2>: that's what autowarming is about. Particularly the
>>> filterCache and queryResultCache. My guess is that you have the
>>> autowarm count on those two caches set to zero. Try setting it to some
>>> modest number like 16 or 32. The whole _point_ of those parameters is
>>> to smooth out these kinds of spikes. Additionally, the newSearcher
>>> event (also in solrconfig.xml) is explicitly intended to allow you to
>>> hard-code queries that fill the internal caches as well as the mmap OS
>>> memory from disk, people include facets, sorts and the like in that
>>> event. It's fired every time a new searcher is opened (i.e. whenever
>>> you commit and open a new searcher)...
>>>
>>> FirstSearcher is for restarts. The difference is that newSearcher
>>> presumes Solr has been running for a while and the autowarm counts
>>> have something to work from. OTOH, when you start Solr there's no
>>> history to autowarm so firstSeracher can be quite a bit more complex
>>> than newSearcher. Practically, most people just copy newSearcher into
>>> firstSearcher on the assumption that restarting Solr is pretty
>>> rare.....
>>>
>>> about <3> MMap stuff will be controlled by the OS I think. I actually
>>> worked with a much more primitive system at one point that would be
>>> dog-slow during off-hours. Someone wrote an equivalent of a cron job
>>> to tickle the app upon occasion to prevent periodic slowness.....
>>>
>>> for a nauseating set of details about hard and soft commits, see:
>>>
>>> https://lucidworks.com/blog/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/
>>>
>>> Best,
>>> Erick
>>>
>>>
>>> On Sat, Sep 24, 2016 at 11:35 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>
>>>>
>>>>
>>>> On 9/22/16 5:59 AM, Shawn Heisey wrote:
>>>>>
>>>>>
>>>>> On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
>>>>>>
>>>>>>
>>>>>> Did you find any solution to slow searches? As far as I know jetty
>>>>>> container default configuration is bit slow for large production
>>>>>> environment.
>>>>>
>>>>>
>>>>>
>>>>> This might be true for the default configuration that comes with a
>>>>> completely stock jetty downloaded from eclipse.org, but the jetty
>>>>> configuration that *Solr* ships with is adequate for just about any Solr
>>>>> installation. The Solr configuration may require adjustment as the
>>>>> query load increases, but the jetty configuration usually doesn't.
>>>>>
>>>>> Thanks,
>>>>> Shawn
>>>>>
>>>>
>>>> It turned out to be a "sequence of performance testing sessions" in order
>>>> to
>>>> locate slowness. Though I am not completely done with it, here are my
>>>> finding so far. We are using NRT configuration (warm up count to 0 for
>>>> caches and NRTCachingDirectoryFactory for index directory)
>>>>
>>>> 1. Essentially, solr searches (particularly with edismax and relevance)
>>>> generate lot of "garbage" that makes GC activity to kick in more often.
>>>> This
>>>> becomes even more when facets are included. This has huge impact on
>>>> QTimes
>>>> (I have 12g heap and configured 6g to NewSize).
>>>>
>>>> 2. After a fresh restart (or core reload) when searches are performed,
>>>> Solr
>>>> would initially "populate" mmap entries and this is adding to total
>>>> QTimes
>>>> (I have made sure that index files are cached at filesystem layer using
>>>> vmtouch - https://hoytech.com/vmtouch). When run the same test again with
>>>> mmap entries populated from previous tests, it shows improved QTimes
>>>> relative to previous test.
>>>>
>>>> 3. Seems the populated mmap entries are flushed away after certain idle
>>>> time
>>>> (not sure if it is controlled by Solr or underlying OS). This will make
>>>> subsequent searches to fetch from "disk" (even though the disk items are
>>>> cached by OS).
>>>>
>>>> So, what I am gonna try next is to tune the field(s) for facets to reduce
>>>> the index size if possible. Though I am not sure, if it will have impact
>>>> but
>>>> would attempt to change the "caches" even though they will be invalidated
>>>> after a softCommit (every 10 minutes in my case).
>>>>
>>>> Any other tips/clues/suggestions are welcome. Thanks.
>>>>
>>
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
bq: The QTimes increase as the number of words in a phrase increase
Well, there's more work to do as the # of words increases, and if you
have large slops there's more work yet.
Best,
Erick
On Wed, Sep 28, 2016 at 5:54 PM, Rallavagu <ra...@gmail.com> wrote:
> Thanks Erick.
>
> I have added queries for "firstSearcher" and "newSearcher". After startup,
> pmap shows well populated mmap entries and have better QTimes than before.
>
> However, phrase queries (edismax with pf2) are still sluggish. The QTimes
> increase as the number of words in a phrase increase. None of the mmap
> "warming" seem to have any impact on this. Am I missing anything? Thanks.
>
> On 9/24/16 5:20 PM, Erick Erickson wrote:
>>
>> Hmm..
>>
>> About <1>: Yep, GC is one of the "more art than science" bits of
>> Java/Solr. Siiiggggh.
>>
>> About <2>: that's what autowarming is about. Particularly the
>> filterCache and queryResultCache. My guess is that you have the
>> autowarm count on those two caches set to zero. Try setting it to some
>> modest number like 16 or 32. The whole _point_ of those parameters is
>> to smooth out these kinds of spikes. Additionally, the newSearcher
>> event (also in solrconfig.xml) is explicitly intended to allow you to
>> hard-code queries that fill the internal caches as well as the mmap OS
>> memory from disk, people include facets, sorts and the like in that
>> event. It's fired every time a new searcher is opened (i.e. whenever
>> you commit and open a new searcher)...
>>
>> FirstSearcher is for restarts. The difference is that newSearcher
>> presumes Solr has been running for a while and the autowarm counts
>> have something to work from. OTOH, when you start Solr there's no
>> history to autowarm so firstSeracher can be quite a bit more complex
>> than newSearcher. Practically, most people just copy newSearcher into
>> firstSearcher on the assumption that restarting Solr is pretty
>> rare.....
>>
>> about <3> MMap stuff will be controlled by the OS I think. I actually
>> worked with a much more primitive system at one point that would be
>> dog-slow during off-hours. Someone wrote an equivalent of a cron job
>> to tickle the app upon occasion to prevent periodic slowness.....
>>
>> for a nauseating set of details about hard and soft commits, see:
>>
>> https://lucidworks.com/blog/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/
>>
>> Best,
>> Erick
>>
>>
>> On Sat, Sep 24, 2016 at 11:35 AM, Rallavagu <ra...@gmail.com> wrote:
>>>
>>>
>>>
>>> On 9/22/16 5:59 AM, Shawn Heisey wrote:
>>>>
>>>>
>>>> On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
>>>>>
>>>>>
>>>>> Did you find any solution to slow searches? As far as I know jetty
>>>>> container default configuration is bit slow for large production
>>>>> environment.
>>>>
>>>>
>>>>
>>>> This might be true for the default configuration that comes with a
>>>> completely stock jetty downloaded from eclipse.org, but the jetty
>>>> configuration that *Solr* ships with is adequate for just about any Solr
>>>> installation. The Solr configuration may require adjustment as the
>>>> query load increases, but the jetty configuration usually doesn't.
>>>>
>>>> Thanks,
>>>> Shawn
>>>>
>>>
>>> It turned out to be a "sequence of performance testing sessions" in order
>>> to
>>> locate slowness. Though I am not completely done with it, here are my
>>> finding so far. We are using NRT configuration (warm up count to 0 for
>>> caches and NRTCachingDirectoryFactory for index directory)
>>>
>>> 1. Essentially, solr searches (particularly with edismax and relevance)
>>> generate lot of "garbage" that makes GC activity to kick in more often.
>>> This
>>> becomes even more when facets are included. This has huge impact on
>>> QTimes
>>> (I have 12g heap and configured 6g to NewSize).
>>>
>>> 2. After a fresh restart (or core reload) when searches are performed,
>>> Solr
>>> would initially "populate" mmap entries and this is adding to total
>>> QTimes
>>> (I have made sure that index files are cached at filesystem layer using
>>> vmtouch - https://hoytech.com/vmtouch). When run the same test again with
>>> mmap entries populated from previous tests, it shows improved QTimes
>>> relative to previous test.
>>>
>>> 3. Seems the populated mmap entries are flushed away after certain idle
>>> time
>>> (not sure if it is controlled by Solr or underlying OS). This will make
>>> subsequent searches to fetch from "disk" (even though the disk items are
>>> cached by OS).
>>>
>>> So, what I am gonna try next is to tune the field(s) for facets to reduce
>>> the index size if possible. Though I am not sure, if it will have impact
>>> but
>>> would attempt to change the "caches" even though they will be invalidated
>>> after a softCommit (every 10 minutes in my case).
>>>
>>> Any other tips/clues/suggestions are welcome. Thanks.
>>>
>
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
Thanks Erick.
I have added queries for "firstSearcher" and "newSearcher". After
startup, pmap shows well populated mmap entries and have better QTimes
than before.
However, phrase queries (edismax with pf2) are still sluggish. The
QTimes increase as the number of words in a phrase increase. None of the
mmap "warming" seem to have any impact on this. Am I missing anything?
Thanks.
On 9/24/16 5:20 PM, Erick Erickson wrote:
> Hmm..
>
> About <1>: Yep, GC is one of the "more art than science" bits of
> Java/Solr. Siiiggggh.
>
> About <2>: that's what autowarming is about. Particularly the
> filterCache and queryResultCache. My guess is that you have the
> autowarm count on those two caches set to zero. Try setting it to some
> modest number like 16 or 32. The whole _point_ of those parameters is
> to smooth out these kinds of spikes. Additionally, the newSearcher
> event (also in solrconfig.xml) is explicitly intended to allow you to
> hard-code queries that fill the internal caches as well as the mmap OS
> memory from disk, people include facets, sorts and the like in that
> event. It's fired every time a new searcher is opened (i.e. whenever
> you commit and open a new searcher)...
>
> FirstSearcher is for restarts. The difference is that newSearcher
> presumes Solr has been running for a while and the autowarm counts
> have something to work from. OTOH, when you start Solr there's no
> history to autowarm so firstSeracher can be quite a bit more complex
> than newSearcher. Practically, most people just copy newSearcher into
> firstSearcher on the assumption that restarting Solr is pretty
> rare.....
>
> about <3> MMap stuff will be controlled by the OS I think. I actually
> worked with a much more primitive system at one point that would be
> dog-slow during off-hours. Someone wrote an equivalent of a cron job
> to tickle the app upon occasion to prevent periodic slowness.....
>
> for a nauseating set of details about hard and soft commits, see:
> https://lucidworks.com/blog/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/
>
> Best,
> Erick
>
>
> On Sat, Sep 24, 2016 at 11:35 AM, Rallavagu <ra...@gmail.com> wrote:
>>
>>
>> On 9/22/16 5:59 AM, Shawn Heisey wrote:
>>>
>>> On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
>>>>
>>>> Did you find any solution to slow searches? As far as I know jetty
>>>> container default configuration is bit slow for large production
>>>> environment.
>>>
>>>
>>> This might be true for the default configuration that comes with a
>>> completely stock jetty downloaded from eclipse.org, but the jetty
>>> configuration that *Solr* ships with is adequate for just about any Solr
>>> installation. The Solr configuration may require adjustment as the
>>> query load increases, but the jetty configuration usually doesn't.
>>>
>>> Thanks,
>>> Shawn
>>>
>>
>> It turned out to be a "sequence of performance testing sessions" in order to
>> locate slowness. Though I am not completely done with it, here are my
>> finding so far. We are using NRT configuration (warm up count to 0 for
>> caches and NRTCachingDirectoryFactory for index directory)
>>
>> 1. Essentially, solr searches (particularly with edismax and relevance)
>> generate lot of "garbage" that makes GC activity to kick in more often. This
>> becomes even more when facets are included. This has huge impact on QTimes
>> (I have 12g heap and configured 6g to NewSize).
>>
>> 2. After a fresh restart (or core reload) when searches are performed, Solr
>> would initially "populate" mmap entries and this is adding to total QTimes
>> (I have made sure that index files are cached at filesystem layer using
>> vmtouch - https://hoytech.com/vmtouch). When run the same test again with
>> mmap entries populated from previous tests, it shows improved QTimes
>> relative to previous test.
>>
>> 3. Seems the populated mmap entries are flushed away after certain idle time
>> (not sure if it is controlled by Solr or underlying OS). This will make
>> subsequent searches to fetch from "disk" (even though the disk items are
>> cached by OS).
>>
>> So, what I am gonna try next is to tune the field(s) for facets to reduce
>> the index size if possible. Though I am not sure, if it will have impact but
>> would attempt to change the "caches" even though they will be invalidated
>> after a softCommit (every 10 minutes in my case).
>>
>> Any other tips/clues/suggestions are welcome. Thanks.
>>
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
Hmm..
About <1>: Yep, GC is one of the "more art than science" bits of
Java/Solr. Siiiggggh.
About <2>: that's what autowarming is about. Particularly the
filterCache and queryResultCache. My guess is that you have the
autowarm count on those two caches set to zero. Try setting it to some
modest number like 16 or 32. The whole _point_ of those parameters is
to smooth out these kinds of spikes. Additionally, the newSearcher
event (also in solrconfig.xml) is explicitly intended to allow you to
hard-code queries that fill the internal caches as well as the mmap OS
memory from disk, people include facets, sorts and the like in that
event. It's fired every time a new searcher is opened (i.e. whenever
you commit and open a new searcher)...
FirstSearcher is for restarts. The difference is that newSearcher
presumes Solr has been running for a while and the autowarm counts
have something to work from. OTOH, when you start Solr there's no
history to autowarm so firstSeracher can be quite a bit more complex
than newSearcher. Practically, most people just copy newSearcher into
firstSearcher on the assumption that restarting Solr is pretty
rare.....
about <3> MMap stuff will be controlled by the OS I think. I actually
worked with a much more primitive system at one point that would be
dog-slow during off-hours. Someone wrote an equivalent of a cron job
to tickle the app upon occasion to prevent periodic slowness.....
for a nauseating set of details about hard and soft commits, see:
https://lucidworks.com/blog/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/
Best,
Erick
On Sat, Sep 24, 2016 at 11:35 AM, Rallavagu <ra...@gmail.com> wrote:
>
>
> On 9/22/16 5:59 AM, Shawn Heisey wrote:
>>
>> On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
>>>
>>> Did you find any solution to slow searches? As far as I know jetty
>>> container default configuration is bit slow for large production
>>> environment.
>>
>>
>> This might be true for the default configuration that comes with a
>> completely stock jetty downloaded from eclipse.org, but the jetty
>> configuration that *Solr* ships with is adequate for just about any Solr
>> installation. The Solr configuration may require adjustment as the
>> query load increases, but the jetty configuration usually doesn't.
>>
>> Thanks,
>> Shawn
>>
>
> It turned out to be a "sequence of performance testing sessions" in order to
> locate slowness. Though I am not completely done with it, here are my
> finding so far. We are using NRT configuration (warm up count to 0 for
> caches and NRTCachingDirectoryFactory for index directory)
>
> 1. Essentially, solr searches (particularly with edismax and relevance)
> generate lot of "garbage" that makes GC activity to kick in more often. This
> becomes even more when facets are included. This has huge impact on QTimes
> (I have 12g heap and configured 6g to NewSize).
>
> 2. After a fresh restart (or core reload) when searches are performed, Solr
> would initially "populate" mmap entries and this is adding to total QTimes
> (I have made sure that index files are cached at filesystem layer using
> vmtouch - https://hoytech.com/vmtouch). When run the same test again with
> mmap entries populated from previous tests, it shows improved QTimes
> relative to previous test.
>
> 3. Seems the populated mmap entries are flushed away after certain idle time
> (not sure if it is controlled by Solr or underlying OS). This will make
> subsequent searches to fetch from "disk" (even though the disk items are
> cached by OS).
>
> So, what I am gonna try next is to tune the field(s) for facets to reduce
> the index size if possible. Though I am not sure, if it will have impact but
> would attempt to change the "caches" even though they will be invalidated
> after a softCommit (every 10 minutes in my case).
>
> Any other tips/clues/suggestions are welcome. Thanks.
>
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
On 9/22/16 5:59 AM, Shawn Heisey wrote:
> On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
>> Did you find any solution to slow searches? As far as I know jetty
>> container default configuration is bit slow for large production
>> environment.
>
> This might be true for the default configuration that comes with a
> completely stock jetty downloaded from eclipse.org, but the jetty
> configuration that *Solr* ships with is adequate for just about any Solr
> installation. The Solr configuration may require adjustment as the
> query load increases, but the jetty configuration usually doesn't.
>
> Thanks,
> Shawn
>
It turned out to be a "sequence of performance testing sessions" in
order to locate slowness. Though I am not completely done with it, here
are my finding so far. We are using NRT configuration (warm up count to
0 for caches and NRTCachingDirectoryFactory for index directory)
1. Essentially, solr searches (particularly with edismax and relevance)
generate lot of "garbage" that makes GC activity to kick in more often.
This becomes even more when facets are included. This has huge impact on
QTimes (I have 12g heap and configured 6g to NewSize).
2. After a fresh restart (or core reload) when searches are performed,
Solr would initially "populate" mmap entries and this is adding to total
QTimes (I have made sure that index files are cached at filesystem layer
using vmtouch - https://hoytech.com/vmtouch). When run the same test
again with mmap entries populated from previous tests, it shows improved
QTimes relative to previous test.
3. Seems the populated mmap entries are flushed away after certain idle
time (not sure if it is controlled by Solr or underlying OS). This will
make subsequent searches to fetch from "disk" (even though the disk
items are cached by OS).
So, what I am gonna try next is to tune the field(s) for facets to
reduce the index size if possible. Though I am not sure, if it will have
impact but would attempt to change the "caches" even though they will be
invalidated after a softCommit (every 10 minutes in my case).
Any other tips/clues/suggestions are welcome. Thanks.
Re: slow updates/searches
Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/22/2016 5:46 AM, Muhammad Zahid Iqbal wrote:
> Did you find any solution to slow searches? As far as I know jetty
> container default configuration is bit slow for large production
> environment.
This might be true for the default configuration that comes with a
completely stock jetty downloaded from eclipse.org, but the jetty
configuration that *Solr* ships with is adequate for just about any Solr
installation. The Solr configuration may require adjustment as the
query load increases, but the jetty configuration usually doesn't.
Thanks,
Shawn
Re: slow updates/searches
Posted by Muhammad Zahid Iqbal <za...@northbaysolutions.net>.
Rallavagu,
Did you find any solution to slow searches? As far as I know jetty
container default configuration is bit slow for large production
environment.
On Tue, Sep 20, 2016 at 8:05 AM, Erick Erickson <er...@gmail.com>
wrote:
> If both queries _and_ updates are slow, it's hard to see how upping
> the number of
> threads would help overall. Hmmm, you also reported that the CPUs
> didn't seem to be
> stressed so its worth a try, perhaps there's some kind of blocking going
> on....
>
> Best,
> Erick
>
> On Mon, Sep 19, 2016 at 5:33 PM, Rallavagu <ra...@gmail.com> wrote:
> > Hi Erick,
> >
> > Would increasing (or adjusting) update threads help as per this JIRA
> ((Allow
> > the number of threads ConcurrentUpdateSolrClient StreamingSolrClients
> > configurable by a system property) here?
> >
> > https://issues.apache.org/jira/browse/SOLR-8500
> >
> > Thanks
> >
> >
> > On 9/19/16 8:30 AM, Erick Erickson wrote:
> >>
> >> Hmmm, not sure, and also not sure what to suggest next. QTimes
> >> measure only the search time, not, say, time waiting for the request to
> >> get
> >> serviced.
> >>
> >> I'm afraid the next suggestion is to throw a profiler at it 'cause
> nothing
> >> jumps
> >> out at me..'
> >>
> >> Best,
> >> Erick
> >>
> >> On Fri, Sep 16, 2016 at 10:23 AM, Rallavagu <ra...@gmail.com>
> wrote:
> >>>
> >>> Comments in line...
> >>>
> >>> On 9/16/16 10:15 AM, Erick Erickson wrote:
> >>>>
> >>>>
> >>>> Well, the next thing I'd look at is CPU activity. If you're flooding
> the
> >>>> system
> >>>> with updates there'll be CPU contention.
> >>>
> >>>
> >>>
> >>> Monitoring does not suggest any high CPU but as you can see from vmstat
> >>> output "user" cpu is a bit high during updates that are taking time (34
> >>> user, 65 idle).
> >>>
> >>>>
> >>>> And there are a number of things you can do that make updates in
> >>>> particular
> >>>> much less efficient, from committing very frequently (sometimes
> combined
> >>>> with excessive autowarm parameters) and the like.
> >>>
> >>>
> >>>
> >>> softCommit is set to 10 minutes, autowarm count is set to 0 and commit
> is
> >>> set to 15 sec for NRT.
> >>>
> >>>>
> >>>> There are a series of ideas that might trigger an "aha" moment:
> >>>> https://wiki.apache.org/solr/SolrPerformanceFactors
> >>>
> >>>
> >>>
> >>> Reviewed this document and made few changes accordingly a while ago.
> >>>>
> >>>>
> >>>>
> >>>> But the crude measure is just to look at CPU usage when updates
> happen,
> >>>> or
> >>>> just before. Are you running hot with queries alone then add an update
> >>>> burden?
> >>>
> >>>
> >>>
> >>> Essentially, it is high QTimes for queries got me looking into logs,
> >>> system
> >>> etc and I could correlate updates slowness and searching slowness. Some
> >>> other time QTimes go high is right after softCommit which is expected.
> >>>
> >>> Wondering what causes update threads wait and if it has any impact on
> >>> search
> >>> at all. I had couple of more CPUs added but I still see similar
> behavior.
> >>>
> >>> Thanks.
> >>>
> >>>
> >>>>
> >>>> Best,
> >>>> Erick
> >>>>
> >>>> On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com>
> wrote:
> >>>>>
> >>>>>
> >>>>> Erick,
> >>>>>
> >>>>> Was monitoring GC activity and couldn't align GC pauses to this
> >>>>> behavior.
> >>>>> Also, the vmstat shows no swapping or cpu I/O wait. However,
> whenever I
> >>>>> see
> >>>>> high update response times (corresponding high QTimes for searches)
> >>>>> vmstat
> >>>>> shows as series of number of "waiting to runnable" processes in "r"
> >>>>> column
> >>>>> of "procs" section.
> >>>>>
> >>>>>
> >>>>>
> >>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%
> 202016-09-16%20at%209.05.51%20AM.png
> >>>>>
> >>>>> procs -----------------------memory---------------------- ---swap--
> >>>>> -----io---- -system-- --------cpu-------- -----timestamp-----
> >>>>> r b swpd free inact active si so
> bi
> >>>>> bo
> >>>>> in cs us sy id wa st CDT
> >>>>> 2 0 71068 18688496 2526604 24204440 0 0 0
> >>>>> 0
> >>>>> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
> >>>>> 1 0 71068 18688180 2526600 24204568 0 0 0
> >>>>> 0
> >>>>> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
> >>>>> 1 0 71068 18687928 2526600 24204568 0 0 0
> >>>>> 0
> >>>>> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
> >>>>> 1 0 71068 18687800 2526600 24204572 0 0 0
> >>>>> 0
> >>>>> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
> >>>>> 1 0 71068 18687164 2527116 24204844 0 0 0
> >>>>> 0
> >>>>> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
> >>>>> 1 0 71068 18686944 2527108 24204908 0 0 0
> >>>>> 52
> >>>>> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
> >>>>> 12 1 71068 18682676 2528560 24207116 0 0 0
> >>>>> 280
> >>>>> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
> >>>>> 2 1 71068 18651340 2530820 24233368 0 0 0
> >>>>> 1052
> >>>>> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
> >>>>> 5 0 71068 18648600 2530112 24235060 0 0 0
> >>>>> 1988
> >>>>> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
> >>>>> 9 1 71068 18647804 2530580 24236076 0 0 0
> >>>>> 1688
> >>>>> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
> >>>>> 1 0 71068 18647628 2530364 24236256 0 0 0
> >>>>> 680
> >>>>> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
> >>>>> 1 0 71068 18646344 2531204 24236536 0 0 0
> >>>>> 44
> >>>>> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
> >>>>> 2 0 71068 18644460 2532196 24237440 0 0 0
> >>>>> 0
> >>>>> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
> >>>>> 0 0 71068 18661900 2531724 24218764 0 0 0
> >>>>> 0
> >>>>> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
> >>>>> 2 0 71068 18649400 2532228 24229800 0 0 0
> >>>>> 0
> >>>>> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
> >>>>> 0 0 71068 18648280 2533440 24230300 0 0 0
> >>>>> 108
> >>>>> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
> >>>>> 0 0 71068 18648156 2533212 24230684 0 0 0
> >>>>> 12
> >>>>> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
> >>>>>
> >>>>>
> >>>>> Captured stack trace including timing for one of the update threads.
> >>>>>
> >>>>>
> >>>>> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method
> time =
> >>>>> 15
> >>>>> ms, total time = 30782 ms)
> >>>>> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total
> >>>>> time
> >>>>> =
> >>>>> 30767 ms)
> >>>>> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms,
> total
> >>>>> time =
> >>>>> 30767 ms)
> >>>>> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0
> ms,
> >>>>> total
> >>>>> time = 30767 ms)
> >>>>> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time =
> 0
> >>>>> ms,
> >>>>> total time = 30767 ms)
> >>>>> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms,
> >>>>> total
> >>>>> time = 30767 ms)
> >>>>> org.apache.solr.handler.RequestHandlerBase:handleRequest:156
> >>>>> (method
> >>>>> time = 0 ms, total time = 30767 ms)
> >>>>>
> >>>>> org.apache.solr.handler.ContentStreamHandlerBase:
> handleRequestBody:70
> >>>>> (method time = 0 ms, total time = 30767 ms)
> >>>>> org.apache.solr.handler.UpdateRequestHandler$1:load:95
> (method
> >>>>> time
> >>>>> = 0 ms, total time = 23737 ms)
> >>>>> org.apache.solr.handler.loader.XMLLoader:load:178 (method
> time
> >>>>> =
> >>>>> 0
> >>>>> ms, total time = 23737 ms)
> >>>>> org.apache.solr.handler.loader.XMLLoader:processUpdate:251
> >>>>> (method
> >>>>> time = 0 ms, total time = 23737 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$
> LogUpdateProcessor:processAdd:104
> >>>>> (method time = 0 ms, total time = 23737 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> processAdd:702
> >>>>> (method time = 0 ms, total time = 23737 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> versionAdd:1011
> >>>>> (method time = 0 ms, total time = 23477 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> getUpdatedDocument:1114
> >>>>> (method time = 0 ms, total time = 51 ms)
> >>>>>
> >>>>> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:
> merge:110
> >>>>> (method time = 51 ms, total time = 51 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> doLocalAdd:924
> >>>>> (method time = 0 ms, total time = 23426 ms)
> >>>>>
> >>>>> org.apache.solr.update.processor.UpdateRequestProcessor:
> processAdd:49
> >>>>> (method time = 0 ms, total time = 23426 ms)
> >>>>>
> >>>>> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69
> >>>>> (method
> >>>>> time = 0 ms, total time = 23426 ms)
> >>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc:
> 169
> >>>>> (method time = 0 ms, total time = 23426 ms)
> >>>>>
> >>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method
> time =
> >>>>> 0
> >>>>> ms,
> >>>>> total time = 23426 ms)
> >>>>>
> >>>>> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275
> (method
> >>>>> time
> >>>>> = 0 ms, total time = 23426 ms)
> >>>>>
> >>>>> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method
> time =
> >>>>> 0
> >>>>> ms,
> >>>>> total time = 8551 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method
> time
> >>>>> =
> >>>>> 0
> >>>>> ms, total time = 8551 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234
> >>>>> (method
> >>>>> time = 0 ms, total time = 8551 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DefaultIndexingChain:processDocument:300
> >>>>> (method
> >>>>> time = 0 ms, total time = 8551 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DefaultIndexingChain:processField:344
> (method
> >>>>> time =
> >>>>> 0 ms, total time = 8551 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613
> >>>>> (method
> >>>>> time = 0 ms, total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.analysis.util.FilteringTokenFilter:
> incrementToken:51
> >>>>> (method time = 0 ms, total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627
> >>>>> (method
> >>>>> time = 0 ms, total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method
> time
> >>>>> =
> >>>>> 0
> >>>>> ms, total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0
> ms,
> >>>>> total
> >>>>> time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0
> ms,
> >>>>> total
> >>>>> time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method
> time
> >>>>> =
> >>>>> 0
> >>>>> ms, total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0
> >>>>> ms,
> >>>>> total time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms,
> total
> >>>>> time
> >>>>> = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098
> ms,
> >>>>> total
> >>>>> time = 4098 ms)
> >>>>>
> >>>>> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484
> (method
> >>>>> time
> >>>>> = 0 ms, total time = 4453 ms)
> >>>>>
> >>>>> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method
> time =
> >>>>> 0
> >>>>> ms,
> >>>>> total time = 4453 ms)
> >>>>>
> >>>>> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method
> >>>>> time
> >>>>> =
> >>>>> 4453 ms, total time = 4453 ms)
> >>>>> org.apache.solr.update.UpdateLog:add:412 (method
> >>>>> time
> >>>>> =
> >>>>> 0 ms, total time = 14875 ms)
> >>>>> org.apache.solr.update.UpdateLog:add:421
> (method
> >>>>> time =
> >>>>> 14875 ms, total time = 14875 ms)
> >>>>> org.apache.solr.update.SolrCmdDistributor:distribAdd:
> 207
> >>>>> (method time = 0 ms, total time = 260 ms)
> >>>>> org.apache.solr.update.SolrCmdDistributor:submit:289
> >>>>> (method
> >>>>> time = 0 ms, total time = 260 ms)
> >>>>> org.apache.solr.update.SolrCmdDistributor:doRequest:
> 296
> >>>>> (method time = 0 ms, total time = 260 ms)
> >>>>> org.apache.solr.client.solrj.SolrClient:request:1220
> >>>>> (method
> >>>>> time = 0 ms, total time = 260 ms)
> >>>>>
> >>>>>
> >>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:
> request:382
> >>>>> (method time = 0 ms, total time = 260 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:
> addRunner:324
> >>>>> (method time = 0 ms, total time = 260 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:
> execute:215
> >>>>> (method time = 0 ms, total time = 260 ms)
> >>>>>
> >>>>> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40
> >>>>> (method
> >>>>> time = 260 ms, total time = 260 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$
> LogUpdateProcessor:finish:183
> >>>>> (method time = 0 ms, total time = 7030 ms)
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> finish:1626
> >>>>> (method time = 0 ms, total time = 7030 ms)
> >>>>>
> >>>>>
> >>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:
> doFinish:778
> >>>>> (method time = 0 ms, total time = 7030 ms)
> >>>>> org.apache.solr.update.SolrCmdDistributor:finish:90
> (method
> >>>>> time
> >>>>> = 0 ms, total time = 7030 ms)
> >>>>>
> >>>>> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232
> (method
> >>>>> time
> >>>>> = 0 ms, total time = 7030 ms)
> >>>>>
> >>>>> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107
> >>>>> (method
> >>>>> time = 0 ms, total time = 7030 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:
> blockUntilFinished:429
> >>>>> (method time = 0 ms, total time = 7030 ms)
> >>>>> java.lang.Object:wait (method time = 7030 ms, total
> time
> >>>>> =
> >>>>> 7030 ms)
> >>>>>
> >>>>>
> >>>>>
> >>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%
> 202016-09-16%20at%209.18.52%20AM.png
> >>>>>
> >>>>> Appears there could be thread waiting but I am not sure how would
> this
> >>>>> impact searching.
> >>>>>
> >>>>> Thanks
> >>>>>
> >>>>> On 9/16/16 8:42 AM, Erick Erickson wrote:
> >>>>>>
> >>>>>>
> >>>>>>
> >>>>>> First thing I'd look is whether you're _also_ seeing stop-the-world
> GC
> >>>>>> pauses.
> >>>>>> In that case there are a number of JVM options that can be tuned....
> >>>>>>
> >>>>>> Best,
> >>>>>> Erick
> >>>>>>
> >>>>>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com>
> >>>>>> wrote:
> >>>>>>>
> >>>>>>>
> >>>>>>>
> >>>>>>> Solr 5.4.1 with embedded jetty single shard - NRT
> >>>>>>>
> >>>>>>> Looking in logs, noticed that there are high QTimes for Queries and
> >>>>>>> round
> >>>>>>> same time high response times for updates. These are not during
> >>>>>>> "commit"
> >>>>>>> or
> >>>>>>> "softCommit" but when client application is sending updates.
> >>>>>>> Wondering
> >>>>>>> how
> >>>>>>> updates could impact query performance. What are the options for
> >>>>>>> tuning?
> >>>>>>> Thanks.
>
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
If both queries _and_ updates are slow, it's hard to see how upping
the number of
threads would help overall. Hmmm, you also reported that the CPUs
didn't seem to be
stressed so its worth a try, perhaps there's some kind of blocking going on....
Best,
Erick
On Mon, Sep 19, 2016 at 5:33 PM, Rallavagu <ra...@gmail.com> wrote:
> Hi Erick,
>
> Would increasing (or adjusting) update threads help as per this JIRA ((Allow
> the number of threads ConcurrentUpdateSolrClient StreamingSolrClients
> configurable by a system property) here?
>
> https://issues.apache.org/jira/browse/SOLR-8500
>
> Thanks
>
>
> On 9/19/16 8:30 AM, Erick Erickson wrote:
>>
>> Hmmm, not sure, and also not sure what to suggest next. QTimes
>> measure only the search time, not, say, time waiting for the request to
>> get
>> serviced.
>>
>> I'm afraid the next suggestion is to throw a profiler at it 'cause nothing
>> jumps
>> out at me..'
>>
>> Best,
>> Erick
>>
>> On Fri, Sep 16, 2016 at 10:23 AM, Rallavagu <ra...@gmail.com> wrote:
>>>
>>> Comments in line...
>>>
>>> On 9/16/16 10:15 AM, Erick Erickson wrote:
>>>>
>>>>
>>>> Well, the next thing I'd look at is CPU activity. If you're flooding the
>>>> system
>>>> with updates there'll be CPU contention.
>>>
>>>
>>>
>>> Monitoring does not suggest any high CPU but as you can see from vmstat
>>> output "user" cpu is a bit high during updates that are taking time (34
>>> user, 65 idle).
>>>
>>>>
>>>> And there are a number of things you can do that make updates in
>>>> particular
>>>> much less efficient, from committing very frequently (sometimes combined
>>>> with excessive autowarm parameters) and the like.
>>>
>>>
>>>
>>> softCommit is set to 10 minutes, autowarm count is set to 0 and commit is
>>> set to 15 sec for NRT.
>>>
>>>>
>>>> There are a series of ideas that might trigger an "aha" moment:
>>>> https://wiki.apache.org/solr/SolrPerformanceFactors
>>>
>>>
>>>
>>> Reviewed this document and made few changes accordingly a while ago.
>>>>
>>>>
>>>>
>>>> But the crude measure is just to look at CPU usage when updates happen,
>>>> or
>>>> just before. Are you running hot with queries alone then add an update
>>>> burden?
>>>
>>>
>>>
>>> Essentially, it is high QTimes for queries got me looking into logs,
>>> system
>>> etc and I could correlate updates slowness and searching slowness. Some
>>> other time QTimes go high is right after softCommit which is expected.
>>>
>>> Wondering what causes update threads wait and if it has any impact on
>>> search
>>> at all. I had couple of more CPUs added but I still see similar behavior.
>>>
>>> Thanks.
>>>
>>>
>>>>
>>>> Best,
>>>> Erick
>>>>
>>>> On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>>
>>>>>
>>>>> Erick,
>>>>>
>>>>> Was monitoring GC activity and couldn't align GC pauses to this
>>>>> behavior.
>>>>> Also, the vmstat shows no swapping or cpu I/O wait. However, whenever I
>>>>> see
>>>>> high update response times (corresponding high QTimes for searches)
>>>>> vmstat
>>>>> shows as series of number of "waiting to runnable" processes in "r"
>>>>> column
>>>>> of "procs" section.
>>>>>
>>>>>
>>>>>
>>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
>>>>>
>>>>> procs -----------------------memory---------------------- ---swap--
>>>>> -----io---- -system-- --------cpu-------- -----timestamp-----
>>>>> r b swpd free inact active si so bi
>>>>> bo
>>>>> in cs us sy id wa st CDT
>>>>> 2 0 71068 18688496 2526604 24204440 0 0 0
>>>>> 0
>>>>> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
>>>>> 1 0 71068 18688180 2526600 24204568 0 0 0
>>>>> 0
>>>>> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
>>>>> 1 0 71068 18687928 2526600 24204568 0 0 0
>>>>> 0
>>>>> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
>>>>> 1 0 71068 18687800 2526600 24204572 0 0 0
>>>>> 0
>>>>> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
>>>>> 1 0 71068 18687164 2527116 24204844 0 0 0
>>>>> 0
>>>>> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
>>>>> 1 0 71068 18686944 2527108 24204908 0 0 0
>>>>> 52
>>>>> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
>>>>> 12 1 71068 18682676 2528560 24207116 0 0 0
>>>>> 280
>>>>> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
>>>>> 2 1 71068 18651340 2530820 24233368 0 0 0
>>>>> 1052
>>>>> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
>>>>> 5 0 71068 18648600 2530112 24235060 0 0 0
>>>>> 1988
>>>>> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
>>>>> 9 1 71068 18647804 2530580 24236076 0 0 0
>>>>> 1688
>>>>> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
>>>>> 1 0 71068 18647628 2530364 24236256 0 0 0
>>>>> 680
>>>>> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
>>>>> 1 0 71068 18646344 2531204 24236536 0 0 0
>>>>> 44
>>>>> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
>>>>> 2 0 71068 18644460 2532196 24237440 0 0 0
>>>>> 0
>>>>> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
>>>>> 0 0 71068 18661900 2531724 24218764 0 0 0
>>>>> 0
>>>>> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
>>>>> 2 0 71068 18649400 2532228 24229800 0 0 0
>>>>> 0
>>>>> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
>>>>> 0 0 71068 18648280 2533440 24230300 0 0 0
>>>>> 108
>>>>> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
>>>>> 0 0 71068 18648156 2533212 24230684 0 0 0
>>>>> 12
>>>>> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
>>>>>
>>>>>
>>>>> Captured stack trace including timing for one of the update threads.
>>>>>
>>>>>
>>>>> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time =
>>>>> 15
>>>>> ms, total time = 30782 ms)
>>>>> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total
>>>>> time
>>>>> =
>>>>> 30767 ms)
>>>>> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total
>>>>> time =
>>>>> 30767 ms)
>>>>> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms,
>>>>> total
>>>>> time = 30767 ms)
>>>>> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0
>>>>> ms,
>>>>> total time = 30767 ms)
>>>>> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms,
>>>>> total
>>>>> time = 30767 ms)
>>>>> org.apache.solr.handler.RequestHandlerBase:handleRequest:156
>>>>> (method
>>>>> time = 0 ms, total time = 30767 ms)
>>>>>
>>>>> org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
>>>>> (method time = 0 ms, total time = 30767 ms)
>>>>> org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method
>>>>> time
>>>>> = 0 ms, total time = 23737 ms)
>>>>> org.apache.solr.handler.loader.XMLLoader:load:178 (method time
>>>>> =
>>>>> 0
>>>>> ms, total time = 23737 ms)
>>>>> org.apache.solr.handler.loader.XMLLoader:processUpdate:251
>>>>> (method
>>>>> time = 0 ms, total time = 23737 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
>>>>> (method time = 0 ms, total time = 23737 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
>>>>> (method time = 0 ms, total time = 23737 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
>>>>> (method time = 0 ms, total time = 23477 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
>>>>> (method time = 0 ms, total time = 51 ms)
>>>>>
>>>>> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
>>>>> (method time = 51 ms, total time = 51 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
>>>>> (method time = 0 ms, total time = 23426 ms)
>>>>>
>>>>> org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
>>>>> (method time = 0 ms, total time = 23426 ms)
>>>>>
>>>>> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69
>>>>> (method
>>>>> time = 0 ms, total time = 23426 ms)
>>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc:169
>>>>> (method time = 0 ms, total time = 23426 ms)
>>>>>
>>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time =
>>>>> 0
>>>>> ms,
>>>>> total time = 23426 ms)
>>>>>
>>>>> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method
>>>>> time
>>>>> = 0 ms, total time = 23426 ms)
>>>>>
>>>>> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time =
>>>>> 0
>>>>> ms,
>>>>> total time = 8551 ms)
>>>>>
>>>>> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time
>>>>> =
>>>>> 0
>>>>> ms, total time = 8551 ms)
>>>>>
>>>>> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234
>>>>> (method
>>>>> time = 0 ms, total time = 8551 ms)
>>>>>
>>>>> org.apache.lucene.index.DefaultIndexingChain:processDocument:300
>>>>> (method
>>>>> time = 0 ms, total time = 8551 ms)
>>>>>
>>>>> org.apache.lucene.index.DefaultIndexingChain:processField:344 (method
>>>>> time =
>>>>> 0 ms, total time = 8551 ms)
>>>>>
>>>>> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613
>>>>> (method
>>>>> time = 0 ms, total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
>>>>> (method time = 0 ms, total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627
>>>>> (method
>>>>> time = 0 ms, total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time
>>>>> =
>>>>> 0
>>>>> ms, total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms,
>>>>> total
>>>>> time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms,
>>>>> total
>>>>> time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time
>>>>> =
>>>>> 0
>>>>> ms, total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0
>>>>> ms,
>>>>> total time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total
>>>>> time
>>>>> = 4098 ms)
>>>>>
>>>>> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms,
>>>>> total
>>>>> time = 4098 ms)
>>>>>
>>>>> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method
>>>>> time
>>>>> = 0 ms, total time = 4453 ms)
>>>>>
>>>>> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time =
>>>>> 0
>>>>> ms,
>>>>> total time = 4453 ms)
>>>>>
>>>>> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method
>>>>> time
>>>>> =
>>>>> 4453 ms, total time = 4453 ms)
>>>>> org.apache.solr.update.UpdateLog:add:412 (method
>>>>> time
>>>>> =
>>>>> 0 ms, total time = 14875 ms)
>>>>> org.apache.solr.update.UpdateLog:add:421 (method
>>>>> time =
>>>>> 14875 ms, total time = 14875 ms)
>>>>> org.apache.solr.update.SolrCmdDistributor:distribAdd:207
>>>>> (method time = 0 ms, total time = 260 ms)
>>>>> org.apache.solr.update.SolrCmdDistributor:submit:289
>>>>> (method
>>>>> time = 0 ms, total time = 260 ms)
>>>>> org.apache.solr.update.SolrCmdDistributor:doRequest:296
>>>>> (method time = 0 ms, total time = 260 ms)
>>>>> org.apache.solr.client.solrj.SolrClient:request:1220
>>>>> (method
>>>>> time = 0 ms, total time = 260 ms)
>>>>>
>>>>>
>>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
>>>>> (method time = 0 ms, total time = 260 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
>>>>> (method time = 0 ms, total time = 260 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
>>>>> (method time = 0 ms, total time = 260 ms)
>>>>>
>>>>> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40
>>>>> (method
>>>>> time = 260 ms, total time = 260 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
>>>>> (method time = 0 ms, total time = 7030 ms)
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
>>>>> (method time = 0 ms, total time = 7030 ms)
>>>>>
>>>>>
>>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
>>>>> (method time = 0 ms, total time = 7030 ms)
>>>>> org.apache.solr.update.SolrCmdDistributor:finish:90 (method
>>>>> time
>>>>> = 0 ms, total time = 7030 ms)
>>>>>
>>>>> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method
>>>>> time
>>>>> = 0 ms, total time = 7030 ms)
>>>>>
>>>>> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107
>>>>> (method
>>>>> time = 0 ms, total time = 7030 ms)
>>>>>
>>>>>
>>>>>
>>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
>>>>> (method time = 0 ms, total time = 7030 ms)
>>>>> java.lang.Object:wait (method time = 7030 ms, total time
>>>>> =
>>>>> 7030 ms)
>>>>>
>>>>>
>>>>>
>>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
>>>>>
>>>>> Appears there could be thread waiting but I am not sure how would this
>>>>> impact searching.
>>>>>
>>>>> Thanks
>>>>>
>>>>> On 9/16/16 8:42 AM, Erick Erickson wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> First thing I'd look is whether you're _also_ seeing stop-the-world GC
>>>>>> pauses.
>>>>>> In that case there are a number of JVM options that can be tuned....
>>>>>>
>>>>>> Best,
>>>>>> Erick
>>>>>>
>>>>>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com>
>>>>>> wrote:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> Solr 5.4.1 with embedded jetty single shard - NRT
>>>>>>>
>>>>>>> Looking in logs, noticed that there are high QTimes for Queries and
>>>>>>> round
>>>>>>> same time high response times for updates. These are not during
>>>>>>> "commit"
>>>>>>> or
>>>>>>> "softCommit" but when client application is sending updates.
>>>>>>> Wondering
>>>>>>> how
>>>>>>> updates could impact query performance. What are the options for
>>>>>>> tuning?
>>>>>>> Thanks.
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
Hi Erick,
Would increasing (or adjusting) update threads help as per this JIRA
((Allow the number of threads ConcurrentUpdateSolrClient
StreamingSolrClients configurable by a system property) here?
https://issues.apache.org/jira/browse/SOLR-8500
Thanks
On 9/19/16 8:30 AM, Erick Erickson wrote:
> Hmmm, not sure, and also not sure what to suggest next. QTimes
> measure only the search time, not, say, time waiting for the request to get
> serviced.
>
> I'm afraid the next suggestion is to throw a profiler at it 'cause nothing jumps
> out at me..'
>
> Best,
> Erick
>
> On Fri, Sep 16, 2016 at 10:23 AM, Rallavagu <ra...@gmail.com> wrote:
>> Comments in line...
>>
>> On 9/16/16 10:15 AM, Erick Erickson wrote:
>>>
>>> Well, the next thing I'd look at is CPU activity. If you're flooding the
>>> system
>>> with updates there'll be CPU contention.
>>
>>
>> Monitoring does not suggest any high CPU but as you can see from vmstat
>> output "user" cpu is a bit high during updates that are taking time (34
>> user, 65 idle).
>>
>>>
>>> And there are a number of things you can do that make updates in
>>> particular
>>> much less efficient, from committing very frequently (sometimes combined
>>> with excessive autowarm parameters) and the like.
>>
>>
>> softCommit is set to 10 minutes, autowarm count is set to 0 and commit is
>> set to 15 sec for NRT.
>>
>>>
>>> There are a series of ideas that might trigger an "aha" moment:
>>> https://wiki.apache.org/solr/SolrPerformanceFactors
>>
>>
>> Reviewed this document and made few changes accordingly a while ago.
>>>
>>>
>>> But the crude measure is just to look at CPU usage when updates happen, or
>>> just before. Are you running hot with queries alone then add an update
>>> burden?
>>
>>
>> Essentially, it is high QTimes for queries got me looking into logs, system
>> etc and I could correlate updates slowness and searching slowness. Some
>> other time QTimes go high is right after softCommit which is expected.
>>
>> Wondering what causes update threads wait and if it has any impact on search
>> at all. I had couple of more CPUs added but I still see similar behavior.
>>
>> Thanks.
>>
>>
>>>
>>> Best,
>>> Erick
>>>
>>> On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>
>>>> Erick,
>>>>
>>>> Was monitoring GC activity and couldn't align GC pauses to this behavior.
>>>> Also, the vmstat shows no swapping or cpu I/O wait. However, whenever I
>>>> see
>>>> high update response times (corresponding high QTimes for searches)
>>>> vmstat
>>>> shows as series of number of "waiting to runnable" processes in "r"
>>>> column
>>>> of "procs" section.
>>>>
>>>>
>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
>>>>
>>>> procs -----------------------memory---------------------- ---swap--
>>>> -----io---- -system-- --------cpu-------- -----timestamp-----
>>>> r b swpd free inact active si so bi
>>>> bo
>>>> in cs us sy id wa st CDT
>>>> 2 0 71068 18688496 2526604 24204440 0 0 0
>>>> 0
>>>> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
>>>> 1 0 71068 18688180 2526600 24204568 0 0 0
>>>> 0
>>>> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
>>>> 1 0 71068 18687928 2526600 24204568 0 0 0
>>>> 0
>>>> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
>>>> 1 0 71068 18687800 2526600 24204572 0 0 0
>>>> 0
>>>> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
>>>> 1 0 71068 18687164 2527116 24204844 0 0 0
>>>> 0
>>>> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
>>>> 1 0 71068 18686944 2527108 24204908 0 0 0
>>>> 52
>>>> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
>>>> 12 1 71068 18682676 2528560 24207116 0 0 0
>>>> 280
>>>> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
>>>> 2 1 71068 18651340 2530820 24233368 0 0 0
>>>> 1052
>>>> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
>>>> 5 0 71068 18648600 2530112 24235060 0 0 0
>>>> 1988
>>>> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
>>>> 9 1 71068 18647804 2530580 24236076 0 0 0
>>>> 1688
>>>> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
>>>> 1 0 71068 18647628 2530364 24236256 0 0 0
>>>> 680
>>>> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
>>>> 1 0 71068 18646344 2531204 24236536 0 0 0
>>>> 44
>>>> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
>>>> 2 0 71068 18644460 2532196 24237440 0 0 0
>>>> 0
>>>> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
>>>> 0 0 71068 18661900 2531724 24218764 0 0 0
>>>> 0
>>>> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
>>>> 2 0 71068 18649400 2532228 24229800 0 0 0
>>>> 0
>>>> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
>>>> 0 0 71068 18648280 2533440 24230300 0 0 0
>>>> 108
>>>> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
>>>> 0 0 71068 18648156 2533212 24230684 0 0 0
>>>> 12
>>>> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
>>>>
>>>>
>>>> Captured stack trace including timing for one of the update threads.
>>>>
>>>>
>>>> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time =
>>>> 15
>>>> ms, total time = 30782 ms)
>>>> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total time
>>>> =
>>>> 30767 ms)
>>>> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total
>>>> time =
>>>> 30767 ms)
>>>> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms,
>>>> total
>>>> time = 30767 ms)
>>>> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0 ms,
>>>> total time = 30767 ms)
>>>> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms,
>>>> total
>>>> time = 30767 ms)
>>>> org.apache.solr.handler.RequestHandlerBase:handleRequest:156
>>>> (method
>>>> time = 0 ms, total time = 30767 ms)
>>>>
>>>> org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
>>>> (method time = 0 ms, total time = 30767 ms)
>>>> org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method
>>>> time
>>>> = 0 ms, total time = 23737 ms)
>>>> org.apache.solr.handler.loader.XMLLoader:load:178 (method time =
>>>> 0
>>>> ms, total time = 23737 ms)
>>>> org.apache.solr.handler.loader.XMLLoader:processUpdate:251
>>>> (method
>>>> time = 0 ms, total time = 23737 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
>>>> (method time = 0 ms, total time = 23737 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
>>>> (method time = 0 ms, total time = 23737 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
>>>> (method time = 0 ms, total time = 23477 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
>>>> (method time = 0 ms, total time = 51 ms)
>>>>
>>>> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
>>>> (method time = 51 ms, total time = 51 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
>>>> (method time = 0 ms, total time = 23426 ms)
>>>>
>>>> org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
>>>> (method time = 0 ms, total time = 23426 ms)
>>>>
>>>> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69 (method
>>>> time = 0 ms, total time = 23426 ms)
>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc:169
>>>> (method time = 0 ms, total time = 23426 ms)
>>>>
>>>> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time = 0
>>>> ms,
>>>> total time = 23426 ms)
>>>>
>>>> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method
>>>> time
>>>> = 0 ms, total time = 23426 ms)
>>>>
>>>> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time = 0
>>>> ms,
>>>> total time = 8551 ms)
>>>>
>>>> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time =
>>>> 0
>>>> ms, total time = 8551 ms)
>>>>
>>>> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234
>>>> (method
>>>> time = 0 ms, total time = 8551 ms)
>>>>
>>>> org.apache.lucene.index.DefaultIndexingChain:processDocument:300 (method
>>>> time = 0 ms, total time = 8551 ms)
>>>>
>>>> org.apache.lucene.index.DefaultIndexingChain:processField:344 (method
>>>> time =
>>>> 0 ms, total time = 8551 ms)
>>>>
>>>> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613 (method
>>>> time = 0 ms, total time = 4098 ms)
>>>>
>>>> org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
>>>> (method time = 0 ms, total time = 4098 ms)
>>>>
>>>> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627
>>>> (method
>>>> time = 0 ms, total time = 4098 ms)
>>>>
>>>> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time =
>>>> 0
>>>> ms, total time = 4098 ms)
>>>>
>>>> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms,
>>>> total
>>>> time = 4098 ms)
>>>>
>>>> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms,
>>>> total
>>>> time = 4098 ms)
>>>>
>>>> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time =
>>>> 0
>>>> ms, total time = 4098 ms)
>>>>
>>>> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0 ms,
>>>> total time = 4098 ms)
>>>>
>>>> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total
>>>> time
>>>> = 4098 ms)
>>>>
>>>> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms,
>>>> total
>>>> time = 4098 ms)
>>>>
>>>> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method
>>>> time
>>>> = 0 ms, total time = 4453 ms)
>>>>
>>>> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time = 0
>>>> ms,
>>>> total time = 4453 ms)
>>>>
>>>> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method time
>>>> =
>>>> 4453 ms, total time = 4453 ms)
>>>> org.apache.solr.update.UpdateLog:add:412 (method time
>>>> =
>>>> 0 ms, total time = 14875 ms)
>>>> org.apache.solr.update.UpdateLog:add:421 (method
>>>> time =
>>>> 14875 ms, total time = 14875 ms)
>>>> org.apache.solr.update.SolrCmdDistributor:distribAdd:207
>>>> (method time = 0 ms, total time = 260 ms)
>>>> org.apache.solr.update.SolrCmdDistributor:submit:289
>>>> (method
>>>> time = 0 ms, total time = 260 ms)
>>>> org.apache.solr.update.SolrCmdDistributor:doRequest:296
>>>> (method time = 0 ms, total time = 260 ms)
>>>> org.apache.solr.client.solrj.SolrClient:request:1220
>>>> (method
>>>> time = 0 ms, total time = 260 ms)
>>>>
>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
>>>> (method time = 0 ms, total time = 260 ms)
>>>>
>>>>
>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
>>>> (method time = 0 ms, total time = 260 ms)
>>>>
>>>>
>>>> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
>>>> (method time = 0 ms, total time = 260 ms)
>>>>
>>>> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40 (method
>>>> time = 260 ms, total time = 260 ms)
>>>>
>>>>
>>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
>>>> (method time = 0 ms, total time = 7030 ms)
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
>>>> (method time = 0 ms, total time = 7030 ms)
>>>>
>>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
>>>> (method time = 0 ms, total time = 7030 ms)
>>>> org.apache.solr.update.SolrCmdDistributor:finish:90 (method
>>>> time
>>>> = 0 ms, total time = 7030 ms)
>>>>
>>>> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method
>>>> time
>>>> = 0 ms, total time = 7030 ms)
>>>>
>>>> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107
>>>> (method
>>>> time = 0 ms, total time = 7030 ms)
>>>>
>>>>
>>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
>>>> (method time = 0 ms, total time = 7030 ms)
>>>> java.lang.Object:wait (method time = 7030 ms, total time =
>>>> 7030 ms)
>>>>
>>>>
>>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
>>>>
>>>> Appears there could be thread waiting but I am not sure how would this
>>>> impact searching.
>>>>
>>>> Thanks
>>>>
>>>> On 9/16/16 8:42 AM, Erick Erickson wrote:
>>>>>
>>>>>
>>>>> First thing I'd look is whether you're _also_ seeing stop-the-world GC
>>>>> pauses.
>>>>> In that case there are a number of JVM options that can be tuned....
>>>>>
>>>>> Best,
>>>>> Erick
>>>>>
>>>>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>>>
>>>>>>
>>>>>> Solr 5.4.1 with embedded jetty single shard - NRT
>>>>>>
>>>>>> Looking in logs, noticed that there are high QTimes for Queries and
>>>>>> round
>>>>>> same time high response times for updates. These are not during
>>>>>> "commit"
>>>>>> or
>>>>>> "softCommit" but when client application is sending updates. Wondering
>>>>>> how
>>>>>> updates could impact query performance. What are the options for
>>>>>> tuning?
>>>>>> Thanks.
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
Hmmm, not sure, and also not sure what to suggest next. QTimes
measure only the search time, not, say, time waiting for the request to get
serviced.
I'm afraid the next suggestion is to throw a profiler at it 'cause nothing jumps
out at me..'
Best,
Erick
On Fri, Sep 16, 2016 at 10:23 AM, Rallavagu <ra...@gmail.com> wrote:
> Comments in line...
>
> On 9/16/16 10:15 AM, Erick Erickson wrote:
>>
>> Well, the next thing I'd look at is CPU activity. If you're flooding the
>> system
>> with updates there'll be CPU contention.
>
>
> Monitoring does not suggest any high CPU but as you can see from vmstat
> output "user" cpu is a bit high during updates that are taking time (34
> user, 65 idle).
>
>>
>> And there are a number of things you can do that make updates in
>> particular
>> much less efficient, from committing very frequently (sometimes combined
>> with excessive autowarm parameters) and the like.
>
>
> softCommit is set to 10 minutes, autowarm count is set to 0 and commit is
> set to 15 sec for NRT.
>
>>
>> There are a series of ideas that might trigger an "aha" moment:
>> https://wiki.apache.org/solr/SolrPerformanceFactors
>
>
> Reviewed this document and made few changes accordingly a while ago.
>>
>>
>> But the crude measure is just to look at CPU usage when updates happen, or
>> just before. Are you running hot with queries alone then add an update
>> burden?
>
>
> Essentially, it is high QTimes for queries got me looking into logs, system
> etc and I could correlate updates slowness and searching slowness. Some
> other time QTimes go high is right after softCommit which is expected.
>
> Wondering what causes update threads wait and if it has any impact on search
> at all. I had couple of more CPUs added but I still see similar behavior.
>
> Thanks.
>
>
>>
>> Best,
>> Erick
>>
>> On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com> wrote:
>>>
>>> Erick,
>>>
>>> Was monitoring GC activity and couldn't align GC pauses to this behavior.
>>> Also, the vmstat shows no swapping or cpu I/O wait. However, whenever I
>>> see
>>> high update response times (corresponding high QTimes for searches)
>>> vmstat
>>> shows as series of number of "waiting to runnable" processes in "r"
>>> column
>>> of "procs" section.
>>>
>>>
>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
>>>
>>> procs -----------------------memory---------------------- ---swap--
>>> -----io---- -system-- --------cpu-------- -----timestamp-----
>>> r b swpd free inact active si so bi
>>> bo
>>> in cs us sy id wa st CDT
>>> 2 0 71068 18688496 2526604 24204440 0 0 0
>>> 0
>>> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
>>> 1 0 71068 18688180 2526600 24204568 0 0 0
>>> 0
>>> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
>>> 1 0 71068 18687928 2526600 24204568 0 0 0
>>> 0
>>> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
>>> 1 0 71068 18687800 2526600 24204572 0 0 0
>>> 0
>>> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
>>> 1 0 71068 18687164 2527116 24204844 0 0 0
>>> 0
>>> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
>>> 1 0 71068 18686944 2527108 24204908 0 0 0
>>> 52
>>> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
>>> 12 1 71068 18682676 2528560 24207116 0 0 0
>>> 280
>>> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
>>> 2 1 71068 18651340 2530820 24233368 0 0 0
>>> 1052
>>> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
>>> 5 0 71068 18648600 2530112 24235060 0 0 0
>>> 1988
>>> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
>>> 9 1 71068 18647804 2530580 24236076 0 0 0
>>> 1688
>>> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
>>> 1 0 71068 18647628 2530364 24236256 0 0 0
>>> 680
>>> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
>>> 1 0 71068 18646344 2531204 24236536 0 0 0
>>> 44
>>> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
>>> 2 0 71068 18644460 2532196 24237440 0 0 0
>>> 0
>>> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
>>> 0 0 71068 18661900 2531724 24218764 0 0 0
>>> 0
>>> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
>>> 2 0 71068 18649400 2532228 24229800 0 0 0
>>> 0
>>> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
>>> 0 0 71068 18648280 2533440 24230300 0 0 0
>>> 108
>>> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
>>> 0 0 71068 18648156 2533212 24230684 0 0 0
>>> 12
>>> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
>>>
>>>
>>> Captured stack trace including timing for one of the update threads.
>>>
>>>
>>> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time =
>>> 15
>>> ms, total time = 30782 ms)
>>> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total time
>>> =
>>> 30767 ms)
>>> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total
>>> time =
>>> 30767 ms)
>>> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms,
>>> total
>>> time = 30767 ms)
>>> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0 ms,
>>> total time = 30767 ms)
>>> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms,
>>> total
>>> time = 30767 ms)
>>> org.apache.solr.handler.RequestHandlerBase:handleRequest:156
>>> (method
>>> time = 0 ms, total time = 30767 ms)
>>>
>>> org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
>>> (method time = 0 ms, total time = 30767 ms)
>>> org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method
>>> time
>>> = 0 ms, total time = 23737 ms)
>>> org.apache.solr.handler.loader.XMLLoader:load:178 (method time =
>>> 0
>>> ms, total time = 23737 ms)
>>> org.apache.solr.handler.loader.XMLLoader:processUpdate:251
>>> (method
>>> time = 0 ms, total time = 23737 ms)
>>>
>>>
>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
>>> (method time = 0 ms, total time = 23737 ms)
>>>
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
>>> (method time = 0 ms, total time = 23737 ms)
>>>
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
>>> (method time = 0 ms, total time = 23477 ms)
>>>
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
>>> (method time = 0 ms, total time = 51 ms)
>>>
>>> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
>>> (method time = 51 ms, total time = 51 ms)
>>>
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
>>> (method time = 0 ms, total time = 23426 ms)
>>>
>>> org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
>>> (method time = 0 ms, total time = 23426 ms)
>>>
>>> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69 (method
>>> time = 0 ms, total time = 23426 ms)
>>> org.apache.solr.update.DirectUpdateHandler2:addDoc:169
>>> (method time = 0 ms, total time = 23426 ms)
>>>
>>> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time = 0
>>> ms,
>>> total time = 23426 ms)
>>>
>>> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method
>>> time
>>> = 0 ms, total time = 23426 ms)
>>>
>>> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time = 0
>>> ms,
>>> total time = 8551 ms)
>>>
>>> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time =
>>> 0
>>> ms, total time = 8551 ms)
>>>
>>> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234
>>> (method
>>> time = 0 ms, total time = 8551 ms)
>>>
>>> org.apache.lucene.index.DefaultIndexingChain:processDocument:300 (method
>>> time = 0 ms, total time = 8551 ms)
>>>
>>> org.apache.lucene.index.DefaultIndexingChain:processField:344 (method
>>> time =
>>> 0 ms, total time = 8551 ms)
>>>
>>> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613 (method
>>> time = 0 ms, total time = 4098 ms)
>>>
>>> org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
>>> (method time = 0 ms, total time = 4098 ms)
>>>
>>> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627
>>> (method
>>> time = 0 ms, total time = 4098 ms)
>>>
>>> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time =
>>> 0
>>> ms, total time = 4098 ms)
>>>
>>> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms,
>>> total
>>> time = 4098 ms)
>>>
>>> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms,
>>> total
>>> time = 4098 ms)
>>>
>>> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time =
>>> 0
>>> ms, total time = 4098 ms)
>>>
>>> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0 ms,
>>> total time = 4098 ms)
>>>
>>> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total
>>> time
>>> = 4098 ms)
>>>
>>> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms,
>>> total
>>> time = 4098 ms)
>>>
>>> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method
>>> time
>>> = 0 ms, total time = 4453 ms)
>>>
>>> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time = 0
>>> ms,
>>> total time = 4453 ms)
>>>
>>> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method time
>>> =
>>> 4453 ms, total time = 4453 ms)
>>> org.apache.solr.update.UpdateLog:add:412 (method time
>>> =
>>> 0 ms, total time = 14875 ms)
>>> org.apache.solr.update.UpdateLog:add:421 (method
>>> time =
>>> 14875 ms, total time = 14875 ms)
>>> org.apache.solr.update.SolrCmdDistributor:distribAdd:207
>>> (method time = 0 ms, total time = 260 ms)
>>> org.apache.solr.update.SolrCmdDistributor:submit:289
>>> (method
>>> time = 0 ms, total time = 260 ms)
>>> org.apache.solr.update.SolrCmdDistributor:doRequest:296
>>> (method time = 0 ms, total time = 260 ms)
>>> org.apache.solr.client.solrj.SolrClient:request:1220
>>> (method
>>> time = 0 ms, total time = 260 ms)
>>>
>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
>>> (method time = 0 ms, total time = 260 ms)
>>>
>>>
>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
>>> (method time = 0 ms, total time = 260 ms)
>>>
>>>
>>> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
>>> (method time = 0 ms, total time = 260 ms)
>>>
>>> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40 (method
>>> time = 260 ms, total time = 260 ms)
>>>
>>>
>>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
>>> (method time = 0 ms, total time = 7030 ms)
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
>>> (method time = 0 ms, total time = 7030 ms)
>>>
>>> org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
>>> (method time = 0 ms, total time = 7030 ms)
>>> org.apache.solr.update.SolrCmdDistributor:finish:90 (method
>>> time
>>> = 0 ms, total time = 7030 ms)
>>>
>>> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method
>>> time
>>> = 0 ms, total time = 7030 ms)
>>>
>>> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107
>>> (method
>>> time = 0 ms, total time = 7030 ms)
>>>
>>>
>>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
>>> (method time = 0 ms, total time = 7030 ms)
>>> java.lang.Object:wait (method time = 7030 ms, total time =
>>> 7030 ms)
>>>
>>>
>>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
>>>
>>> Appears there could be thread waiting but I am not sure how would this
>>> impact searching.
>>>
>>> Thanks
>>>
>>> On 9/16/16 8:42 AM, Erick Erickson wrote:
>>>>
>>>>
>>>> First thing I'd look is whether you're _also_ seeing stop-the-world GC
>>>> pauses.
>>>> In that case there are a number of JVM options that can be tuned....
>>>>
>>>> Best,
>>>> Erick
>>>>
>>>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>>
>>>>>
>>>>> Solr 5.4.1 with embedded jetty single shard - NRT
>>>>>
>>>>> Looking in logs, noticed that there are high QTimes for Queries and
>>>>> round
>>>>> same time high response times for updates. These are not during
>>>>> "commit"
>>>>> or
>>>>> "softCommit" but when client application is sending updates. Wondering
>>>>> how
>>>>> updates could impact query performance. What are the options for
>>>>> tuning?
>>>>> Thanks.
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
Comments in line...
On 9/16/16 10:15 AM, Erick Erickson wrote:
> Well, the next thing I'd look at is CPU activity. If you're flooding the system
> with updates there'll be CPU contention.
Monitoring does not suggest any high CPU but as you can see from vmstat
output "user" cpu is a bit high during updates that are taking time (34
user, 65 idle).
>
> And there are a number of things you can do that make updates in particular
> much less efficient, from committing very frequently (sometimes combined
> with excessive autowarm parameters) and the like.
softCommit is set to 10 minutes, autowarm count is set to 0 and commit
is set to 15 sec for NRT.
>
> There are a series of ideas that might trigger an "aha" moment:
> https://wiki.apache.org/solr/SolrPerformanceFactors
Reviewed this document and made few changes accordingly a while ago.
>
> But the crude measure is just to look at CPU usage when updates happen, or
> just before. Are you running hot with queries alone then add an update burden?
Essentially, it is high QTimes for queries got me looking into logs,
system etc and I could correlate updates slowness and searching
slowness. Some other time QTimes go high is right after softCommit which
is expected.
Wondering what causes update threads wait and if it has any impact on
search at all. I had couple of more CPUs added but I still see similar
behavior.
Thanks.
>
> Best,
> Erick
>
> On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com> wrote:
>> Erick,
>>
>> Was monitoring GC activity and couldn't align GC pauses to this behavior.
>> Also, the vmstat shows no swapping or cpu I/O wait. However, whenever I see
>> high update response times (corresponding high QTimes for searches) vmstat
>> shows as series of number of "waiting to runnable" processes in "r" column
>> of "procs" section.
>>
>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
>>
>> procs -----------------------memory---------------------- ---swap--
>> -----io---- -system-- --------cpu-------- -----timestamp-----
>> r b swpd free inact active si so bi bo
>> in cs us sy id wa st CDT
>> 2 0 71068 18688496 2526604 24204440 0 0 0 0
>> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
>> 1 0 71068 18688180 2526600 24204568 0 0 0 0
>> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
>> 1 0 71068 18687928 2526600 24204568 0 0 0 0
>> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
>> 1 0 71068 18687800 2526600 24204572 0 0 0 0
>> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
>> 1 0 71068 18687164 2527116 24204844 0 0 0 0
>> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
>> 1 0 71068 18686944 2527108 24204908 0 0 0 52
>> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
>> 12 1 71068 18682676 2528560 24207116 0 0 0 280
>> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
>> 2 1 71068 18651340 2530820 24233368 0 0 0 1052
>> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
>> 5 0 71068 18648600 2530112 24235060 0 0 0 1988
>> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
>> 9 1 71068 18647804 2530580 24236076 0 0 0 1688
>> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
>> 1 0 71068 18647628 2530364 24236256 0 0 0 680
>> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
>> 1 0 71068 18646344 2531204 24236536 0 0 0 44
>> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
>> 2 0 71068 18644460 2532196 24237440 0 0 0 0
>> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
>> 0 0 71068 18661900 2531724 24218764 0 0 0 0
>> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
>> 2 0 71068 18649400 2532228 24229800 0 0 0 0
>> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
>> 0 0 71068 18648280 2533440 24230300 0 0 0 108
>> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
>> 0 0 71068 18648156 2533212 24230684 0 0 0 12
>> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
>>
>>
>> Captured stack trace including timing for one of the update threads.
>>
>>
>> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time = 15
>> ms, total time = 30782 ms)
>> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total time =
>> 30767 ms)
>> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total time =
>> 30767 ms)
>> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms, total
>> time = 30767 ms)
>> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0 ms,
>> total time = 30767 ms)
>> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms, total
>> time = 30767 ms)
>> org.apache.solr.handler.RequestHandlerBase:handleRequest:156 (method
>> time = 0 ms, total time = 30767 ms)
>>
>> org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
>> (method time = 0 ms, total time = 30767 ms)
>> org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method time
>> = 0 ms, total time = 23737 ms)
>> org.apache.solr.handler.loader.XMLLoader:load:178 (method time = 0
>> ms, total time = 23737 ms)
>> org.apache.solr.handler.loader.XMLLoader:processUpdate:251 (method
>> time = 0 ms, total time = 23737 ms)
>>
>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
>> (method time = 0 ms, total time = 23737 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
>> (method time = 0 ms, total time = 23737 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
>> (method time = 0 ms, total time = 23477 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
>> (method time = 0 ms, total time = 51 ms)
>>
>> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
>> (method time = 51 ms, total time = 51 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
>> (method time = 0 ms, total time = 23426 ms)
>>
>> org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
>> (method time = 0 ms, total time = 23426 ms)
>>
>> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69 (method
>> time = 0 ms, total time = 23426 ms)
>> org.apache.solr.update.DirectUpdateHandler2:addDoc:169
>> (method time = 0 ms, total time = 23426 ms)
>>
>> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time = 0 ms,
>> total time = 23426 ms)
>>
>> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method time
>> = 0 ms, total time = 23426 ms)
>>
>> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time = 0 ms,
>> total time = 8551 ms)
>>
>> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time = 0
>> ms, total time = 8551 ms)
>>
>> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234 (method
>> time = 0 ms, total time = 8551 ms)
>>
>> org.apache.lucene.index.DefaultIndexingChain:processDocument:300 (method
>> time = 0 ms, total time = 8551 ms)
>>
>> org.apache.lucene.index.DefaultIndexingChain:processField:344 (method time =
>> 0 ms, total time = 8551 ms)
>>
>> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613 (method
>> time = 0 ms, total time = 4098 ms)
>>
>> org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
>> (method time = 0 ms, total time = 4098 ms)
>>
>> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627 (method
>> time = 0 ms, total time = 4098 ms)
>>
>> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time = 0
>> ms, total time = 4098 ms)
>>
>> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms, total
>> time = 4098 ms)
>>
>> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms, total
>> time = 4098 ms)
>>
>> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time = 0
>> ms, total time = 4098 ms)
>>
>> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0 ms,
>> total time = 4098 ms)
>>
>> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total time
>> = 4098 ms)
>>
>> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms, total
>> time = 4098 ms)
>>
>> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method time
>> = 0 ms, total time = 4453 ms)
>>
>> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time = 0 ms,
>> total time = 4453 ms)
>>
>> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method time =
>> 4453 ms, total time = 4453 ms)
>> org.apache.solr.update.UpdateLog:add:412 (method time =
>> 0 ms, total time = 14875 ms)
>> org.apache.solr.update.UpdateLog:add:421 (method time =
>> 14875 ms, total time = 14875 ms)
>> org.apache.solr.update.SolrCmdDistributor:distribAdd:207
>> (method time = 0 ms, total time = 260 ms)
>> org.apache.solr.update.SolrCmdDistributor:submit:289 (method
>> time = 0 ms, total time = 260 ms)
>> org.apache.solr.update.SolrCmdDistributor:doRequest:296
>> (method time = 0 ms, total time = 260 ms)
>> org.apache.solr.client.solrj.SolrClient:request:1220 (method
>> time = 0 ms, total time = 260 ms)
>>
>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
>> (method time = 0 ms, total time = 260 ms)
>>
>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
>> (method time = 0 ms, total time = 260 ms)
>>
>> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
>> (method time = 0 ms, total time = 260 ms)
>>
>> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40 (method
>> time = 260 ms, total time = 260 ms)
>>
>> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
>> (method time = 0 ms, total time = 7030 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
>> (method time = 0 ms, total time = 7030 ms)
>>
>> org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
>> (method time = 0 ms, total time = 7030 ms)
>> org.apache.solr.update.SolrCmdDistributor:finish:90 (method time
>> = 0 ms, total time = 7030 ms)
>>
>> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method time
>> = 0 ms, total time = 7030 ms)
>>
>> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107 (method
>> time = 0 ms, total time = 7030 ms)
>>
>> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
>> (method time = 0 ms, total time = 7030 ms)
>> java.lang.Object:wait (method time = 7030 ms, total time =
>> 7030 ms)
>>
>> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
>>
>> Appears there could be thread waiting but I am not sure how would this
>> impact searching.
>>
>> Thanks
>>
>> On 9/16/16 8:42 AM, Erick Erickson wrote:
>>>
>>> First thing I'd look is whether you're _also_ seeing stop-the-world GC
>>> pauses.
>>> In that case there are a number of JVM options that can be tuned....
>>>
>>> Best,
>>> Erick
>>>
>>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
>>>>
>>>> Solr 5.4.1 with embedded jetty single shard - NRT
>>>>
>>>> Looking in logs, noticed that there are high QTimes for Queries and round
>>>> same time high response times for updates. These are not during "commit"
>>>> or
>>>> "softCommit" but when client application is sending updates. Wondering
>>>> how
>>>> updates could impact query performance. What are the options for tuning?
>>>> Thanks.
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
Well, the next thing I'd look at is CPU activity. If you're flooding the system
with updates there'll be CPU contention.
And there are a number of things you can do that make updates in particular
much less efficient, from committing very frequently (sometimes combined
with excessive autowarm parameters) and the like.
There are a series of ideas that might trigger an "aha" moment:
https://wiki.apache.org/solr/SolrPerformanceFactors
But the crude measure is just to look at CPU usage when updates happen, or
just before. Are you running hot with queries alone then add an update burden?
Best,
Erick
On Fri, Sep 16, 2016 at 9:19 AM, Rallavagu <ra...@gmail.com> wrote:
> Erick,
>
> Was monitoring GC activity and couldn't align GC pauses to this behavior.
> Also, the vmstat shows no swapping or cpu I/O wait. However, whenever I see
> high update response times (corresponding high QTimes for searches) vmstat
> shows as series of number of "waiting to runnable" processes in "r" column
> of "procs" section.
>
> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
>
> procs -----------------------memory---------------------- ---swap--
> -----io---- -system-- --------cpu-------- -----timestamp-----
> r b swpd free inact active si so bi bo
> in cs us sy id wa st CDT
> 2 0 71068 18688496 2526604 24204440 0 0 0 0
> 1433 462 27 1 73 0 0 2016-09-16 11:02:32
> 1 0 71068 18688180 2526600 24204568 0 0 0 0
> 1388 404 26 1 74 0 0 2016-09-16 11:02:33
> 1 0 71068 18687928 2526600 24204568 0 0 0 0
> 1354 401 25 0 75 0 0 2016-09-16 11:02:34
> 1 0 71068 18687800 2526600 24204572 0 0 0 0
> 1311 397 25 0 74 0 0 2016-09-16 11:02:35
> 1 0 71068 18687164 2527116 24204844 0 0 0 0
> 1770 702 31 1 69 0 0 2016-09-16 11:02:36
> 1 0 71068 18686944 2527108 24204908 0 0 0 52
> 1266 421 26 0 74 0 0 2016-09-16 11:02:37
> 12 1 71068 18682676 2528560 24207116 0 0 0 280
> 2388 934 34 1 65 0 0 2016-09-16 11:02:38
> 2 1 71068 18651340 2530820 24233368 0 0 0 1052
> 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
> 5 0 71068 18648600 2530112 24235060 0 0 0 1988
> 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
> 9 1 71068 18647804 2530580 24236076 0 0 0 1688
> 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
> 1 0 71068 18647628 2530364 24236256 0 0 0 680
> 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
> 1 0 71068 18646344 2531204 24236536 0 0 0 44
> 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
> 2 0 71068 18644460 2532196 24237440 0 0 0 0
> 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
> 0 0 71068 18661900 2531724 24218764 0 0 0 0
> 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
> 2 0 71068 18649400 2532228 24229800 0 0 0 0
> 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
> 0 0 71068 18648280 2533440 24230300 0 0 0 108
> 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
> 0 0 71068 18648156 2533212 24230684 0 0 0 12
> 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
>
>
> Captured stack trace including timing for one of the update threads.
>
>
> org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time = 15
> ms, total time = 30782 ms)
> Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total time =
> 30767 ms)
> Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total time =
> 30767 ms)
> org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms, total
> time = 30767 ms)
> org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0 ms,
> total time = 30767 ms)
> org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms, total
> time = 30767 ms)
> org.apache.solr.handler.RequestHandlerBase:handleRequest:156 (method
> time = 0 ms, total time = 30767 ms)
>
> org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
> (method time = 0 ms, total time = 30767 ms)
> org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method time
> = 0 ms, total time = 23737 ms)
> org.apache.solr.handler.loader.XMLLoader:load:178 (method time = 0
> ms, total time = 23737 ms)
> org.apache.solr.handler.loader.XMLLoader:processUpdate:251 (method
> time = 0 ms, total time = 23737 ms)
>
> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
> (method time = 0 ms, total time = 23737 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
> (method time = 0 ms, total time = 23737 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
> (method time = 0 ms, total time = 23477 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
> (method time = 0 ms, total time = 51 ms)
>
> org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
> (method time = 51 ms, total time = 51 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
> (method time = 0 ms, total time = 23426 ms)
>
> org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
> (method time = 0 ms, total time = 23426 ms)
>
> org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69 (method
> time = 0 ms, total time = 23426 ms)
> org.apache.solr.update.DirectUpdateHandler2:addDoc:169
> (method time = 0 ms, total time = 23426 ms)
>
> org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time = 0 ms,
> total time = 23426 ms)
>
> org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method time
> = 0 ms, total time = 23426 ms)
>
> org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time = 0 ms,
> total time = 8551 ms)
>
> org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time = 0
> ms, total time = 8551 ms)
>
> org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234 (method
> time = 0 ms, total time = 8551 ms)
>
> org.apache.lucene.index.DefaultIndexingChain:processDocument:300 (method
> time = 0 ms, total time = 8551 ms)
>
> org.apache.lucene.index.DefaultIndexingChain:processField:344 (method time =
> 0 ms, total time = 8551 ms)
>
> org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613 (method
> time = 0 ms, total time = 4098 ms)
>
> org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
> (method time = 0 ms, total time = 4098 ms)
>
> org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627 (method
> time = 0 ms, total time = 4098 ms)
>
> org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time = 0
> ms, total time = 4098 ms)
>
> org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms, total
> time = 4098 ms)
>
> org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms, total
> time = 4098 ms)
>
> org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time = 0
> ms, total time = 4098 ms)
>
> org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0 ms,
> total time = 4098 ms)
>
> org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total time
> = 4098 ms)
>
> org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms, total
> time = 4098 ms)
>
> org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method time
> = 0 ms, total time = 4453 ms)
>
> org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time = 0 ms,
> total time = 4453 ms)
>
> org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method time =
> 4453 ms, total time = 4453 ms)
> org.apache.solr.update.UpdateLog:add:412 (method time =
> 0 ms, total time = 14875 ms)
> org.apache.solr.update.UpdateLog:add:421 (method time =
> 14875 ms, total time = 14875 ms)
> org.apache.solr.update.SolrCmdDistributor:distribAdd:207
> (method time = 0 ms, total time = 260 ms)
> org.apache.solr.update.SolrCmdDistributor:submit:289 (method
> time = 0 ms, total time = 260 ms)
> org.apache.solr.update.SolrCmdDistributor:doRequest:296
> (method time = 0 ms, total time = 260 ms)
> org.apache.solr.client.solrj.SolrClient:request:1220 (method
> time = 0 ms, total time = 260 ms)
>
> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
> (method time = 0 ms, total time = 260 ms)
>
> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
> (method time = 0 ms, total time = 260 ms)
>
> org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
> (method time = 0 ms, total time = 260 ms)
>
> org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40 (method
> time = 260 ms, total time = 260 ms)
>
> org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
> (method time = 0 ms, total time = 7030 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
> (method time = 0 ms, total time = 7030 ms)
>
> org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
> (method time = 0 ms, total time = 7030 ms)
> org.apache.solr.update.SolrCmdDistributor:finish:90 (method time
> = 0 ms, total time = 7030 ms)
>
> org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method time
> = 0 ms, total time = 7030 ms)
>
> org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107 (method
> time = 0 ms, total time = 7030 ms)
>
> org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
> (method time = 0 ms, total time = 7030 ms)
> java.lang.Object:wait (method time = 7030 ms, total time =
> 7030 ms)
>
> https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
>
> Appears there could be thread waiting but I am not sure how would this
> impact searching.
>
> Thanks
>
> On 9/16/16 8:42 AM, Erick Erickson wrote:
>>
>> First thing I'd look is whether you're _also_ seeing stop-the-world GC
>> pauses.
>> In that case there are a number of JVM options that can be tuned....
>>
>> Best,
>> Erick
>>
>> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
>>>
>>> Solr 5.4.1 with embedded jetty single shard - NRT
>>>
>>> Looking in logs, noticed that there are high QTimes for Queries and round
>>> same time high response times for updates. These are not during "commit"
>>> or
>>> "softCommit" but when client application is sending updates. Wondering
>>> how
>>> updates could impact query performance. What are the options for tuning?
>>> Thanks.
Re: slow updates/searches
Posted by Rallavagu <ra...@gmail.com>.
Erick,
Was monitoring GC activity and couldn't align GC pauses to this
behavior. Also, the vmstat shows no swapping or cpu I/O wait. However,
whenever I see high update response times (corresponding high QTimes for
searches) vmstat shows as series of number of "waiting to runnable"
processes in "r" column of "procs" section.
https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.05.51%20AM.png
procs -----------------------memory---------------------- ---swap--
-----io---- -system-- --------cpu-------- -----timestamp-----
r b swpd free inact active si so
bi bo in cs us sy id wa st CDT
2 0 71068 18688496 2526604 24204440 0 0
0 0 1433 462 27 1 73 0 0 2016-09-16 11:02:32
1 0 71068 18688180 2526600 24204568 0 0
0 0 1388 404 26 1 74 0 0 2016-09-16 11:02:33
1 0 71068 18687928 2526600 24204568 0 0
0 0 1354 401 25 0 75 0 0 2016-09-16 11:02:34
1 0 71068 18687800 2526600 24204572 0 0
0 0 1311 397 25 0 74 0 0 2016-09-16 11:02:35
1 0 71068 18687164 2527116 24204844 0 0
0 0 1770 702 31 1 69 0 0 2016-09-16 11:02:36
1 0 71068 18686944 2527108 24204908 0 0
0 52 1266 421 26 0 74 0 0 2016-09-16 11:02:37
12 1 71068 18682676 2528560 24207116 0 0
0 280 2388 934 34 1 65 0 0 2016-09-16 11:02:38
2 1 71068 18651340 2530820 24233368 0 0
0 1052 10258 5696 82 5 13 0 0 2016-09-16 11:02:39
5 0 71068 18648600 2530112 24235060 0 0
0 1988 7261 3644 84 2 13 1 0 2016-09-16 11:02:40
9 1 71068 18647804 2530580 24236076 0 0
0 1688 7031 3575 84 2 13 1 0 2016-09-16 11:02:41
1 0 71068 18647628 2530364 24236256 0 0
0 680 7065 4463 61 3 35 1 0 2016-09-16 11:02:42
1 0 71068 18646344 2531204 24236536 0 0
0 44 6422 4922 35 3 63 0 0 2016-09-16 11:02:43
2 0 71068 18644460 2532196 24237440 0 0
0 0 6561 5056 25 3 72 0 0 2016-09-16 11:02:44
0 0 71068 18661900 2531724 24218764 0 0
0 0 7312 10050 11 3 86 0 0 2016-09-16 11:02:45
2 0 71068 18649400 2532228 24229800 0 0
0 0 7211 6222 34 3 63 0 0 2016-09-16 11:02:46
0 0 71068 18648280 2533440 24230300 0 0
0 108 3936 3381 20 1 79 0 0 2016-09-16 11:02:47
0 0 71068 18648156 2533212 24230684 0 0
0 12 1279 1681 2 0 97 0 0 2016-09-16 11:02:48
Captured stack trace including timing for one of the update threads.
org.eclipse.jetty.server.handler.ContextHandler:doHandle (method time =
15 ms, total time = 30782 ms)
Filter - SolrDispatchFilter:doFilter:181 (method time = 0 ms, total
time = 30767 ms)
Filter - SolrDispatchFilter:doFilter:223 (method time = 0 ms, total
time = 30767 ms)
org.apache.solr.servlet.HttpSolrCall:call:457 (method time = 0 ms,
total time = 30767 ms)
org.apache.solr.servlet.HttpSolrCall:execute:658 (method time = 0
ms, total time = 30767 ms)
org.apache.solr.core.SolrCore:execute:2073 (method time = 0 ms,
total time = 30767 ms)
org.apache.solr.handler.RequestHandlerBase:handleRequest:156
(method time = 0 ms, total time = 30767 ms)
org.apache.solr.handler.ContentStreamHandlerBase:handleRequestBody:70
(method time = 0 ms, total time = 30767 ms)
org.apache.solr.handler.UpdateRequestHandler$1:load:95 (method
time = 0 ms, total time = 23737 ms)
org.apache.solr.handler.loader.XMLLoader:load:178 (method time
= 0 ms, total time = 23737 ms)
org.apache.solr.handler.loader.XMLLoader:processUpdate:251
(method time = 0 ms, total time = 23737 ms)
org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:processAdd:104
(method time = 0 ms, total time = 23737 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:processAdd:702
(method time = 0 ms, total time = 23737 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:versionAdd:1011
(method time = 0 ms, total time = 23477 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:getUpdatedDocument:1114
(method time = 0 ms, total time = 51 ms)
org.apache.solr.update.processor.AtomicUpdateDocumentMerger:merge:110
(method time = 51 ms, total time = 51 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:doLocalAdd:924
(method time = 0 ms, total time = 23426 ms)
org.apache.solr.update.processor.UpdateRequestProcessor:processAdd:49
(method time = 0 ms, total time = 23426 ms)
org.apache.solr.update.processor.RunUpdateProcessor:processAdd:69
(method time = 0 ms, total time = 23426 ms)
org.apache.solr.update.DirectUpdateHandler2:addDoc:169
(method time = 0 ms, total time = 23426 ms)
org.apache.solr.update.DirectUpdateHandler2:addDoc0:207 (method time = 0
ms, total time = 23426 ms)
org.apache.solr.update.DirectUpdateHandler2:doNormalUpdate:275 (method
time = 0 ms, total time = 23426 ms)
org.apache.lucene.index.IndexWriter:updateDocument:1477 (method time = 0
ms, total time = 8551 ms)
org.apache.lucene.index.DocumentsWriter:updateDocument:450 (method time
= 0 ms, total time = 8551 ms)
org.apache.lucene.index.DocumentsWriterPerThread:updateDocument:234
(method time = 0 ms, total time = 8551 ms)
org.apache.lucene.index.DefaultIndexingChain:processDocument:300 (method
time = 0 ms, total time = 8551 ms)
org.apache.lucene.index.DefaultIndexingChain:processField:344 (method
time = 0 ms, total time = 8551 ms)
org.apache.lucene.index.DefaultIndexingChain$PerField:invert:613 (method
time = 0 ms, total time = 4098 ms)
org.apache.lucene.analysis.util.FilteringTokenFilter:incrementToken:51
(method time = 0 ms, total time = 4098 ms)
org.apache.lucene.analysis.synonym.SynonymFilter:incrementToken:627
(method time = 0 ms, total time = 4098 ms)
org.apache.lucene.analysis.synonym.SynonymFilter:parse:396 (method time
= 0 ms, total time = 4098 ms)
org.apache.lucene.util.fst.FST:findTargetArc:1186 (method time = 0 ms,
total time = 4098 ms)
org.apache.lucene.util.fst.FST:findTargetArc:1270 (method time = 0 ms,
total time = 4098 ms)
org.apache.lucene.util.fst.FST:readFirstRealTargetArc:992 (method time =
0 ms, total time = 4098 ms)
org.apache.lucene.util.fst.FST:readNextRealArc:1085 (method time = 0 ms,
total time = 4098 ms)
org.apache.lucene.util.fst.FST:readLabel:636 (method time = 0 ms, total
time = 4098 ms)
org.apache.lucene.store.DataInput:readVInt:125 (method time = 4098 ms,
total time = 4098 ms)
org.apache.lucene.index.DefaultIndexingChain:getOrAddField:484 (method
time = 0 ms, total time = 4453 ms)
org.apache.lucene.index.FieldInfos$Builder:getOrAdd:317 (method time = 0
ms, total time = 4453 ms)
org.apache.lucene.index.FieldInfos$FieldNumbers:addOrGet:218 (method
time = 4453 ms, total time = 4453 ms)
org.apache.solr.update.UpdateLog:add:412 (method
time = 0 ms, total time = 14875 ms)
org.apache.solr.update.UpdateLog:add:421 (method
time = 14875 ms, total time = 14875 ms)
org.apache.solr.update.SolrCmdDistributor:distribAdd:207
(method time = 0 ms, total time = 260 ms)
org.apache.solr.update.SolrCmdDistributor:submit:289
(method time = 0 ms, total time = 260 ms)
org.apache.solr.update.SolrCmdDistributor:doRequest:296
(method time = 0 ms, total time = 260 ms)
org.apache.solr.client.solrj.SolrClient:request:1220
(method time = 0 ms, total time = 260 ms)
org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:request:382
(method time = 0 ms, total time = 260 ms)
org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:addRunner:324
(method time = 0 ms, total time = 260 ms)
org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor:execute:215
(method time = 0 ms, total time = 260 ms)
org.apache.solr.common.util.SolrjNamedThreadFactory:newThread:40 (method
time = 260 ms, total time = 260 ms)
org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor:finish:183
(method time = 0 ms, total time = 7030 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:finish:1626
(method time = 0 ms, total time = 7030 ms)
org.apache.solr.update.processor.DistributedUpdateProcessor:doFinish:778
(method time = 0 ms, total time = 7030 ms)
org.apache.solr.update.SolrCmdDistributor:finish:90 (method
time = 0 ms, total time = 7030 ms)
org.apache.solr.update.SolrCmdDistributor:blockAndDoRetries:232 (method
time = 0 ms, total time = 7030 ms)
org.apache.solr.update.StreamingSolrClients:blockUntilFinished:107
(method time = 0 ms, total time = 7030 ms)
org.apache.solr.client.solrj.impl.ConcurrentUpdateSolrClient:blockUntilFinished:429
(method time = 0 ms, total time = 7030 ms)
java.lang.Object:wait (method time = 7030 ms, total time
= 7030 ms)
https://dl.dropboxusercontent.com/u/39813705/Screen%20Shot%202016-09-16%20at%209.18.52%20AM.png
Appears there could be thread waiting but I am not sure how would this
impact searching.
Thanks
On 9/16/16 8:42 AM, Erick Erickson wrote:
> First thing I'd look is whether you're _also_ seeing stop-the-world GC pauses.
> In that case there are a number of JVM options that can be tuned....
>
> Best,
> Erick
>
> On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
>> Solr 5.4.1 with embedded jetty single shard - NRT
>>
>> Looking in logs, noticed that there are high QTimes for Queries and round
>> same time high response times for updates. These are not during "commit" or
>> "softCommit" but when client application is sending updates. Wondering how
>> updates could impact query performance. What are the options for tuning?
>> Thanks.
Re: slow updates/searches
Posted by Erick Erickson <er...@gmail.com>.
First thing I'd look is whether you're _also_ seeing stop-the-world GC pauses.
In that case there are a number of JVM options that can be tuned....
Best,
Erick
On Fri, Sep 16, 2016 at 8:40 AM, Rallavagu <ra...@gmail.com> wrote:
> Solr 5.4.1 with embedded jetty single shard - NRT
>
> Looking in logs, noticed that there are high QTimes for Queries and round
> same time high response times for updates. These are not during "commit" or
> "softCommit" but when client application is sending updates. Wondering how
> updates could impact query performance. What are the options for tuning?
> Thanks.