1.背景

老化环境上由于交换机重启，导致服务器出现短暂的网络中断状态，一天后网络恢复正常后，服务器中某个服务出现假死状态

排查服务日志并没有发现内存溢出之类的错误，使用swagger-ui访问接口也可以交互，说明服务仍是正常运行的，但是服务的存储数据功能却暂停了。

通过jstack pid 导出该服务的堆栈信息，发现一个有趣的现象，pool-15-thread-1线程获取了锁<0x00000006c0050b18>，与此同时其他线程也需要获取锁<0x00000006c0050b18>，从而造成了其他线程处于BLOCKED状态。

"pool-15-thread-1" #70 prio=5 os_prio=0 tid=0x00007f7bd4ea6800 nid=0xfd73 runnable [0x00007f7a57afd000]java.lang.Thread.State: RUNNABLEat java.io.FileOutputStream.writeBytes(Native Method)at java.io.FileOutputStream.write(FileOutputStream.java:326)at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)- locked <0x00000006c0050b38> (a java.io.BufferedOutputStream)at java.io.PrintStream.write(PrintStream.java:482)- locked <0x00000006c0050b18> (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 <0x00000006c0050c58> (a java.io.OutputStreamWriter)at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)at java.io.PrintStream.write(PrintStream.java:527)- locked <0x00000006c0050b18> (a java.io.PrintStream)at java.io.PrintStream.print(PrintStream.java:669)at java.io.PrintStream.println(PrintStream.java:823)- locked <0x00000006c0050b18> (a java.io.PrintStream)at java.lang.Throwable$WrappedPrintStream.println(Throwable.java:749)at java.lang.Throwable.printStackTrace(Throwable.java:659)- locked <0x00000006c0050b18> (a java.io.PrintStream)at java.lang.Throwable.printStackTrace(Throwable.java:644)at java.lang.Throwable.printStackTrace(Throwable.java:635)at com.yjy.storage.ConsumerDisOrderMsg.ping(ConsumerDisOrderMsg.java:639)at com.yjy.storage.ConsumerDisOrderMsg.lambda$checkInfluxDB$2(ConsumerDisOrderMsg.java:280)at com.yjy.storage.ConsumerDisOrderMsg$$Lambda$710/1752001901.accept(Unknown Source)at java.util.HashMap.forEach(HashMap.java:1289)at com.yjy.storage.ConsumerDisOrderMsg.checkInfluxDB(ConsumerDisOrderMsg.java:279)at sun.reflect.GeneratedMethodAccessor172.invoke(Unknown Source)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93)at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)at java.util.concurrent.FutureTask.run(FutureTask.java:266)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at java.lang.Thread.run(Thread.java:748)

虽然pool-15-thread-1线程处于runnable状态，但是实际上该线程并未往下执行，而是一直阻塞在java.io.FileOutputStream.writeBytes(Native Method)上

通过查询官网文档得知，处于runnable状态的线程，并不一定是在真正执行中，也可能是在等待来自操作系统的其他资源

分析到这里，可以知道pool-15-thread-1这个线程虽然处于runnable状态，但是一定是在等待某些资源，从而一直阻塞住了，从而导致获取的锁没有释放，进一步的导致其他线程一直处于BLOCKED状态，从而导致服务的部分功能无法使用。

2.过程

2.1问题起源

pool-15-thread-1这个线程到底在等待什么资源呢？继续看该线程的堆栈信息

可以发现，在调用业务代码中的ping方法后，程序执行了e.printStackTrace，从这之后就一发不可收拾了。到这里，基本可以定位到引发这个问题的源代码是它了。

2.2源码分析

