现象

某天凌晨02:05调用配置服务接口可用率下降

ConsoleAppenderBlock01
ConsoleAppenderBlock01

出现配置服务JSF线程池满的问题

ConsoleAppenderBlock02
ConsoleAppenderBlock02

处理

先对配置服务进行第一波扩容(5台机器)后,可用率升至80%,后续再扩容可用率并没有恢复至100%。

检查JSF线程池配置,最大线程池为400。发现扩容后的机器线程数很低,均没有使用到最大线程池。
线上服务器:

ConsoleAppenderBlock03
ConsoleAppenderBlock03

扩容服务器:

ConsoleAppenderBlock04
ConsoleAppenderBlock04

初步怀疑线程阻塞或者死锁,下线原本线上两台服务器,可用率恢复。

问题

dump线上服务器线程信息,发现大量线程处于Block等待同一资源的情况。

ConsoleAppenderBlock05
ConsoleAppenderBlock05

ConsoleAppenderBlock06
ConsoleAppenderBlock06

ConsoleAppenderBlock07
ConsoleAppenderBlock07

从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图所示,可以看到被阻塞地方有synchronized同步调用。

ConsoleAppenderBlock08
ConsoleAppenderBlock08

从日志配置可以看到每次日志都会往console输出。

ConsoleAppenderBlock09
ConsoleAppenderBlock09

从githubhttps://github.com/moby/moby/issues/35865中找到一个类似的issue,如果一个进程的 stdout/stderr 由 docker-Container-shim 收集,并发送一行数千个字符(观察到在5k-9k 范围内的任何地方) ,那么 docker-Container-shim 将停止从主机读取。这会导致写入终端的进程挂起 write (2)调用,从而很快使容器无法使用。
从阻塞线程堆栈中可以看到,日志阻塞在org.apache.ibatis.logging.stdout.StdOutImpl.debug(StdOutImpl.java:52),我们猜测,mybatis在输出debug日志时,可能有比较大的日志,导致 docker-Container-shim 停止从主机读取。如果控制台没取,这时候控制台会暂停输出,不从缓存中取东西,缓存内容就不会清,日志程序会一直往里写,直到写满,线程就会停止写入,等待缓存可用,表现在程序里,就是writeBytes函数不返回,持有的锁不释放。

修复方案

对于线上服务来说,使用ConsoleAppender是完全没有必要的,我们将日志配置中输出console配置删除,同时将写日志文件配置调整为异步不阻塞的策略,避免日志阻塞带来的线上问题。因为以性能较高的RollingRandomAccessFileAppender的同步Logger,其在打印日志时同样也需要获取RollingRandomAccessFileManager对象的monitor锁,只不过该同步块中的处理效率较高,不像OutputStreamManager锁块那么低效而已。

ConsoleAppenderBlock10
ConsoleAppenderBlock10