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 Jeff Newburn <jn...@zappos.com> on 2009/09/27 16:51:55 UTC
Thread Blocking Radomly
It appears that a few seconds after midnight every night our solr 1.4
instances block for about 15-30 seconds and stop serving search requests. I
have included a stack trace of the the running thread and one that is
blocked by it. Please let me know of any way I can stop this or if it is a
solr issue at all.
"http-8080-exec-5" - Thread t@37
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.close0(Native Method)
at java.io.FileOutputStream.close(FileOutputStream.java:279)
at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
- locked java.io.FileWriter@@">295650d <monitor://>
at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
at java.io.PrintWriter.close(PrintWriter.java:295)
- locked java.io.FileWriter@@">295650d <monitor://>
at org.apache.juli.FileHandler.close(FileHandler.java:159)
at org.apache.juli.FileHandler.publish(FileHandler.java:120)
- locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
at java.util.logging.Logger.log(Logger.java:472)
at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
at
org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
03)
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
232)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
FilterChain.java:235)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
ain.java:206)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
va:233)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
va:175)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
:109)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at
org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
879)
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
ttp11NioProtocol.java:719)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
2080)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:885)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
07)
at java.lang.Thread.run(Thread.java:619)
Locked ownable synchronizers:
- locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">b5117a
<monitor://>
"http-8080-exec-6" - Thread t@38
java.lang.Thread.State: BLOCKED on org.apache.juli.FileHandler@e0f34c5
owned by: http-8080-exec-5
at java.util.logging.Handler.getLevel(Handler.java:250)
at java.util.logging.Handler.isLoggable(Handler.java:267)
at org.apache.juli.FileHandler.publish(FileHandler.java:107)
at java.util.logging.Logger.log(Logger.java:472)
at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
at
org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
03)
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
232)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
FilterChain.java:235)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
ain.java:206)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
va:233)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
va:175)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
:109)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at
org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
879)
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
ttp11NioProtocol.java:719)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
2080)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:885)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
07)
at java.lang.Thread.run(Thread.java:619)
Locked ownable synchronizers:
- locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">1ac730b
<monitor://>
--
Jeff Newburn
Software Engineer, Zappos.com
jnewburn@zappos.com - 702-943-7562
Re: Thread Blocking Radomly
Posted by Mark Miller <ma...@gmail.com>.
Mark Miller wrote:
> Its certainly happening when its trying to switch to a new log file. It
> doesn't try and close the file otherwise. Why there is such a pause
> doing it, I dunno. Perhaps because there are tons of file descriptors
> around?
>
> Does it happen on a fresh system, or did it just start after running for
> a long time? I recently found and resolved a file descriptor leak in the
> java replication code.
>
>
bq. Additionally, we see similar things during the day.
To tell you the truth, thats likely something else. Can you get a tread
dump then?
Tomcats FileHandler rolls to a new file when the first 10 digits of
System.currentTimeMillis changes.
I haven't done the math, but I'm guessing thats daily.
You won't get a block at the point your showing unless that happens.
--
- Mark
http://www.lucidimagination.com
Re: Thread Blocking Radomly
Posted by Mark Miller <ma...@gmail.com>.
Its certainly happening when its trying to switch to a new log file. It
doesn't try and close the file otherwise. Why there is such a pause
doing it, I dunno. Perhaps because there are tons of file descriptors
around?
Does it happen on a fresh system, or did it just start after running for
a long time? I recently found and resolved a file descriptor leak in the
java replication code.
--
- Mark
http://www.lucidimagination.com
Jeffery Newburn wrote:
> I originally thought it was replication but one of the servers
> exhibited the same issue with polling disabled. If it is tomcat why
> would it block for so long on a simple log rotation?
>
> Additionally, we see similar things during the day. Replication often
> is around the occurance but never at the same time
>
>
>
> On Sep 27, 2009, at 8:32 AM, "Yonik Seeley"
> <yo...@lucidimagination.com> wrote:
>
>> Perhaps something like Tomcat rotating it's log files nightly?
>>
>> -Yonik
>> http://www.lucidimagination.com
>>
>> On Sun, Sep 27, 2009 at 11:13 AM, Mark Miller <ma...@gmail.com>
>> wrote:
>>> Doesn't sound so random ;)
>>>
>>> Do you have anything specific going on at that time? Replication,
>>> something else scheduled? Pretty odd it would happen at around the same
>>> time every night unless something is set to occur then ...
>>>
>>> Jeff Newburn wrote:
>>>> It appears that a few seconds after midnight every night our solr 1.4
>>>> instances block for about 15-30 seconds and stop serving search
>>>> requests. I
>>>> have included a stack trace of the the running thread and one that is
>>>> blocked by it. Please let me know of any way I can stop this or if
>>>> it is a
>>>> solr issue at all.
>>>>
>>>> "http-8080-exec-5" - Thread t@37
>>>> java.lang.Thread.State: RUNNABLE
>>>> at java.io.FileOutputStream.close0(Native Method)
>>>> at java.io.FileOutputStream.close(FileOutputStream.java:279)
>>>> at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
>>>> at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
>>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>>> at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
>>>> at java.io.PrintWriter.close(PrintWriter.java:295)
>>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>>> at org.apache.juli.FileHandler.close(FileHandler.java:159)
>>>> at org.apache.juli.FileHandler.publish(FileHandler.java:120)
>>>> - locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
>>>> at java.util.logging.Logger.log(Logger.java:472)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
>>>> at
>>>> org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
>>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
>>>>
>>>> 03)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
>>>>
>>>> 232)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
>>>>
>>>> FilterChain.java:235)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
>>>>
>>>> ain.java:206)
>>>> at
>>>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
>>>>
>>>> va:233)
>>>> at
>>>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
>>>>
>>>> va:175)
>>>> at
>>>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
>>>>
>>>> )
>>>> at
>>>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
>>>>
>>>> )
>>>> at
>>>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
>>>>
>>>> :109)
>>>> at
>>>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
>>>>
>>>> at
>>>> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
>>>>
>>>> 879)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
>>>>
>>>> ttp11NioProtocol.java:719)
>>>> at
>>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
>>>>
>>>> 2080)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>>>>
>>>> va:885)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>>>>
>>>> 07)
>>>> at java.lang.Thread.run(Thread.java:619)
>>>> Locked ownable synchronizers:
>>>> - locked
>>>> java.util.concurrent.locks.ReentrantLock$NonfairSync@@">b5117a
>>>> <monitor://>
>>>>
>>>>
>>>> "http-8080-exec-6" - Thread t@38
>>>> java.lang.Thread.State: BLOCKED on
>>>> org.apache.juli.FileHandler@e0f34c5
>>>> owned by: http-8080-exec-5
>>>> at java.util.logging.Handler.getLevel(Handler.java:250)
>>>> at java.util.logging.Handler.isLoggable(Handler.java:267)
>>>> at org.apache.juli.FileHandler.publish(FileHandler.java:107)
>>>> at java.util.logging.Logger.log(Logger.java:472)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
>>>> at
>>>> org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
>>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
>>>>
>>>> 03)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
>>>>
>>>> 232)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
>>>>
>>>> FilterChain.java:235)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
>>>>
>>>> ain.java:206)
>>>> at
>>>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
>>>>
>>>> va:233)
>>>> at
>>>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
>>>>
>>>> va:175)
>>>> at
>>>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
>>>>
>>>> )
>>>> at
>>>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
>>>>
>>>> )
>>>> at
>>>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
>>>>
>>>> :109)
>>>> at
>>>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
>>>>
>>>> at
>>>> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
>>>>
>>>> 879)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
>>>>
>>>> ttp11NioProtocol.java:719)
>>>> at
>>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
>>>>
>>>> 2080)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>>>>
>>>> va:885)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>>>>
>>>> 07)
>>>> at java.lang.Thread.run(Thread.java:619)
>>>> Locked ownable synchronizers:
>>>> - locked
>>>> java.util.concurrent.locks.ReentrantLock$NonfairSync@@">1ac730b
>>>> <monitor://>
>>>> --
>>>> Jeff Newburn
>>>> Software Engineer, Zappos.com
>>>> jnewburn@zappos.com - 702-943-7562
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> - Mark
>>>
>>> http://www.lucidimagination.com
>>>
>>>
>>>
>>>
Re: Thread Blocking Radomly
Posted by Jeff Newburn <jn...@zappos.com>.
Further interestingness with replication on the thread blocking issue. 1
core seems to take a VERY long time to replicate. This duration is close to
5 minutes when cores 2x its size take like 100 seconds to pull down. The
searcher is also taking about 4-5 minutes to warm when an almost identical
core takes only a fraction of a second. Is there something with that core
that could be bogging down the whole instance?
--
Jeff Newburn
Software Engineer, Zappos.com
jnewburn@zappos.com - 702-943-7562
> From: Jeffery Newburn <jn...@zappos.com>
> Reply-To: <so...@lucene.apache.org>
> Date: Sun, 27 Sep 2009 14:14:24 -0700
> To: <so...@lucene.apache.org>
> Subject: Re: Thread Blocking Radomly
>
> I originally thought it was replication but one of the servers
> exhibited the same issue with polling disabled. If it is tomcat why
> would it block for so long on a simple log rotation?
>
> Additionally, we see similar things during the day. Replication often
> is around the occurance but never at the same time
>
>
>
> On Sep 27, 2009, at 8:32 AM, "Yonik Seeley"
> <yo...@lucidimagination.com> wrote:
>
>> Perhaps something like Tomcat rotating it's log files nightly?
>>
>> -Yonik
>> http://www.lucidimagination.com
>>
>> On Sun, Sep 27, 2009 at 11:13 AM, Mark Miller
>> <ma...@gmail.com> wrote:
>>> Doesn't sound so random ;)
>>>
>>> Do you have anything specific going on at that time? Replication,
>>> something else scheduled? Pretty odd it would happen at around the
>>> same
>>> time every night unless something is set to occur then ...
>>>
>>> Jeff Newburn wrote:
>>>> It appears that a few seconds after midnight every night our solr
>>>> 1.4
>>>> instances block for about 15-30 seconds and stop serving search
>>>> requests. I
>>>> have included a stack trace of the the running thread and one that
>>>> is
>>>> blocked by it. Please let me know of any way I can stop this or
>>>> if it is a
>>>> solr issue at all.
>>>>
>>>> "http-8080-exec-5" - Thread t@37
>>>> java.lang.Thread.State: RUNNABLE
>>>> at java.io.FileOutputStream.close0(Native Method)
>>>> at java.io.FileOutputStream.close(FileOutputStream.java:279)
>>>> at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
>>>> at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
>>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>>> at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
>>>> at java.io.PrintWriter.close(PrintWriter.java:295)
>>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>>> at org.apache.juli.FileHandler.close(FileHandler.java:159)
>>>> at org.apache.juli.FileHandler.publish(FileHandler.java:120)
>>>> - locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
>>>> at java.util.logging.Logger.log(Logger.java:472)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:
>>>> 587)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:
>>>> 284)
>>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.execute
>>>> (SolrDispatchFilter.java:3
>>>> 03)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter
>>>> (SolrDispatchFilter.java:
>>>> 232)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
>>>> (Application
>>>> FilterChain.java:235)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter
>>>> (ApplicationFilterCh
>>>> ain.java:206)
>>>> at
>>>> org.apache.catalina.core.StandardWrapperValve.invoke
>>>> (StandardWrapperValve.ja
>>>> va:233)
>>>> at
>>>> org.apache.catalina.core.StandardContextValve.invoke
>>>> (StandardContextValve.ja
>>>> va:175)
>>>> at
>>>> org.apache.catalina.core.StandardHostValve.invoke
>>>> (StandardHostValve.java:128
>>>> )
>>>> at
>>>> org.apache.catalina.valves.ErrorReportValve.invoke
>>>> (ErrorReportValve.java:102
>>>> )
>>>> at
>>>> org.apache.catalina.core.StandardEngineValve.invoke
>>>> (StandardEngineValve.java
>>>> :109)
>>>> at
>>>> org.apache.catalina.connector.CoyoteAdapter.service
>>>> (CoyoteAdapter.java:286)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProcessor.process
>>>> (Http11NioProcessor.java:
>>>> 879)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProtocol
>>>> $Http11ConnectionHandler.process(H
>>>> ttp11NioProtocol.java:719)
>>>> at
>>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run
>>>> (NioEndpoint.java:
>>>> 2080)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask
>>>> (ThreadPoolExecutor.ja
>>>> va:885)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run
>>>> (ThreadPoolExecutor.java:9
>>>> 07)
>>>> at java.lang.Thread.run(Thread.java:619)
>>>> Locked ownable synchronizers:
>>>> - locked java.util.concurrent.locks.ReentrantLock
>>>> $NonfairSync@@">b5117a
>>>> <monitor://>
>>>>
>>>>
>>>> "http-8080-exec-6" - Thread t@38
>>>> java.lang.Thread.State: BLOCKED on
>>>> org.apache.juli.FileHandler@e0f34c5
>>>> owned by: http-8080-exec-5
>>>> at java.util.logging.Handler.getLevel(Handler.java:250)
>>>> at java.util.logging.Handler.isLoggable(Handler.java:267)
>>>> at org.apache.juli.FileHandler.publish(FileHandler.java:107)
>>>> at java.util.logging.Logger.log(Logger.java:472)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:
>>>> 587)
>>>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:
>>>> 284)
>>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.execute
>>>> (SolrDispatchFilter.java:3
>>>> 03)
>>>> at
>>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter
>>>> (SolrDispatchFilter.java:
>>>> 232)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
>>>> (Application
>>>> FilterChain.java:235)
>>>> at
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter
>>>> (ApplicationFilterCh
>>>> ain.java:206)
>>>> at
>>>> org.apache.catalina.core.StandardWrapperValve.invoke
>>>> (StandardWrapperValve.ja
>>>> va:233)
>>>> at
>>>> org.apache.catalina.core.StandardContextValve.invoke
>>>> (StandardContextValve.ja
>>>> va:175)
>>>> at
>>>> org.apache.catalina.core.StandardHostValve.invoke
>>>> (StandardHostValve.java:128
>>>> )
>>>> at
>>>> org.apache.catalina.valves.ErrorReportValve.invoke
>>>> (ErrorReportValve.java:102
>>>> )
>>>> at
>>>> org.apache.catalina.core.StandardEngineValve.invoke
>>>> (StandardEngineValve.java
>>>> :109)
>>>> at
>>>> org.apache.catalina.connector.CoyoteAdapter.service
>>>> (CoyoteAdapter.java:286)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProcessor.process
>>>> (Http11NioProcessor.java:
>>>> 879)
>>>> at
>>>> org.apache.coyote.http11.Http11NioProtocol
>>>> $Http11ConnectionHandler.process(H
>>>> ttp11NioProtocol.java:719)
>>>> at
>>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run
>>>> (NioEndpoint.java:
>>>> 2080)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask
>>>> (ThreadPoolExecutor.ja
>>>> va:885)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run
>>>> (ThreadPoolExecutor.java:9
>>>> 07)
>>>> at java.lang.Thread.run(Thread.java:619)
>>>> Locked ownable synchronizers:
>>>> - locked java.util.concurrent.locks.ReentrantLock
>>>> $NonfairSync@@">1ac730b
>>>> <monitor://>
>>>> --
>>>> Jeff Newburn
>>>> Software Engineer, Zappos.com
>>>> jnewburn@zappos.com - 702-943-7562
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> - Mark
>>>
>>> http://www.lucidimagination.com
>>>
>>>
>>>
>>>
Re: Thread Blocking Radomly
Posted by Jeffery Newburn <jn...@zappos.com>.
I originally thought it was replication but one of the servers
exhibited the same issue with polling disabled. If it is tomcat why
would it block for so long on a simple log rotation?
Additionally, we see similar things during the day. Replication often
is around the occurance but never at the same time
On Sep 27, 2009, at 8:32 AM, "Yonik Seeley"
<yo...@lucidimagination.com> wrote:
> Perhaps something like Tomcat rotating it's log files nightly?
>
> -Yonik
> http://www.lucidimagination.com
>
> On Sun, Sep 27, 2009 at 11:13 AM, Mark Miller
> <ma...@gmail.com> wrote:
>> Doesn't sound so random ;)
>>
>> Do you have anything specific going on at that time? Replication,
>> something else scheduled? Pretty odd it would happen at around the
>> same
>> time every night unless something is set to occur then ...
>>
>> Jeff Newburn wrote:
>>> It appears that a few seconds after midnight every night our solr
>>> 1.4
>>> instances block for about 15-30 seconds and stop serving search
>>> requests. I
>>> have included a stack trace of the the running thread and one that
>>> is
>>> blocked by it. Please let me know of any way I can stop this or
>>> if it is a
>>> solr issue at all.
>>>
>>> "http-8080-exec-5" - Thread t@37
>>> java.lang.Thread.State: RUNNABLE
>>> at java.io.FileOutputStream.close0(Native Method)
>>> at java.io.FileOutputStream.close(FileOutputStream.java:279)
>>> at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
>>> at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>> at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
>>> at java.io.PrintWriter.close(PrintWriter.java:295)
>>> - locked java.io.FileWriter@@">295650d <monitor://>
>>> at org.apache.juli.FileHandler.close(FileHandler.java:159)
>>> at org.apache.juli.FileHandler.publish(FileHandler.java:120)
>>> - locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
>>> at java.util.logging.Logger.log(Logger.java:472)
>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:
>>> 587)
>>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:
>>> 284)
>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>> at
>>> org.apache.solr.servlet.SolrDispatchFilter.execute
>>> (SolrDispatchFilter.java:3
>>> 03)
>>> at
>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter
>>> (SolrDispatchFilter.java:
>>> 232)
>>> at
>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
>>> (Application
>>> FilterChain.java:235)
>>> at
>>> org.apache.catalina.core.ApplicationFilterChain.doFilter
>>> (ApplicationFilterCh
>>> ain.java:206)
>>> at
>>> org.apache.catalina.core.StandardWrapperValve.invoke
>>> (StandardWrapperValve.ja
>>> va:233)
>>> at
>>> org.apache.catalina.core.StandardContextValve.invoke
>>> (StandardContextValve.ja
>>> va:175)
>>> at
>>> org.apache.catalina.core.StandardHostValve.invoke
>>> (StandardHostValve.java:128
>>> )
>>> at
>>> org.apache.catalina.valves.ErrorReportValve.invoke
>>> (ErrorReportValve.java:102
>>> )
>>> at
>>> org.apache.catalina.core.StandardEngineValve.invoke
>>> (StandardEngineValve.java
>>> :109)
>>> at
>>> org.apache.catalina.connector.CoyoteAdapter.service
>>> (CoyoteAdapter.java:286)
>>> at
>>> org.apache.coyote.http11.Http11NioProcessor.process
>>> (Http11NioProcessor.java:
>>> 879)
>>> at
>>> org.apache.coyote.http11.Http11NioProtocol
>>> $Http11ConnectionHandler.process(H
>>> ttp11NioProtocol.java:719)
>>> at
>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run
>>> (NioEndpoint.java:
>>> 2080)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask
>>> (ThreadPoolExecutor.ja
>>> va:885)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run
>>> (ThreadPoolExecutor.java:9
>>> 07)
>>> at java.lang.Thread.run(Thread.java:619)
>>> Locked ownable synchronizers:
>>> - locked java.util.concurrent.locks.ReentrantLock
>>> $NonfairSync@@">b5117a
>>> <monitor://>
>>>
>>>
>>> "http-8080-exec-6" - Thread t@38
>>> java.lang.Thread.State: BLOCKED on
>>> org.apache.juli.FileHandler@e0f34c5
>>> owned by: http-8080-exec-5
>>> at java.util.logging.Handler.getLevel(Handler.java:250)
>>> at java.util.logging.Handler.isLoggable(Handler.java:267)
>>> at org.apache.juli.FileHandler.publish(FileHandler.java:107)
>>> at java.util.logging.Logger.log(Logger.java:472)
>>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:
>>> 587)
>>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:
>>> 284)
>>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>>> at
>>> org.apache.solr.servlet.SolrDispatchFilter.execute
>>> (SolrDispatchFilter.java:3
>>> 03)
>>> at
>>> org.apache.solr.servlet.SolrDispatchFilter.doFilter
>>> (SolrDispatchFilter.java:
>>> 232)
>>> at
>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter
>>> (Application
>>> FilterChain.java:235)
>>> at
>>> org.apache.catalina.core.ApplicationFilterChain.doFilter
>>> (ApplicationFilterCh
>>> ain.java:206)
>>> at
>>> org.apache.catalina.core.StandardWrapperValve.invoke
>>> (StandardWrapperValve.ja
>>> va:233)
>>> at
>>> org.apache.catalina.core.StandardContextValve.invoke
>>> (StandardContextValve.ja
>>> va:175)
>>> at
>>> org.apache.catalina.core.StandardHostValve.invoke
>>> (StandardHostValve.java:128
>>> )
>>> at
>>> org.apache.catalina.valves.ErrorReportValve.invoke
>>> (ErrorReportValve.java:102
>>> )
>>> at
>>> org.apache.catalina.core.StandardEngineValve.invoke
>>> (StandardEngineValve.java
>>> :109)
>>> at
>>> org.apache.catalina.connector.CoyoteAdapter.service
>>> (CoyoteAdapter.java:286)
>>> at
>>> org.apache.coyote.http11.Http11NioProcessor.process
>>> (Http11NioProcessor.java:
>>> 879)
>>> at
>>> org.apache.coyote.http11.Http11NioProtocol
>>> $Http11ConnectionHandler.process(H
>>> ttp11NioProtocol.java:719)
>>> at
>>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run
>>> (NioEndpoint.java:
>>> 2080)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask
>>> (ThreadPoolExecutor.ja
>>> va:885)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run
>>> (ThreadPoolExecutor.java:9
>>> 07)
>>> at java.lang.Thread.run(Thread.java:619)
>>> Locked ownable synchronizers:
>>> - locked java.util.concurrent.locks.ReentrantLock
>>> $NonfairSync@@">1ac730b
>>> <monitor://>
>>> --
>>> Jeff Newburn
>>> Software Engineer, Zappos.com
>>> jnewburn@zappos.com - 702-943-7562
>>>
>>>
>>>
>>
>>
>> --
>> - Mark
>>
>> http://www.lucidimagination.com
>>
>>
>>
>>
Re: Thread Blocking Radomly
Posted by Yonik Seeley <yo...@lucidimagination.com>.
Perhaps something like Tomcat rotating it's log files nightly?
-Yonik
http://www.lucidimagination.com
On Sun, Sep 27, 2009 at 11:13 AM, Mark Miller <ma...@gmail.com> wrote:
> Doesn't sound so random ;)
>
> Do you have anything specific going on at that time? Replication,
> something else scheduled? Pretty odd it would happen at around the same
> time every night unless something is set to occur then ...
>
> Jeff Newburn wrote:
>> It appears that a few seconds after midnight every night our solr 1.4
>> instances block for about 15-30 seconds and stop serving search requests. I
>> have included a stack trace of the the running thread and one that is
>> blocked by it. Please let me know of any way I can stop this or if it is a
>> solr issue at all.
>>
>> "http-8080-exec-5" - Thread t@37
>> java.lang.Thread.State: RUNNABLE
>> at java.io.FileOutputStream.close0(Native Method)
>> at java.io.FileOutputStream.close(FileOutputStream.java:279)
>> at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
>> at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
>> - locked java.io.FileWriter@@">295650d <monitor://>
>> at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
>> at java.io.PrintWriter.close(PrintWriter.java:295)
>> - locked java.io.FileWriter@@">295650d <monitor://>
>> at org.apache.juli.FileHandler.close(FileHandler.java:159)
>> at org.apache.juli.FileHandler.publish(FileHandler.java:120)
>> - locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
>> at java.util.logging.Logger.log(Logger.java:472)
>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>> at
>> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
>> 03)
>> at
>> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
>> 232)
>> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
>> FilterChain.java:235)
>> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
>> ain.java:206)
>> at
>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
>> va:233)
>> at
>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
>> va:175)
>> at
>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
>> )
>> at
>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
>> )
>> at
>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
>> :109)
>> at
>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
>> at
>> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
>> 879)
>> at
>> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
>> ttp11NioProtocol.java:719)
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
>> 2080)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:885)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 07)
>> at java.lang.Thread.run(Thread.java:619)
>> Locked ownable synchronizers:
>> - locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">b5117a
>> <monitor://>
>>
>>
>> "http-8080-exec-6" - Thread t@38
>> java.lang.Thread.State: BLOCKED on org.apache.juli.FileHandler@e0f34c5
>> owned by: http-8080-exec-5
>> at java.util.logging.Handler.getLevel(Handler.java:250)
>> at java.util.logging.Handler.isLoggable(Handler.java:267)
>> at org.apache.juli.FileHandler.publish(FileHandler.java:107)
>> at java.util.logging.Logger.log(Logger.java:472)
>> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
>> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
>> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
>> at
>> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
>> 03)
>> at
>> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
>> 232)
>> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
>> FilterChain.java:235)
>> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
>> ain.java:206)
>> at
>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
>> va:233)
>> at
>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
>> va:175)
>> at
>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
>> )
>> at
>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
>> )
>> at
>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
>> :109)
>> at
>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
>> at
>> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
>> 879)
>> at
>> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
>> ttp11NioProtocol.java:719)
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
>> 2080)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:885)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 07)
>> at java.lang.Thread.run(Thread.java:619)
>> Locked ownable synchronizers:
>> - locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">1ac730b
>> <monitor://>
>> --
>> Jeff Newburn
>> Software Engineer, Zappos.com
>> jnewburn@zappos.com - 702-943-7562
>>
>>
>>
>
>
> --
> - Mark
>
> http://www.lucidimagination.com
>
>
>
>
Re: Thread Blocking Radomly
Posted by Mark Miller <ma...@gmail.com>.
Doesn't sound so random ;)
Do you have anything specific going on at that time? Replication,
something else scheduled? Pretty odd it would happen at around the same
time every night unless something is set to occur then ...
Jeff Newburn wrote:
> It appears that a few seconds after midnight every night our solr 1.4
> instances block for about 15-30 seconds and stop serving search requests. I
> have included a stack trace of the the running thread and one that is
> blocked by it. Please let me know of any way I can stop this or if it is a
> solr issue at all.
>
> "http-8080-exec-5" - Thread t@37
> java.lang.Thread.State: RUNNABLE
> at java.io.FileOutputStream.close0(Native Method)
> at java.io.FileOutputStream.close(FileOutputStream.java:279)
> at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
> at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
> - locked java.io.FileWriter@@">295650d <monitor://>
> at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
> at java.io.PrintWriter.close(PrintWriter.java:295)
> - locked java.io.FileWriter@@">295650d <monitor://>
> at org.apache.juli.FileHandler.close(FileHandler.java:159)
> at org.apache.juli.FileHandler.publish(FileHandler.java:120)
> - locked org.apache.juli.FileHandler@@">e0f34c <monitor://>
> at java.util.logging.Logger.log(Logger.java:472)
> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
> at
> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
> 03)
> at
> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
> 232)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
> FilterChain.java:235)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
> ain.java:206)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
> va:233)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
> va:175)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
> )
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
> )
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
> :109)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
> at
> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
> 879)
> at
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
> ttp11NioProtocol.java:719)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
> 2080)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:885)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 07)
> at java.lang.Thread.run(Thread.java:619)
> Locked ownable synchronizers:
> - locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">b5117a
> <monitor://>
>
>
> "http-8080-exec-6" - Thread t@38
> java.lang.Thread.State: BLOCKED on org.apache.juli.FileHandler@e0f34c5
> owned by: http-8080-exec-5
> at java.util.logging.Handler.getLevel(Handler.java:250)
> at java.util.logging.Handler.isLoggable(Handler.java:267)
> at org.apache.juli.FileHandler.publish(FileHandler.java:107)
> at java.util.logging.Logger.log(Logger.java:472)
> at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:587)
> at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:284)
> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1341)
> at
> org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:3
> 03)
> at
> org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:
> 232)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
> FilterChain.java:235)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
> ain.java:206)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
> va:233)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
> va:175)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128
> )
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102
> )
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
> :109)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
> at
> org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:
> 879)
> at
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(H
> ttp11NioProtocol.java:719)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:
> 2080)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:885)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 07)
> at java.lang.Thread.run(Thread.java:619)
> Locked ownable synchronizers:
> - locked java.util.concurrent.locks.ReentrantLock$NonfairSync@@">1ac730b
> <monitor://>
> --
> Jeff Newburn
> Software Engineer, Zappos.com
> jnewburn@zappos.com - 702-943-7562
>
>
>
--
- Mark
http://www.lucidimagination.com