聊聊、Jstack 解决生产问题

最近项目很多，所在公司是一家金融企业。从 APP 端到基金公司，整个体系涉及到很多系统。而我所负责的，正好是整个体系尾部，业务核心。前段时间，隔几天总会有用户购买理财产品失败，但是日志里面没有任何异常，也没有超时日志输出。上面领导对这件事情也很重视，生产无小事，尤其是金融行业，天天跟钱打交道，而且数额巨大。

既然日志看不出问题，就只能去服务器上查找问题了。这个时候 Jstack 就帮上忙了。

Java 本身提供虚拟机堆栈调试监控工具，我们平时写代码，也会打印堆栈信息。 Jstack 用于打印出给定的 Java 进程ID 或 core file 或远程调试服务的 Java 堆栈信息。用法很简单 Jstack -l 8898 > stack.txt，将堆栈消息输出到指定的文档，这样方便查看。

在服务器上查看端口情况，发现有一个端口一直 waiting，而且调用的是 Dubbo 服务。于是查出 PID，输出堆栈信息，果然线程一直挂着，就是用户购买理财产品请求线程。

"http-8082-7" daemon prio=6 tid=0x000000000c031000 nid=0x1b74 runnable [0x0000000012d6e000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(FileOutputStream.java:345)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    - locked <0x00000000c4d1f7e0> (a java.io.BufferedOutputStream)
    at java.io.PrintStream.write(PrintStream.java:482)
    - locked <0x00000000c4cf81a0> (a java.io.PrintStream)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
    - locked <0x00000000c4cf8220> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
    at java.io.PrintStream.write(PrintStream.java:527)
    - locked <0x00000000c4cf81a0> (a java.io.PrintStream)
    at java.io.PrintStream.print(PrintStream.java:669)
    at java.io.PrintStream.println(PrintStream.java:823)
    - locked <0x00000000c4cf81a0> (a java.io.PrintStream)
    at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:242)
    at java.lang.Throwable$WrappedPrintStream.println(Throwable.java:748)
    at java.lang.Throwable.printStackTrace(Throwable.java:655)
    - locked <0x00000000c4cefc10> (a org.apache.tomcat.util.log.SystemLogHandler)
    at java.lang.Throwable.printStackTrace(Throwable.java:643)
    at java.lang.Throwable.printStackTrace(Throwable.java:634)
    at com.szkingdom.kfps.service.file.util.HttpSendServiceImpl.send(HttpSendServiceImpl.java:267)
    at com.szkingdom.kfps.http.service.impl.HttpServiceDefaultImpl.httpInvoke(HttpServiceDefaultImpl.java:66)
    at com.szkingdom.kfps.service.acct.AcctServiceAbstract.acctInvoke(AcctServiceAbstract.java:108)
    at com.szkingdom.kfps.service.acct.AcctBuyServiceImpl.excuete(AcctBuyServiceImpl.java:62)
    at com.szkingdom.kfps.dispatch.WebGateDispatch.excuete(WebGateDispatch.java:37)
    at com.szkingdom.kfps.servlet.BaseServlet.doProcess(BaseServlet.java:108)
    at com.szkingdom.kfps.servlet.acct.AcctServlet.doPost(AcctServlet.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:643)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:723)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
    at java.lang.Thread.run(Thread.java:745)

上面堆栈消息，可以看到

locked <0x00000000c4cefc10> (a org.apache.tomcat.util.log.SystemLogHandler)
    at java.lang.Throwable.printStackTrace(Throwable.java:643)
    at java.lang.Throwable.printStackTrace(Throwable.java:634)
    at com.szkingdom.kfps.service.file.util.HttpSendServiceImpl.send(HttpSendServiceImpl.java:267)

于是找到 HttpSendServiceImpl 267 行，看看究竟是怎么回事。

e.printStackTrace(); 是的，问题就出在了这一行代码。实质上，用户购买理财产品确实超时了，但是抛出异常后，正常流程是打印异常日志，但是由于时间段是在请求高峰期，
而且 tomcat 存在控制台输出日志线程锁死 bug。这个也是查了很多资料才知道。于是注释掉打印堆栈信息到控制台，监控系统到现在，几个月过去了，没有再出现这种线程挂起
锁死情况。

 时间有限，谢谢大家观看！希望对大家能有一点点帮助。