求有经验的Java大牛看看，Tomcat 中System.out.println()造成死锁

Question

这几天有个Java Web 项目，跑着跑着，tomcat就假死了，用Jstack PID 打印堆栈信息，发现大量的线程处于blocked状态。下图就是其中一个blocked线程.其它blocked线程报错内容和下图类似。

"http-bio-8080-exec-34" daemon prio=6 tid=0x042b4c00 nid=0x17b8 waiting for monitor entry [0x093af000..0x093afae8]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.io.PrintStream.println(PrintStream.java:756)
	- waiting to lock <0x23c04208> (a java.io.PrintStream)
	at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:264)
	at com.security.MyUsernamePasswordAuthenticationFilter.attemptAuthentication(MyUsernamePasswordAuthenticationFilter.java:33)
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:199)
...........

我定位到MyUsernamePasswordAuthenticationFilter.java:33行发现此处使用了System.out.println()，查看println()源码，发现System.out.println()方法是synchronized方法，也就是说可能是System.out.println()这个同步方法造成了死锁。

然而我查看了整个堆栈信息，也没发现有2个线程相互等待锁（业务代码中这一块也没有用线程同步，应该不是业务代码造成的死锁），那么死锁是如何发生的呢？

我找到最后一个处于RUNNABLE状态的线程，如下图：

"http-bio-8080-exec-13" daemon prio=6 tid=0x04ccc000 nid=0x22a0 runnable [0x0583d000..0x0583fae8]
   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 <0x23c0ab18> (a java.io.BufferedOutputStream)
	at java.io.PrintStream.write(PrintStream.java:430)
	- locked <0x23c04208> (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.flushBuffer(StreamEncoder.java:85)
	- locked <0x23c0ab58> (a java.io.OutputStreamWriter)
	at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168)
	at java.io.PrintStream.write(PrintStream.java:477)
	- locked <0x23c04208> (a java.io.PrintStream)
	at java.io.PrintStream.print(PrintStream.java:619)
	at java.io.PrintStream.println(PrintStream.java:756)
	- locked <0x23c04208> (a java.io.PrintStream)
	at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:264)
	at com.energy.web.EnergyAction.findRealtimeEnergyDataByEquipmentName(EnergyAction.java:60)
	at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.opensymphony.xwork2.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:452)
	at com.opensymphony.xwork2.DefaultActionInvocation.invokeActionOnly(DefaultActionInvocation.java:291)
	at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:254)
	at com.opensymphony.xwork2.interceptor.DefaultWorkflowInterceptor.doIntercept(DefaultWorkflowInterceptor.java:176)
	at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
	at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:248)
	at com.opensymphony.xwork2.validator.ValidationInterceptor.doIntercept(ValidationInterceptor.java:263)
..............

这个“”http-bio-8080-exec-13“”线程，获取了锁locked <0x23c04208> (a java.io.PrintStream)，但是没有释放它...为什么不释放呢？求大神解释下原因。堆栈中有sun.nio,死锁是否和nio有关(只是我的猜测)

还有个问题，从堆栈信息中可以看出，在tomcat 中调用System.out.println，println被定向到了org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:264)，这是否说明java 的system.out.println被tomcat的SystemLogHandler接管了呢？

求有经验的Java大牛帮忙看看

Answer 1

catalina.out是一个tomcat下所有app公用的日志文件，会不会是有别的程序抢占不放而导致其它程序一直等待呢

Answer 2

cmd 窗口我就遇过卡死，就是阻塞，程序不走了，应该不是死锁

Answer 3

catalina文件太大了，flush的时候阻塞了吧；

Answer 4

刚刚在CSDN上发现有个人遇到了和我类似的问题，但是没有人给出解决方案：http://bbs.csdn.net/topics/390954714?page=1

Answer 5

多线程打印sytem.out.println是没问题的，这个死锁感觉按道理不会成立才对。。。

Answer 6

引用来自“wgzhxy”的评论

"http-bio-8080-exec-13" daemon prio=6 tid=0x04ccc000 nid=0x22a0 runnable [0x0583d000..0x0583fae8]
   java.lang.Thread.State: RUNNABLE

看看这个线程在做啥，从栈信息来看， 

 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 <0x23c0ab18> (a java.io.BufferedOutputStream)
	at java.io.PrintStream.write(PrintStream.java:430)

 应该是在写文件，写文件怎么会用到java.io.PrintStream对象呢，是不是初始化为printStream给OutputStream了，结合上下文看看

Answer 7

我检查了上下文，上下文除了System.out.println就没有其他IO操作了。这里很奇怪，为什么会出现NIO

Answer 8

"http-bio-8080-exec-13" daemon prio=6 tid=0x04ccc000 nid=0x22a0 runnable [0x0583d000..0x0583fae8]
   java.lang.Thread.State: RUNNABLE

看看这个线程在做啥，从栈信息来看， 

 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 <0x23c0ab18> (a java.io.BufferedOutputStream)
	at java.io.PrintStream.write(PrintStream.java:430)

 应该是在写文件，写文件怎么会用到java.io.PrintStream对象呢，是不是初始化为printStream给OutputStream了，结合上下文看看

Answer 9

打印日志当然用log4j，我只是不明白为何system.out.println会死锁...

Answer 10

回复
你这个当然，我就表示呵呵了

Answer 11

回复
都说是新手了....就不要纠结这个了。我们项目中配了日志框架，可是新加入的同学总是习惯性的用System.out.println。问题不是为什么会用System.out.println，而是为什么tomcat会假死...

Answer 12

新手们写代码，总避免不了习惯性使用System.out.println，我只是不懂为何System.out.println会造成死锁