FWIW, by the way, I'm getting some exceptions in the solr log, here are the two patterns I see on a quick look (this is with my hacks, but the test of your patch also produced some like this, I think they were the same). Your comment about trying this with the old-style XML is getting more compelling....
But do note that the stress tests still ran to completion OK, which means that all documents sent to the server made it into the indexes.... Jan 30, 2013 10:20:27 AM org.apache.solr.common.SolrException log SEVERE: java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1279) at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:218) at java.util.concurrent.FutureTask.get(FutureTask.java:83) at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:597) at org.apache.solr.update.CommitTracker.run(CommitTracker.java:216) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:680) FWIW On Wed, Jan 30, 2013 at 8:46 AM, Erick Erickson <[email protected]>wrote: > No joy. It ran to completion on one of my machines for an hour, but not > the other, stack traces below. > > About running without the patch. The other thing that's different is I've > changed where the core.close happens in the patch as opposed to the old > code, which may confuse things. OTOH, it'd be interesting to try since my > changes to where I called close were based on a faulty assumption about > where the lock was occurring. I did a quick hack that I have yet to test > making the stress tester bang up old-style solr.xml setups, but haven't run > it yet. I can give it a try against an unmodified trunk if you think that > would generate useful information but I sadly fear it's an apples/oranges > comparison. > > I'm on IM or we can voice chat if you want to strategize, but I won't be > able to devote much time to this until tonight or tomorrow. I can apply > patches and run tests all day though.... > > Although before digging to deeply, I had to cobble the patch into > DefaultSolrCoreState and I might have screwed it up. Is the finally block > containing if (yielded) in the right place? > > Here's my patched code, but maybe you could just send me the whole file? I > haven't changed it outside this patch.... > > synchronized (writerPauseLock) { > // we need to wait for the Writer to fall out of use > // first lets stop it from being lent out > pauseWriter = true; > // then lets wait until its out of use > log.info("Waiting until IndexWriter is unused... core=" + coreName); > boolean yielded = false; > try { > while (!writerFree) { > // yield the commit lock > core.getUpdateHandler().yieldCommitLock(); > yielded = true; > try { > writerPauseLock.wait(100); > } catch (InterruptedException e) {} > if (closed) { > throw new RuntimeException("SolrCoreState already closed"); > } > } > } finally { > if (yielded) { > core.getUpdateHandler().getCommitLock(); > } > } > try { > if (indexWriter != null) { > if (!rollback) { > try { > > > > Stack trace for the deadlock bits, full file attached: > > Found one Java-level deadlock: > ============================= > "commitScheduler-36850-thread-1": > waiting to lock monitor 7fc2c625f7f8 (object 7429863a0, a > org.apache.solr.update.DefaultSolrCoreState), > which is held by "qtp132616134-30" > "qtp132616134-30": > waiting for ownable synchronizer 740bc1108, (a > java.util.concurrent.locks.ReentrantLock$NonfairSync), > which is held by "commitScheduler-36850-thread-1" > > Java stack information for the threads listed above: > =================================================== > "commitScheduler-36850-thread-1": > at > org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:78) > - waiting to lock <7429863a0> (a > org.apache.solr.update.DefaultSolrCoreState) > at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1359) > at > org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:561) > - locked <74066b838> (a java.lang.Object) > at org.apache.solr.update.CommitTracker.run(CommitTracker.java:216) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) > at java.util.concurrent.FutureTask.run(FutureTask.java:138) > at > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98) > at > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > "qtp132616134-30": > at sun.misc.Unsafe.park(Native Method) > - parking to wait for <740bc1108> (a > java.util.concurrent.locks.ReentrantLock$NonfairSync) > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178) > at > java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186) > at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262) > at > org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:668) > at > org.apache.solr.update.DefaultSolrCoreState.closeIndexWriter(DefaultSolrCoreState.java:64) > - locked <7429863a0> (a org.apache.solr.update.DefaultSolrCoreState) > at > org.apache.solr.update.DefaultSolrCoreState.close(DefaultSolrCoreState.java:280) > - locked <7429863a0> (a org.apache.solr.update.DefaultSolrCoreState) > at org.apache.solr.core.SolrCore.decrefSolrCoreState(SolrCore.java:888) > - locked <7429863a0> (a org.apache.solr.update.DefaultSolrCoreState) > at org.apache.solr.core.SolrCore.close(SolrCore.java:980) > at org.apache.solr.core.CoreMaps.putTransientCore(CoreContainer.java:1466) > at > org.apache.solr.core.CoreContainer.registerCore(CoreContainer.java:730) > at org.apache.solr.core.CoreContainer.getCore(CoreContainer.java:1138) > at > org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:190) > at > org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307) > at > org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453) > at > org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137) > at > org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:560) > at > org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231) > at > org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072) > at > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382) > at > org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) > at > org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006) > at > org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) > at > org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255) > at > org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154) > at > org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) > at org.eclipse.jetty.server.Server.handle(Server.java:365) > at > org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485) > at > org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) > at > org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937) > at > org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998) > at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:948) > at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240) > at > org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) > at > org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264) > at > org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) > at > org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) > at java.lang.Thread.run(Thread.java:680) > > Found 1 deadlock. > > > > On Wed, Jan 30, 2013 at 7:11 AM, Erick Erickson > <[email protected]>wrote: > >> bq: I don't follow this at all - of course you could rapidly load and >> unload cores at the same time before this patch? >> >> Not quite what I was trying to say. The stress test opens and closes >> cores a LOT. Of course you could open and close cores simultaneously >> before. In fact given what I think is a new pattern I'm amazed that there >> aren't a lot more problems, that's some damn good code. What's new is the >> stress test opens and closes a core with *every* call. From 30 threads, >> 15 indexing and 15 querying. >> >> bq: If you cannot easily produce a test that causes deadlock without your >> patch >> >> I don't know how you'd really write a predictable junit test, the time >> window for the race here is small. I had to run my stress test for 20-30 >> minutes to hit it. I think I can modify the stress test to use old-style >> solr.xml which I could run against current trunk, is it worth it though >> after your second look? Note that this open/closing a core every call from >> the stress test wasn't really possible the same way before SOLR-1028, one >> of the keys is that the transient cores have to be aged out. The bolds >> below are new code (SOLR-1028+): >> >> at org.apache.solr.core.CoreMaps$1.*removeEldestEntry* >> (CoreContainer.java:1384) >> ...... >> at org.apache.solr.core.CoreMaps.*putTransientCore* >> (CoreContainer.java:1444) >> >> >> If you still think it's worthwhile, I have some travel time tomorrow that >> I could use to make this test run with old-style solr.xml. Let me know. I'm >> also wondering if the stress test should go into our test suite somewhere. >> It's possible to bring the stress test into junit I think, there's nothing >> magic about it. But it might be better as an external test that we run on, >> say, a nightly or weekly basis, is there precedent? >> >> bq: Because they are different locks protecting different state. >> >> So you're saying that synchronizing the method actually is protecting the >> SolrCore that's passed as a parameter? Otherwise I don't get it, seems like >> moving the synchronized block to the first line of, e.g., newIndexWriter >> and removing synchronized from the method signature would be sufficient. >> That said, my hack of removing the synchronized from the method signature >> was more to poke that what I thought I saw than a well thought-out >> solution... Which is why I'm glad you're looking too... >> >> Yes, the code attached to the JIRA is the latest. You've got enough on >> your plate I'm sure, I'll apply your patch and let you know. I had a little >> trouble with SVN applying it cleanly, but I think I reconciled it >> correctly... >> >> >> On Tue, Jan 29, 2013 at 11:43 PM, Mark Miller <[email protected]>wrote: >> >>> Do you have your latest work attached to the issue? If so, I'll start >>> working with it locally. >>> >>> For now, can you try this experimental, test patch and see what the >>> results are? >>> >>> Index: >>> solr/core/src/java/org/apache/solr/update/DefaultSolrCoreState.java >>> =================================================================== >>> --- solr/core/src/java/org/apache/solr/update/DefaultSolrCoreState.java >>> (revision 1440275) >>> +++ solr/core/src/java/org/apache/solr/update/DefaultSolrCoreState.java >>> (working copy) >>> @@ -135,13 +135,24 @@ >>> pauseWriter = true; >>> // then lets wait until its out of use >>> log.info("Waiting until IndexWriter is unused... core=" + >>> coreName); >>> + >>> + boolean yielded = false; >>> + try { >>> while (!writerFree) { >>> - try { >>> - writerPauseLock.wait(100); >>> - } catch (InterruptedException e) {} >>> - >>> - if (closed) { >>> - throw new RuntimeException("SolrCoreState already closed"); >>> + // yield the commit lock >>> + core.getUpdateHandler().yieldCommitLock(); >>> + yielded = true; >>> + try { >>> + writerPauseLock.wait(100); >>> + } catch (InterruptedException e) {} >>> + >>> + if (closed) { >>> + throw new RuntimeException("SolrCoreState already closed"); >>> + } >>> + } >>> + } finally { >>> + if (yielded) { >>> + core.getUpdateHandler().getCommitLock(); >>> } >>> } >>> >>> Index: solr/core/src/java/org/apache/solr/update/UpdateHandler.java >>> =================================================================== >>> --- solr/core/src/java/org/apache/solr/update/UpdateHandler.java >>> (revision 1440275) >>> +++ solr/core/src/java/org/apache/solr/update/UpdateHandler.java >>> (working copy) >>> @@ -189,4 +189,10 @@ >>> } >>> >>> public abstract void split(SplitIndexCommand cmd) throws IOException; >>> + >>> + >>> + public void getCommitLock() {} >>> + >>> + >>> + public void yieldCommitLock() {} >>> } >>> Index: >>> solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java >>> =================================================================== >>> --- solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java >>> (revision 1440275) >>> +++ solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java >>> (working copy) >>> @@ -830,4 +830,13 @@ >>> public CommitTracker getSoftCommitTracker() { >>> return softCommitTracker; >>> } >>> + >>> + public void getCommitLock() { >>> + commitLock.lock(); >>> + } >>> + >>> + >>> + public void yieldCommitLock() { >>> + commitLock.unlock(); >>> + } >>> } >>> >>> >>> On Jan 29, 2013, at 11:24 PM, Mark Miller <[email protected]> wrote: >>> >>> > Digging into the stack traces... >>> > >>> > This shows a thread waiting for the commit lock trying to close an >>> index writer. >>> > >>> > There is another thread with the commit lock that is waiting for the >>> writer to be returned. >>> > >>> > That seems to be the situation - a race around the commit lock. >>> > >>> > Needs some thought. >>> > >>> > - Mark >>> > >>> > On Jan 29, 2013, at 8:31 AM, Erick Erickson <[email protected]> >>> wrote: >>> > >>> >> Java stack information for the threads listed above: >>> >> =================================================== >>> >> "commitScheduler-42617-thread-1": >>> >> at >>> org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:78) >>> >> - waiting to lock <78b4aa518> (a >>> org.apache.solr.update.DefaultSolrCoreState) >>> >> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1359) >>> >> at >>> org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:561) >>> >> - locked <7884ca730> (a java.lang.Object) >>> >> at org.apache.solr.update.CommitTracker.run(CommitTracker.java:216) >>> >> at >>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439) >>> >> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) >>> >> at java.util.concurrent.FutureTask.run(FutureTask.java:138) >>> >> at >>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98) >>> >> at >>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206) >>> >> at >>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) >>> >> at >>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) >>> >> at java.lang.Thread.run(Thread.java:680) >>> >> >>> >> ********* >>> >> Other thread >>> >> "qtp1401888126-32": >>> >> at sun.misc.Unsafe.park(Native Method) >>> >> - parking to wait for <788d73208> (a >>> >> java.util.concurrent.locks.ReentrantLock$NonfairSync) >>> >> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) >>> >> at >>> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811) >>> >> at >>> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842) >>> >> at >>> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178) >>> >> at >>> java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186) >>> >> at >>> java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262) >>> >> at >>> org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:668) >>> >> at >>> org.apache.solr.update.DefaultSolrCoreState.closeIndexWriter(DefaultSolrCoreState.java:64) >>> >> - locked <78b4aa518> (a org.apache.solr.update.DefaultSolrCoreState) >>> >> at >>> org.apache.solr.update.DefaultSolrCoreState.close(DefaultSolrCoreState.java:272) >>> >> - locked <78b4aa518> (a org.apache.solr.update.DefaultSolrCoreState) >>> >> at >>> org.apache.solr.core.SolrCore.decrefSolrCoreState(SolrCore.java:888) >>> >> - locked <78b4aa518> (a org.apache.solr.update.DefaultSolrCoreState) >>> >> at org.apache.solr.core.SolrCore.close(SolrCore.java:980) >>> >> at >>> org.apache.solr.core.CoreMaps.putTransientCore(CoreContainer.java:1465) >>> >> at >>> org.apache.solr.core.CoreContainer.registerCore(CoreContainer.java:730) >>> >> at org.apache.solr.core.CoreContainer.getCore(CoreContainer.java:1137) >>> >> at >>> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:190) >>> >> at >>> > >>> >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: [email protected] >>> For additional commands, e-mail: [email protected] >>> >>> >> >
