Hey guys, Based on my understanding of the problem we are encountering, I feel we've been able to reduce the likelihood of this issue by making the following changes to our app's usage of SolrCloud:
1) We increased our document batch size to 200 from 10 - our app batches updates to reduce HTTP requests/overhead. The theory is increasing the batch size reduces the likelihood of this issue happening. 2) We reduced to 1 application node sending updates to SolrCloud - we write Solr updates to Redis, and have previously had 4 application nodes pushing the updates to Solr (popping off the Redis queue). Reducing the number of nodes pushing to Solr reduces the concurrency on SolrCloud. 3) Less threads pushing to SolrCloud - due to the increase in batch size, we were able to go down to 5 update threads on the update-pushing-app (from 10 threads). To be clear the above only reduces the likelihood of the issue happening, and DOES NOT actually resolve the issue at hand. If we happen to encounter issues with the above 3 changes, the next steps (I could use some advice on) are: 1) Increase the number of shards (2x) - the theory here is this reduces the locking on shards because there are more shards. Am I onto something here, or will this not help at all? 2) Use CloudSolrServer - currently we have a plain-old least-connection HTTP VIP. If we go "direct" to what we need to update, this will reduce concurrency in SolrCloud a bit. Thoughts? Thanks all! Cheers, Tim On 6 September 2013 14:47, Tim Vaillancourt <t...@elementspace.com> wrote: > Enjoy your trip, Mark! Thanks again for the help! > > Tim > > > On 6 September 2013 14:18, Mark Miller <markrmil...@gmail.com> wrote: > >> Okay, thanks, useful info. Getting on a plane, but ill look more at this >> soon. That 10k thread spike is good to know - that's no good and could >> easily be part of the problem. We want to keep that from happening. >> >> Mark >> >> Sent from my iPhone >> >> On Sep 6, 2013, at 2:05 PM, Tim Vaillancourt <t...@elementspace.com> >> wrote: >> >> > Hey Mark, >> > >> > The farthest we've made it at the same batch size/volume was 12 hours >> > without this patch, but that isn't consistent. Sometimes we would only >> get >> > to 6 hours or less. >> > >> > During the crash I can see an amazing spike in threads to 10k which is >> > essentially our ulimit for the JVM, but I strangely see no "OutOfMemory: >> > cannot open native thread errors" that always follow this. Weird! >> > >> > We also notice a spike in CPU around the crash. The instability caused >> some >> > shard recovery/replication though, so that CPU may be a symptom of the >> > replication, or is possibly the root cause. The CPU spikes from about >> > 20-30% utilization (system + user) to 60% fairly sharply, so the CPU, >> while >> > spiking isn't quite "pinned" (very beefy Dell R720s - 16 core Xeons, >> whole >> > index is in 128GB RAM, 6xRAID10 15k). >> > >> > More on resources: our disk I/O seemed to spike about 2x during the >> crash >> > (about 1300kbps written to 3500kbps), but this may have been the >> > replication, or ERROR logging (we generally log nothing due to >> > WARN-severity unless something breaks). >> > >> > Lastly, I found this stack trace occurring frequently, and have no idea >> > what it is (may be useful or not): >> > >> > "java.lang.IllegalStateException : >> > at org.eclipse.jetty.server.Response.resetBuffer(Response.java:964) >> > at org.eclipse.jetty.server.Response.sendError(Response.java:325) >> > at >> > >> org.apache.solr.servlet.SolrDispatchFilter.sendError(SolrDispatchFilter.java:692) >> > at >> > >> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:380) >> > at >> > >> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:155) >> > at >> > >> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1423) >> > at >> > >> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:450) >> > at >> > >> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138) >> > at >> > >> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564) >> > at >> > >> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213) >> > at >> > >> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1083) >> > at >> > >> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:379) >> > at >> > >> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175) >> > at >> > >> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1017) >> > at >> > >> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136) >> > at >> > >> org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:258) >> > at >> > >> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109) >> > at >> > >> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) >> > at org.eclipse.jetty.server.Server.handle(Server.java:445) >> > at >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:260) >> > at >> > >> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:225) >> > at >> > >> org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358) >> > at >> > >> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:596) >> > at >> > >> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:527) >> > at java.lang.Thread.run(Thread.java:724)" >> > >> > On your live_nodes question, I don't have historical data on this from >> when >> > the crash occurred, which I guess is what you're looking for. I could >> add >> > this to our monitoring for future tests, however. I'd be glad to >> continue >> > further testing, but I think first more monitoring is needed to >> understand >> > this further. Could we come up with a list of metrics that would be >> useful >> > to see following another test and successful crash? >> > >> > Metrics needed: >> > >> > 1) # of live_nodes. >> > 2) Full stack traces. >> > 3) CPU used by Solr's JVM specifically (instead of system-wide). >> > 4) Solr's JVM thread count (already done) >> > 5) ? >> > >> > Cheers, >> > >> > Tim Vaillancourt >> > >> > >> > On 6 September 2013 13:11, Mark Miller <markrmil...@gmail.com> wrote: >> > >> >> Did you ever get to index that long before without hitting the >> deadlock? >> >> >> >> There really isn't anything negative the patch could be introducing, >> other >> >> than allowing for some more threads to possibly run at once. If I had >> to >> >> guess, I would say its likely this patch fixes the deadlock issue and >> your >> >> seeing another issue - which looks like the system cannot keep up with >> the >> >> requests or something for some reason - perhaps due to some OS >> networking >> >> settings or something (more guessing). Connection refused happens >> generally >> >> when there is nothing listening on the port. >> >> >> >> Do you see anything interesting change with the rest of the system? CPU >> >> usage spikes or something like that? >> >> >> >> Clamping down further on the overall number of threads night help >> (which >> >> would require making something configurable). How many nodes are >> listed in >> >> zk under live_nodes? >> >> >> >> Mark >> >> >> >> Sent from my iPhone >> >> >> >> On Sep 6, 2013, at 12:02 PM, Tim Vaillancourt <t...@elementspace.com> >> >> wrote: >> >> >> >>> Hey guys, >> >>> >> >>> (copy of my post to SOLR-5216) >> >>> >> >>> We tested this patch and unfortunately encountered some serious >> issues a >> >>> few hours of 500 update-batches/sec. Our update batch is 10 docs, so >> we >> >> are >> >>> writing about 5000 docs/sec total, using autoCommit to commit the >> updates >> >>> (no explicit commits). >> >>> >> >>> Our environment: >> >>> >> >>> Solr 4.3.1 w/SOLR-5216 patch. >> >>> Jetty 9, Java 1.7. >> >>> 3 solr instances, 1 per physical server. >> >>> 1 collection. >> >>> 3 shards. >> >>> 2 replicas (each instance is a leader and a replica). >> >>> Soft autoCommit is 1000ms. >> >>> Hard autoCommit is 15000ms. >> >>> >> >>> After about 6 hours of stress-testing this patch, we see many of these >> >>> stalled transactions (below), and the Solr instances start to see each >> >>> other as down, flooding our Solr logs with "Connection Refused" >> >> exceptions, >> >>> and otherwise no obviously-useful logs that I could see. >> >>> >> >>> I did notice some stalled transactions on both /select and /update, >> >>> however. This never occurred without this patch. >> >>> >> >>> Stack /select seems stalled on: http://pastebin.com/Y1NCrXGC >> >>> Stack /update seems stalled on: http://pastebin.com/cFLbC8Y9 >> >>> >> >>> Lastly, I have a summary of the ERROR-severity logs from this 24-hour >> >> soak. >> >>> My script "normalizes" the ERROR-severity stack traces and returns >> them >> >> in >> >>> order of occurrence. >> >>> >> >>> Summary of my solr.log: http://pastebin.com/pBdMAWeb >> >>> >> >>> Thanks! >> >>> >> >>> Tim Vaillancourt >> >>> >> >>> >> >>> On 6 September 2013 07:27, Markus Jelsma <markus.jel...@openindex.io> >> >> wrote: >> >>> >> >>>> Thanks! >> >>>> >> >>>> -----Original message----- >> >>>>> From:Erick Erickson <erickerick...@gmail.com> >> >>>>> Sent: Friday 6th September 2013 16:20 >> >>>>> To: solr-user@lucene.apache.org >> >>>>> Subject: Re: SolrCloud 4.x hangs under high update volume >> >>>>> >> >>>>> Markus: >> >>>>> >> >>>>> See: https://issues.apache.org/jira/browse/SOLR-5216 >> >>>>> >> >>>>> >> >>>>> On Wed, Sep 4, 2013 at 11:04 AM, Markus Jelsma >> >>>>> <markus.jel...@openindex.io>wrote: >> >>>>> >> >>>>>> Hi Mark, >> >>>>>> >> >>>>>> Got an issue to watch? >> >>>>>> >> >>>>>> Thanks, >> >>>>>> Markus >> >>>>>> >> >>>>>> -----Original message----- >> >>>>>>> From:Mark Miller <markrmil...@gmail.com> >> >>>>>>> Sent: Wednesday 4th September 2013 16:55 >> >>>>>>> To: solr-user@lucene.apache.org >> >>>>>>> Subject: Re: SolrCloud 4.x hangs under high update volume >> >>>>>>> >> >>>>>>> I'm going to try and fix the root cause for 4.5 - I've suspected >> >>>> what it >> >>>>>> is since early this year, but it's never personally been an issue, >> so >> >>>> it's >> >>>>>> rolled along for a long time. >> >>>>>>> >> >>>>>>> Mark >> >>>>>>> >> >>>>>>> Sent from my iPhone >> >>>>>>> >> >>>>>>> On Sep 3, 2013, at 4:30 PM, Tim Vaillancourt < >> t...@elementspace.com> >> >>>>>> wrote: >> >>>>>>> >> >>>>>>>> Hey guys, >> >>>>>>>> >> >>>>>>>> I am looking into an issue we've been having with SolrCloud since >> >>>> the >> >>>>>>>> beginning of our testing, all the way from 4.1 to 4.3 (haven't >> >>>> tested >> >>>>>> 4.4.0 >> >>>>>>>> yet). I've noticed other users with this same issue, so I'd >> really >> >>>>>> like to >> >>>>>>>> get to the bottom of it. >> >>>>>>>> >> >>>>>>>> Under a very, very high rate of updates (2000+/sec), after 1-12 >> >>>> hours >> >>>>>> we >> >>>>>>>> see stalled transactions that snowball to consume all Jetty >> >>>> threads in >> >>>>>> the >> >>>>>>>> JVM. This eventually causes the JVM to hang with most threads >> >>>> waiting >> >>>>>> on >> >>>>>>>> the condition/stack provided at the bottom of this message. At >> this >> >>>>>> point >> >>>>>>>> SolrCloud instances then start to see their neighbors (who also >> >>>> have >> >>>>>> all >> >>>>>>>> threads hung) as down w/"Connection Refused", and the shards >> become >> >>>>>> "down" >> >>>>>>>> in state. Sometimes a node or two survives and just returns 503s >> >>>> "no >> >>>>>> server >> >>>>>>>> hosting shard" errors. >> >>>>>>>> >> >>>>>>>> As a workaround/experiment, we have tuned the number of threads >> >>>> sending >> >>>>>>>> updates to Solr, as well as the batch size (we batch updates from >> >>>>>> client -> >> >>>>>>>> solr), and the Soft/Hard autoCommits, all to no avail. Turning >> off >> >>>>>>>> Client-to-Solr batching (1 update = 1 call to Solr), which also >> >>>> did not >> >>>>>>>> help. Certain combinations of update threads and batch sizes seem >> >>>> to >> >>>>>>>> mask/help the problem, but not resolve it entirely. >> >>>>>>>> >> >>>>>>>> Our current environment is the following: >> >>>>>>>> - 3 x Solr 4.3.1 instances in Jetty 9 w/Java 7. >> >>>>>>>> - 3 x Zookeeper instances, external Java 7 JVM. >> >>>>>>>> - 1 collection, 3 shards, 2 replicas (each node is a leader of 1 >> >>>> shard >> >>>>>> and >> >>>>>>>> a replica of 1 shard). >> >>>>>>>> - Log4j 1.2 for Solr logs, set to WARN. This log has no movement >> >>>> on a >> >>>>>> good >> >>>>>>>> day. >> >>>>>>>> - 5000 max jetty threads (well above what we use when we are >> >>>> healthy), >> >>>>>>>> Linux-user threads ulimit is 6000. >> >>>>>>>> - Occurs under Jetty 8 or 9 (many versions). >> >>>>>>>> - Occurs under Java 1.6 or 1.7 (several minor versions). >> >>>>>>>> - Occurs under several JVM tunings. >> >>>>>>>> - Everything seems to point to Solr itself, and not a Jetty or >> Java >> >>>>>> version >> >>>>>>>> (I hope I'm wrong). >> >>>>>>>> >> >>>>>>>> The stack trace that is holding up all my Jetty QTP threads is >> the >> >>>>>>>> following, which seems to be waiting on a lock that I would very >> >>>> much >> >>>>>> like >> >>>>>>>> to understand further: >> >>>>>>>> >> >>>>>>>> "java.lang.Thread.State: WAITING (parking) >> >>>>>>>> at sun.misc.Unsafe.park(Native Method) >> >>>>>>>> - parking to wait for <0x00000007216e68d8> (a >> >>>>>>>> java.util.concurrent.Semaphore$NonfairSync) >> >>>>>>>> at >> >>>> java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) >> >>>>>>>> at >> >> >> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834) >> >>>>>>>> at >> >> >> java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994) >> >>>>>>>> at >> >> >> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303) >> >>>>>>>> at java.util.concurrent.Semaphore.acquire(Semaphore.java:317) >> >>>>>>>> at >> >> >> org.apache.solr.util.AdjustableSemaphore.acquire(AdjustableSemaphore.java:61) >> >>>>>>>> at >> >> >> org.apache.solr.update.SolrCmdDistributor.submit(SolrCmdDistributor.java:418) >> >>>>>>>> at >> >> >> org.apache.solr.update.SolrCmdDistributor.submit(SolrCmdDistributor.java:368) >> >>>>>>>> at >> >> >> org.apache.solr.update.SolrCmdDistributor.flushAdds(SolrCmdDistributor.java:300) >> >>>>>>>> at >> >> >> org.apache.solr.update.SolrCmdDistributor.finish(SolrCmdDistributor.java:96) >> >>>>>>>> at >> >> >> org.apache.solr.update.processor.DistributedUpdateProcessor.doFinish(DistributedUpdateProcessor.java:462) >> >>>>>>>> at >> >> >> org.apache.solr.update.processor.DistributedUpdateProcessor.finish(DistributedUpdateProcessor.java:1178) >> >>>>>>>> at >> >> >> org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:83) >> >>>>>>>> at >> >> >> org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:135) >> >>>>>>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1820) >> >>>>>>>> at >> >> >> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:656) >> >>>>>>>> at >> >> >> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:359) >> >>>>>>>> at >> >> >> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:155) >> >>>>>>>> at >> >> >> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1486) >> >>>>>>>> at >> >> >> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138) >> >>>>>>>> at >> >> >> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1096) >> >>>>>>>> at >> >> >> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1030) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:201) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) >> >>>>>>>> at org.eclipse.jetty.server.Server.handle(Server.java:445) >> >>>>>>>> at >> >>>> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:268) >> >>>>>>>> at >> >> >> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:229) >> >>>>>>>> at >> >> >> org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358) >> >>>>>>>> at >> >> >> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601) >> >>>>>>>> at >> >> >> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532) >> >>>>>>>> at java.lang.Thread.run(Thread.java:724)" >> >>>>>>>> >> >>>>>>>> Some questions I had were: >> >>>>>>>> 1) What exclusive locks does SolrCloud "make" when performing an >> >>>>>> update? >> >>>>>>>> 2) Keeping in mind I do not read or write java (sorry :D), could >> >>>>>> someone >> >>>>>>>> help me understand "what" solr is locking in this case at >> >> >> "org.apache.solr.util.AdjustableSemaphore.acquire(AdjustableSemaphore.java:61)" >> >>>>>>>> when performing an update? That will help me understand where to >> >>>> look >> >>>>>> next. >> >>>>>>>> 3) It seems all threads in this state are waiting for >> >>>>>> "0x00000007216e68d8", >> >>>>>>>> is there a way to tell what "0x00000007216e68d8" is? >> >>>>>>>> 4) Is there a limit to how many updates you can do in SolrCloud? >> >>>>>>>> 5) Wild-ass-theory: would more shards provide more locks >> (whatever >> >>>> they >> >>>>>>>> are) on update, and thus more update throughput? >> >>>>>>>> >> >>>>>>>> To those interested, I've provided a stacktrace of 1 of 3 nodes >> at >> >>>>>> this URL >> >>>>>>>> in gzipped form: >> >> >> https://s3.amazonaws.com/timvaillancourt.com/tmp/solr-jstack-2013-08-23.gz >> >>>>>>>> >> >>>>>>>> Any help/suggestions/ideas on this issue, big or small, would be >> >>>> much >> >>>>>>>> appreciated. >> >>>>>>>> >> >>>>>>>> Thanks so much all! >> >>>>>>>> >> >>>>>>>> Tim Vaillancourt >> >> >> > >
