一个RUNNABLE状态的线程hang在了java.io.FileOutputStream.writeBytes方法上

1. 问题背景

web项目要定时拉取其他系统的数据，用Quartz做了一个定时作业。在联调时，为了知道作业的运行情况，将logback的root logger从warn调到了debug， root logger有两个appender，一个是ConsoleAppender，一个是RollingFileAppender。

2. 问题现象

在测试环境windows上，启动tomcat，观察tomcat弹出的console，能够打印出日志信息，没过多久打出了Quartz相关log，说明定时作业运行了。这时打开浏览器，登录web查看拉取的数据情况。在打开首页、登录等几个操作后，页面hang住了，处于假死状态。观察tomcat的console，log不再刷新，没有新log打出来，包括该打出的定时任务的log。

同时查看tomcat的8189端口网络连接情况，netstat -aon | findstr 8189，发现连接都是ESTABLISHED状态，说明浏览器的与tomcat一直处于连接状态。

3. 查找原因

首先想到的就是线程死锁，通过jstack -l pid > thread_dump.txt导出线程堆栈，发现tomcat的work线程http-bio-8189-exec[8,7,6,5,4]和Quartz的调度线程#0_QuartzSchedulerThread线程都是WAITING状态，都在等待<0x00000007f5ae3528>锁，而这个锁被http-bio-8189-exec-2线程持有，且此线程还是RUNNABLE状态。

一个RUNNABLE的线程会被调度，运行完成后释放锁。但过了一会，发现浏览器还是假死状态，再次jstack查看线程栈信息，这几个线程栈信息与之前的一样，状态没有改变，说明http-bio-8189-exec-2没有向下运行。

查看线程http-bio-8189-exec-2的堆栈信息，停在了java.io.FileOutputStream.writeBytes方法上，从堆栈上下文ch.qos.logback.core.joran.spi.ConsoleTarget$1.write可以知道，FileOutputStream写的目的地是console。从网上查询，还真在stackoverflow上找到了答案，现象与我的一样，只不过提问者是log4j。

On Windows, if you click in the console window, this will pause the console, e.g. the stdout buffer will fill up, and as the console appender writes serially, your application will hang until you release the console (press enter or so).

在Windows上，如果点击了console窗口会暂停控制台，如果console appender不停连续的写，那么标准输出缓冲区会被填满，应用就会hang住直到释放console(按下回车释放)。

结合我的情况，在调试的过程中，不知什么时候我点击了console导致它暂停了，然后我去操作web，由于log级别为debug，页面引用的js和css也比较多，这些请求会从filter走到SpringMVC的DispacherServlet，出现了大量spring框架的log写向console，引起缓冲区满不能再写，线程停在了那里。

那么一个RUNNABLE状态的线程为什么表现出了‘阻塞’的想象呢？通过查看Thread$State类的java doc，发现RUNNABLE是这样写的：

A thread in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor.

一个RUNNABLE状态的线程正在jvm中执行，但它有可能正等待系统资源，比如cpu。

同样，也可以是console。

那么为什么不把这种等待cpu和console的线程再起一个状态名字呢，我想如果那样的话，线程模型就过于复杂了，何况要设置一个因程序外状态变化来设置程序内线程状态的‘程序’，也不是一件容易的事。

4. 解决方法

在console选中的情况下，按一下回车。这时立刻就能看到log不停的从console打出来。

5. 参考

[1]https://stackoverflow.com/questions/634102/log4j-is-hanging-my-application-what-am-i-doing-wrong

6. 附录

6.1 环境

OS: 
    Windows Server 2008 R2 Enterprise Service Pack 1
java:
    java version "1.7.0_79"
    Java(TM) SE Runtime Environment (build 1.7.0_79-b15)
    Java HotSpot(TM) 64-Bit Server VM (build 24.79-b02, mixed mode)
tomcat:
    apache-tomcat-7.0.72

6.2 logback配置

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${catalina.base}/logs/foo.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${catalina.base}/logs/foo.%d{yyyy-MM-dd}.log</fileNamePattern>
      <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
  </appender>

  <!-- TRACE、DEBUG、INFO、WARN和ERROR -->
  <root level="DEBUG">
  	<appender-ref ref="STDOUT" />
  	<appender-ref ref="FILE" />
  </root>
</configuration>

6.3 线程堆栈信息

2017-05-23 11:48:53
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.79-b02 mixed mode):

"http-bio-8189-exec-10" daemon prio=6 tid=0x00000000173b3800 nid=0xed0 waiting on condition [0x000000001a8ce000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007f57a5378> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None

"http-bio-8189-exec-9" daemon prio=6 tid=0x00000000173b2800 nid=0x1ca0 waiting on condition [0x000000001a76e000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007f57a5378> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None

"http-bio-8189-exec-8" daemon prio=6 tid=0x00000000173b2000 nid=0x1a00 waiting on condition [0x000000001a64e000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007f5ae3528> (a java.util.concurrent.locks.ReentrantLock$FairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
	at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:229)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
	at ch.qos.logback.classic.Logger.log(Logger.java:788)
	at org.apache.commons.logging.impl.SLF4JLocationAwareLog.debug(SLF4JLocationAwareLog.java:133)
	at org.springframework.security.web.util.matcher.AntPathRequestMatcher.matches(AntPathRequestMatcher.java:145)
	at org.springframework.security.web.DefaultSecurityFilterChain.matches(DefaultSecurityFilterChain.java:42)
	at org.springframework.security.web.FilterChainProxy.getFilters(FilterChainProxy.java:203)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:176)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
	at org.springfram