求有经验的Java大牛看看,Tomcat 中System.out.println()造成死锁?报错-问答-阿里云开发者社区-阿里云

开发者社区> 问答> 正文

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

爱吃鱼的程序员 2020-06-08 15:18:50 32

这几天有个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大牛帮忙看看

Java 应用服务中间件
分享到
取消 提交回答
全部回答(1)
  • 爱吃鱼的程序员
    2020-06-08 15:19:04

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

    打日志用sytem.out.println,涨姿势了.

    回复 @不日小鸡:都说是新手了....就不要纠结这个了。我们项目中配了日志框架,可是新加入的同学总是习惯性的用System.out.println。问题不是为什么会用System.out.println,而是为什么tomcat会假死...回复 @ZhangFinder:你这个当然,我就表示呵呵了打印日志当然用log4j,我只是不明白为何system.out.println会死锁...

    你这个是IO阻塞了吧

    "http-bio-8080-exec-13"daemonprio=6tid=0x04ccc000nid=0x22a0runnable[0x0583d000..0x0583fae8]java.lang.Thread.State:RUNNABLE

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

    java.lang.Thread.State:RUNNABLEatjava.io.FileOutputStream.writeBytes(NativeMethod)atjava.io.FileOutputStream.write(FileOutputStream.java:260)atjava.io.BufferedOutputStream.write(BufferedOutputStream.java:105)-locked<0x23c0ab18>(ajava.io.BufferedOutputStream)atjava.io.PrintStream.write(PrintStream.java:430)

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

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

    引用来自“wgzhxy”的评论

    "http-bio-8080-exec-13"daemonprio=6tid=0x04ccc000nid=0x22a0runnable[0x0583d000..0x0583fae8]java.lang.Thread.State:RUNNABLE

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

    java.lang.Thread.State:RUNNABLEatjava.io.FileOutputStream.writeBytes(NativeMethod)atjava.io.FileOutputStream.write(FileOutputStream.java:260)atjava.io.BufferedOutputStream.write(BufferedOutputStream.java:105)-locked<0x23c0ab18>(ajava.io.BufferedOutputStream)atjava.io.PrintStream.write(PrintStream.java:430)

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

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

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

    catalina文件太大了,flush的时候阻塞了吧;

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

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

    0 0
开发与运维
使用钉钉扫一扫加入圈子
+ 订阅

集结各类场景实战经验,助你开发运维畅行无忧

推荐文章
相似问题
推荐课程