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 <rallav...@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 <rallav...@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.

Reply via email to