简单来说，e.printStackTrace会通过全局的输出流System.err输出错误信息，在输出的过程中，会对System.err加锁，所以多线程执行e.printStackTrace的时候，同一时间只有一个线程可以获取到System.err对象，其他线程阻塞等待，这里就可以解释堆栈中出现的，一个线程得到了System.err的锁，其他线程都处于阻塞状态，但是到这里还不能够解释，为什么获得System.err的锁的线程，虽然是runnable，但是却一直阻塞住呢？

    public void printStackTrace() {printStackTrace(System.err);}public void printStackTrace(PrintStream s) {printStackTrace(new WrappedPrintStream(s));}private void printStackTrace(PrintStreamOrWriter s) {// Guard against malicious overrides of Throwable.equals by// using a Set with identity equality semantics.Set dejaVu =Collections.newSetFromMap(new IdentityHashMap());dejaVu.add(this);synchronized (s.lock()) {// Print our stack traces.println(this);StackTraceElement[] trace = getOurStackTrace();for (StackTraceElement traceElement : trace)s.println("\tat " + traceElement);// Print suppressed exceptions, if anyfor (Throwable se : getSuppressed())se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION, "\t", dejaVu);// Print cause, if anyThrowable ourCause = getCause();if (ourCause != null)ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, "", dejaVu);}}private static class WrappedPrintStream extends PrintStreamOrWriter {private final PrintStream printStream;WrappedPrintStream(PrintStream printStream) {this.printStream = printStream;}Object lock() {return printStream;}void println(Object o) {printStream.println(o);}}

2.3操作系统的流

上面虽然知道了为什么会出现其他线程阻塞的原因，但是还无法解释为什么pool-15-thread-1线程一直手握System.err的锁不放。看e.printStackTrace源码的时候，看到System.err这个对象时，突然想到操作系统的三个流：标准输入流、标准输出流、标准错误流。通过查询资料知道，JAVA中的System.in、System.out、System.err刚好对应操作系统的三个流。

这时候灵光一闪，去查看了下操作系统中，该进程对应的fd文件夹[/proc/服务进程id/fd]，发现里面有很多文件描述符，其中需要关注的是0、1、2这三个，它们分别对应标准输入流、标准输出流、标准错误流。

因为这边是e.printStackTrace导致的，所以是由于标准错误流导致的，对应的就是2的这条记录

可以看出，操作系统的标准错误流最终指向pipe管道，也就是说，该服务中所有的e.printStackTrace打印的信息全部都会写入pipe中。

分析到这里，已经离真相八九不离十了。由于程序的所有信息最终会输入到操作系统中的pipe管道中，而这个pipe中的信息却没有其他进程输出消费，导致pipe被撑满了，从而导致pool-15-thread-1这个线程虽然处于runnable状态，但是一直在等待io[pipe撑满了，线程一直想写，但是写不进去了，阻塞住，没有释放锁]，最终导致整个服务其他使用到System.err对象的线程无限阻塞。

3.解决

通过整个分析，可以推测出当时的情况是这样的：由于服务器断网，导致程序中某些跟网络相关的调用出现异常，try catch后通过e.printStackTrace打印异常堆栈，由于断网时长长达一天，从而导致网络中断的错误不断的打印，即不断的往pipe中写，直到某一个时刻，pipe被撑爆了，写不进去后开始阻塞而不释放System.err的锁，进而引发其他线程阻塞，导致整个服务功能不可用。

既然知道了整个过程的缘由，对症下药也就显得得心应手了。

解决办法：

（1）若不想重启服务，则可以进入/proc/该服务进程id/fd中，直接cat 2，通过cat命令将pipe中的信息输出到控制台中，相当于清空pipe。

（2）若可以重启服务，则启动服务的时候可以将日志重定向都某个文件，这样标准输入、标准输出流、标准错误流等都会被重定向到文件，而不通过pipe

java -jar xxx.jar > xxx.out 2>&1 &

建议：

（1）生产环境下，不要使用能够输出到控制台的打印代码，例如e.printStackTrace、System.out.println等

（2）引入日志框架，将需要打印的信息写入日志文件中，且生产环境下禁用console

4.疑惑

（1）pipe表现出来的现象是被撑满，导致无法再写入了，那pipe的默认大小是多少呢？

本文来自互联网用户投稿，文章观点仅代表作者本人，不代表本站立场，不承担相关法律责任。如若转载，请注明出处。 如若内容造成侵权/违法违规/事实不符，请点击【内容举报】进行投诉反馈！