Re: Stress test deadlocks
On Feb 2, 2013, at 10:29 AM, Erick Erickson erickerick...@gmail.com wrote: My stray thought was I wonder if it'd make sense to add this to some kind of regular test process just for yucks I really think this should be converted into a junit test - it's very useful and could be cranked up on nightly runs. - Mark - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
Re: Stress test deadlocks
On Feb 1, 2013, at 9:02 PM, Erick Erickson erickerick...@gmail.com wrote: First, about the thread interrupt exceptions; what do you think about not logging them? I could argue that if they are benign, reporting them adds unnecessary stress. I kinda figured they were harmless but thought it might be worth mentioning. I guess I'd open a JIRA issue to discuss it - we would probably want to consistently tackle the code base. Currently, I think we usually log something on interruptions. Second, I re-worked the stress test program to use the old-style solr.xml file then re-ran the tests from trunk w/o any of the changes for SOLR-4196. I worked for a couple of hours then I had to stop, but tonight it ran for just a few minutes (I updated the code this morning) and got the same error (stack below just in case I'm imagining things). Next step I guess is I'll apply the changes you indicated above to trunk and see if it I can make it happen again. That said, it's a bit of apples-to-oranges but worth doing nonetheless... It's still clearly happening from some relatively new code related to the transient core thing given the trace is coming form removeEldestEntry eventually…. Since you have the tests and can easily check this, I would appreciate it. We would like to fix this. The below is the same issue. I'm pretty sure the patch addresses it (though don't commit it, it's still hackey), but confirmation would be great. - Mark Found one Java-level deadlock: = commitScheduler-15616-thread-1: waiting to lock monitor 7f920387fd58 (object 7879df120, a org.apache.solr.update.DefaultSolrCoreState), which is held by qtp1490642445-15 qtp1490642445-15: waiting to lock monitor 7f9204803bc0 (object 786d3df78, a java.lang.Object), which is held by commitScheduler-15616-thread-1 Java stack information for the threads listed above: === commitScheduler-15616-thread-1: at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:78) - waiting to lock 7879df120 (a org.apache.solr.update.DefaultSolrCoreState) at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1359) at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:1535) at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:550) - locked 786d3df78 (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) qtp1490642445-15: at org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:705) - waiting to lock 786d3df78 (a java.lang.Object) at org.apache.solr.update.DefaultSolrCoreState.closeIndexWriter(DefaultSolrCoreState.java:64) - locked 7879df120 (a org.apache.solr.update.DefaultSolrCoreState) at org.apache.solr.update.DefaultSolrCoreState.close(DefaultSolrCoreState.java:272) - locked 7879df120 (a org.apache.solr.update.DefaultSolrCoreState) at org.apache.solr.core.SolrCore.decrefSolrCoreState(SolrCore.java:888) - locked 7879df120 (a org.apache.solr.update.DefaultSolrCoreState) at org.apache.solr.core.SolrCore.close(SolrCore.java:980) at org.apache.solr.core.CoreContainer$2.removeEldestEntry(CoreContainer.java:385) at java.util.LinkedHashMap.addEntry(LinkedHashMap.java:410) at java.util.HashMap.put(HashMap.java:385) at org.apache.solr.core.CoreContainer.registerCore(CoreContainer.java:864) - locked 785614df8 (a org.apache.solr.core.CoreContainer$2) at org.apache.solr.core.CoreContainer.registerLazyCore(CoreContainer.java:829) at org.apache.solr.core.CoreContainer.getCore(CoreContainer.java:1321) 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
Re: Stress test deadlocks
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 markrmil...@gmail.com 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
Re: Stress test deadlocks
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 erickerick...@gmail.comwrote:
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
Re: Stress test deadlocks
Without evidence of further damage, that is fine - it just means a thread was
interrupted.
- Mark
On Jan 30, 2013, at 10:52 AM, Erick Erickson erickerick...@gmail.com wrote:
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 erickerick...@gmail.com
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
Re: Stress test deadlocks
Two runs doth not a conclusion reach, but removing synchronized from:
DefaultSolrCoreState.getIndexWriter (line 78)
let me run for an hour, at least twice. And my stress test succeeds,
which fires up 15 indexing threads on 100 cores (transient core size
is 20), indexes documents for an hour while another 15 threads fire
off queries. At the end, it inspects each core to see if there are the
expected number of documents.
But that's kinda a frail reed to pin my hopes on, these are
notoriously hard to reproduce.
I'll set this up to run on an old machine for much longer later today.
Does anyone who knows that code know whether I'm playing with fire? I
haven't looked at the synchronization in that code to try to figure
out the purpose, I'm hoping someone will glance at it and say that's
wrong.
I'll dig into it later and see how much I can figure out about whether it's safe
FWIW,
On Tue, Jan 29, 2013 at 8:31 AM, Erick Erickson erickerick...@gmail.com wrote:
All:
As part of SOLR-4196, I'm opening and closing cores at a furious rate.
My tests are running for 20-40 minutes then locking up quite
regularly. Of course the first place I'm looking is my recent code,
since it has a bunch of synchronized blocks.
The deadlock is definitely happening at a call from the new code to
close a Solr core, so to really look at this anyone will need to get
the patch I'll put up in a minute. The deadlock trace is below.
But without going that far, I question whether it's really anything to
do with new synchronizations I'm doing or whether it's just something
that's been lurking for a while and I'm flushing out of the woodwork.
One of the deadlocked threads may be called form my code, but as far
as I can tell none of the actual synchronization objects I'm using are
held. I have the full jstack output if anyone needs it...
Of course I'll continue looking, but at a glance I'm wondering if this
code has really ever been stressed this way before or whether these
have existed for a while. All synchronization should be approached
with fear and loathing IMO.
One thread blocks at a synchronized method, but should this method
really be synchronized?
at
org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:78)
(here's the method) @Override
public synchronized RefCountedIndexWriter getIndexWriter(SolrCore core)
throws IOException {
and a little later in the method there's:
synchronized (writerPauseLock) {
if (core == null) {
and the other thread blocks at:
at
org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:668),
(here's the method)
// IndexWriterCloser interface method - called from
solrCoreState.decref(this)
@Override
public void closeWriter(IndexWriter writer) throws IOException {
boolean clearRequestInfo = false;
commitLock.lock(); **locking here!
try {
SolrQueryRequest req = new LocalSolrQueryRequest(core, new
ModifiableSolrParams());
SolrQueryResponse rsp = new SolrQueryResponse();
if (SolrRequestInfo.getRequestInfo() == null) {
clearRequestInfo = true;
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
Re: Stress test deadlocks
There is a lot of complicated interplay between locks in that area of the code
- small changes can easily get you into trouble.
Can you modify your test to run on the code before your patch? That would help
in telling if it's something existing or something your introducing.
I still plan on looking at this issue closer this week, so perhaps I can offer
some more help soon.
- Mark
On Jan 29, 2013, at 1:26 PM, Erick Erickson erickerick...@gmail.com wrote:
Two runs doth not a conclusion reach, but removing synchronized from:
DefaultSolrCoreState.getIndexWriter (line 78)
let me run for an hour, at least twice. And my stress test succeeds,
which fires up 15 indexing threads on 100 cores (transient core size
is 20), indexes documents for an hour while another 15 threads fire
off queries. At the end, it inspects each core to see if there are the
expected number of documents.
But that's kinda a frail reed to pin my hopes on, these are
notoriously hard to reproduce.
I'll set this up to run on an old machine for much longer later today.
Does anyone who knows that code know whether I'm playing with fire? I
haven't looked at the synchronization in that code to try to figure
out the purpose, I'm hoping someone will glance at it and say that's
wrong.
I'll dig into it later and see how much I can figure out about whether it's
safe
FWIW,
On Tue, Jan 29, 2013 at 8:31 AM, Erick Erickson erickerick...@gmail.com
wrote:
All:
As part of SOLR-4196, I'm opening and closing cores at a furious rate.
My tests are running for 20-40 minutes then locking up quite
regularly. Of course the first place I'm looking is my recent code,
since it has a bunch of synchronized blocks.
The deadlock is definitely happening at a call from the new code to
close a Solr core, so to really look at this anyone will need to get
the patch I'll put up in a minute. The deadlock trace is below.
But without going that far, I question whether it's really anything to
do with new synchronizations I'm doing or whether it's just something
that's been lurking for a while and I'm flushing out of the woodwork.
One of the deadlocked threads may be called form my code, but as far
as I can tell none of the actual synchronization objects I'm using are
held. I have the full jstack output if anyone needs it...
Of course I'll continue looking, but at a glance I'm wondering if this
code has really ever been stressed this way before or whether these
have existed for a while. All synchronization should be approached
with fear and loathing IMO.
One thread blocks at a synchronized method, but should this method
really be synchronized?
at
org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:78)
(here's the method) @Override
public synchronized RefCountedIndexWriter getIndexWriter(SolrCore core)
throws IOException {
and a little later in the method there's:
synchronized (writerPauseLock) {
if (core == null) {
and the other thread blocks at:
at
org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:668),
(here's the method)
// IndexWriterCloser interface method - called from
solrCoreState.decref(this)
@Override
public void closeWriter(IndexWriter writer) throws IOException {
boolean clearRequestInfo = false;
commitLock.lock(); **locking here!
try {
SolrQueryRequest req = new LocalSolrQueryRequest(core, new
ModifiableSolrParams());
SolrQueryResponse rsp = new SolrQueryResponse();
if (SolrRequestInfo.getRequestInfo() == null) {
clearRequestInfo = true;
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
Re: Stress test deadlocks
First, I approach synchronization with fear and loathing because it's
so easy to screw up, so any comments deeply appreciated.
Second, the code (see below) in DefaultSolrCoreState just looks wrong.
Why synchronize the entire method and then synchronize everything
except the error condition on a _different_ object? The same thing
happens a bit further down in the newIndexWriter method and yet again
potentially in, I think, every synchronized method. That seems like
classic deadlock-vulnerable code. I really think we've been getting
away with this because the incidence of simultaneously opening and
closing cores is very low, or was before the many cores madness. In
fact, I'm not sure _any_ of the synchronized methods in
DefaultSolrCoreState should be synchronized.
Odd that I had that exact thought about running this against the
unmodified code an hour ago on the way back from some family business.
I'm not entirely sure what it would show though, since you don't get
into this situation without loading and unloading cores at the same
time, the stuff from SOLR-1028 and SOLR-4300. Which you couldn't do
before this rapidly. The deadlock is definitely happening when closing
a core, which generally wouldn't happen the way it's happening with
the stress test before the other changes. I can say that the deadlock
doesn't involve any of the new synchronization SOLR-4196 has
introduced, but I think is a consequence of rapidly opening/closing
cores. Now that I look more closely, the stack trace for the
deadlocked cores are _both_ in DefaultSolrCoreState. Smoking gun?
re: reviewing the patch. It spun out of control as I tried to get all
of the solr.xml purged. It's huge. For the main changes to things like
CoreContainer I don't think looking at the differences will help,
we'll have to evaluate it as new code. I'd be happy to get on a
marathon remote-review session with anyone who wants to rip things
apart. All tests pass at this point, but I'm not sure how much
that really means in terms of deadlocking And I'm particularly
uncertain of the violence I did to persisting
Final comment. With the one synchronization on the one method removed,
I've had about 11 hours if my stress test run without problems. So
this is in the right area at least. I'm about to remove the other
synchronized statement on the methods and run it overnight, will look
at the logs and report in the morning.
Here's the code pattern I just think is wrong (pseudo). It's repeated
several times...
public synchronized RefCountedIndexWriter getIndexWriter(SolrCore core)
throws IOException {
if (closed) {
throw new RuntimeException(SolrCoreState already closed);
}
synchronized (writerPauseLock) {
all the rest of the method
}
}
On Tue, Jan 29, 2013 at 1:32 PM, Mark Miller markrmil...@gmail.com wrote:
There is a lot of complicated interplay between locks in that area of the
code - small changes can easily get you into trouble.
Can you modify your test to run on the code before your patch? That would
help in telling if it's something existing or something your introducing.
I still plan on looking at this issue closer this week, so perhaps I can
offer some more help soon.
- Mark
On Jan 29, 2013, at 1:26 PM, Erick Erickson erickerick...@gmail.com wrote:
Two runs doth not a conclusion reach, but removing synchronized from:
DefaultSolrCoreState.getIndexWriter (line 78)
let me run for an hour, at least twice. And my stress test succeeds,
which fires up 15 indexing threads on 100 cores (transient core size
is 20), indexes documents for an hour while another 15 threads fire
off queries. At the end, it inspects each core to see if there are the
expected number of documents.
But that's kinda a frail reed to pin my hopes on, these are
notoriously hard to reproduce.
I'll set this up to run on an old machine for much longer later today.
Does anyone who knows that code know whether I'm playing with fire? I
haven't looked at the synchronization in that code to try to figure
out the purpose, I'm hoping someone will glance at it and say that's
wrong.
I'll dig into it later and see how much I can figure out about whether it's
safe
FWIW,
On Tue, Jan 29, 2013 at 8:31 AM, Erick Erickson erickerick...@gmail.com
wrote:
All:
As part of SOLR-4196, I'm opening and closing cores at a furious rate.
My tests are running for 20-40 minutes then locking up quite
regularly. Of course the first place I'm looking is my recent code,
since it has a bunch of synchronized blocks.
The deadlock is definitely happening at a call from the new code to
close a Solr core, so to really look at this anyone will need to get
the patch I'll put up in a minute. The deadlock trace is below.
But without going that far, I question whether it's really anything to
do with new synchronizations I'm doing or whether it's just something
that's been lurking for a while and I'm flushing out of the woodwork.
Re: Stress test deadlocks
On Jan 29, 2013, at 10:26 PM, Erick Erickson erickerick...@gmail.com wrote: Why synchronize the entire method and then synchronize everything except the error condition on a _different_ object? Because they are different locks protecting different state. Def cannot be safely removed. - Mark - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
Re: Stress test deadlocks
On Jan 29, 2013, at 10:26 PM, Erick Erickson erickerick...@gmail.com wrote: I'm not entirely sure what it would show though, since you don't get into this situation without loading and unloading cores at the same time, the stuff from SOLR-1028 and SOLR-4300. Which you couldn't do before this rapidly. I don't follow this at all - of course you could rapidly load and unload cores at the same time before this patch? If you cannot easily produce a test that causes deadlock without your patch, I'm less inclined to believe it's an existing issue. Like I said, that synchronization is complicated - it's easy to mess it up if you don't follow how it all works. - Mark - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
Re: Stress test deadlocks
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 erickerick...@gmail.com 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: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
Re: Stress test deadlocks
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 markrmil...@gmail.com 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 erickerick...@gmail.com 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
