Java Thread Lock

Question

I have a problem with my java environement. I am running Solr 1.3 (search engine) since over a year ago, and suddenly I have a lot of problems with it. All my thread pools (250) were randomly blocked once or twice a day. I have not made any changes to my solr application or my tomcat server.

I am running tomcat 5.5.25 and Solr 1.3. I got a thread dump when the system is completely overloaded:

igot as 240 stream similar to this:

"http-8080-Processor1" daemon prio=10 tid=0x0000000000b2e000 nid=0x193 waiting for monitor entry [0x000000004066c000..0x000000004066cb20] java.lang.Thread.State: BLOCKED (on object monitor) at java.util.logging.StreamHandler.publish(StreamHandler.java:174) - waiting to lock <0x00007fe37e72b340> (a java.util.logging.ConsoleHandler) at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88) at java.util.logging.Logger.log(Logger.java:472) at java.util.logging.Logger.doLog(Logger.java:494) at java.util.logging.Logger.log(Logger.java:517) at java.util.logging.Logger.info(Logger.java:1036) at org.apache.solr.core.SolrCore.execute(SolrCore.java:1212) at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:303) at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:232) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874) at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665) at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528) at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689) at java.lang.Thread.run(Thread.java:619) 

We see that this thread is blocked and waiting: <0x00007fe37e72b340>

The thread that actually owns <0x00007fe37e72b340> is as follows:

 "http-8080-Processor156" daemon prio=10 tid=0x0000000000df2000 nid=0x1e52 runnable [0x0000000044521000..0x0000000044521c20] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x00007fe37e3abcd8> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x00007fe37e3abca0> (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x00007fe37e72cd90> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at java.util.logging.StreamHandler.flush(StreamHandler.java:225) - locked <0x00007fe37e72b340> (a java.util.logging.ConsoleHandler) at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:89) at java.util.logging.Logger.log(Logger.java:472) at java.util.logging.Logger.doLog(Logger.java:494) at java.util.logging.Logger.log(Logger.java:517) at java.util.logging.Logger.info(Logger.java:1036) at org.apache.solr.core.SolrCore.execute(SolrCore.java:1212) at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:303) at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:232) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874) at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665) at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528) at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689) at java.lang.Thread.run(Thread.java:619) 

and this is the last part of my stream dump:

 "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10 tid=0x00007f6510349800 nid=0xbff waiting on condition [0x0000000041d8d000..0x0000000041d8dd20] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1548) at java.lang.Thread.run(Thread.java:619) "pool-1-thread-1" prio=10 tid=0x0000000000c26400 nid=0xbfe waiting on condition [0x000000004200e000..0x000000004200eca0] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00007f651b275510> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:946) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:906) at java.lang.Thread.run(Thread.java:619) "Low Memory Detector" daemon prio=10 tid=0x00007f6510004400 nid=0xbfa runnable [0x0000000000000000..0x0000000000000000] java.lang.Thread.State: RUNNABLE "CompilerThread1" daemon prio=10 tid=0x00007f6510001000 nid=0xbf9 waiting on condition [0x0000000000000000..0x0000000040d5e340] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x00000000006bc400 nid=0xbf8 waiting on condition [0x0000000000000000..0x0000000040c5d2d0] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x00000000006bb000 nid=0xbf7 runnable [0x0000000000000000..0x0000000040b5da30] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=10 tid=0x0000000000690c00 nid=0xbf6 in Object.wait() [0x000000004065e000..0x000000004065ed20] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00007f651aa10258> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x00007f651aa10258> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x000000000068f400 nid=0xbf5 in Object.wait() [0x000000004055d000..0x000000004055dca0] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00007f651aa10338> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x00007f651aa10338> (a java.lang.ref.Reference$Lock) "main" prio=10 tid=0x0000000000622400 nid=0xbeb runnable [0x0000000000000000..0x00007fff69fcbba0] java.lang.Thread.State: RUNNABLE "VM Thread" prio=10 tid=0x000000000068a000 nid=0xbf4 runnable "GC task thread#0 (ParallelGC)" prio=10 tid=0x000000000062cc00 nid=0xbec runnable "GC task thread#1 (ParallelGC)" prio=10 tid=0x000000000062e000 nid=0xbed runnable "GC task thread#2 (ParallelGC)" prio=10 tid=0x000000000062f400 nid=0xbee runnable "GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000000630400 nid=0xbef runnable "GC task thread#4 (ParallelGC)" prio=10 tid=0x0000000000631800 nid=0xbf0 runnable "GC task thread#5 (ParallelGC)" prio=10 tid=0x0000000000632c00 nid=0xbf1 runnable "GC task thread#6 (ParallelGC)" prio=10 tid=0x0000000000634000 nid=0xbf2 runnable "GC task thread#7 (ParallelGC)" prio=10 tid=0x0000000000635400 nid=0xbf3 runnable "VM Periodic Task Thread" prio=10 tid=0x00007f6510006800 nid=0xbfb waiting on condition JNI global references: 1201 

I know that this is not a thread deadlock problem, since one thread actually starts with all the resources that any other thread needs.

Has anyone understood what might cause this problem?

Answer 1

All your topics are registered. They have to burn to disk all the time. Every time one of your 240 threads goes to the logging line, there are problems accessing the disk.

It seems to me that a thread that has a lock is in RUNNABLE state.

I think he can expect some kind of external ressource to be released (e.g. for disk access)

Do you have low free disk space? Have you changed anything recently in your storage system?

Answer 2

If you are running Windows and the Java application starts the console, be careful not to click in the DOS window. The crap label window and copying the "function" blocks the output in the ConsoleHandler. Thus, any recorder trying to write to the screen is blocked. Writing to the console is performed in a normal call, and therefore the java thread will be in the RUNNING state, when in fact it is blocked, it simply cannot transfer this blocked status back to the application (because you are in the native space).

If the application is blocked (you clicked in the DOS field), click the "Continue" button to continue.

Answer 3

I have never used java.util.logging , so I don’t know if my suggestion is useful, but not accessible:
try using a different instance of java.util.logging.Logger , so not all 240 threads will be blocked on one monitor
(this will help if different instances of Logger use different instances of java.util.logging.ConsoleHandler ).

Answer 4

It seems that a thread that has "0x00007fe37e72b340" is blocked at the I / O level. Perhaps a disk problem (raid?)?

Can you dump the stream after 5 minutes if you see that the same stream is still blocked?

Answer 5

The stream after each log entry will be expensive if you have very detailed logs.

A quality fix is ​​a journal cleanup, probably based on an audit.

As a quick fix, override StreamHandler.flush or OutputStream.flush to not do it immediately. Do it only once, every so often. Please note, however, that you could potentially lose registration data just before the failure if you do so.

Answer 6

According to your log, the problem is related to using java.util.logging.ConsoleHandler.

First try disabling the console handler by removing it from the handlers and .handlers list in $ TOMCAT_HOME /conf/logging.properties. Look, there is still a problem.

If this helps, then this is definitely a problem with ConsoleHandler exit. Try checking if there is a problem in the "catalina.out" file. This is the file in which tomcat redirects the output of its console.