凌晨两点CPU飙到100%，我以为是死循环，排查两小时才发现是日志框架在死锁

上周三凌晨两点，我被一通电话叫醒。

运维那边说线上服务器CPU飙到100%，已经持续了二十分钟，用户开始投诉了。我迷迷糊糊爬起来打开电脑，连上VPN，敲了个top命令。

好家伙，六个Java进程全在吃CPU，每个都占了百分之十几。

我的第一反应是，死循环。肯定是哪个while循环没加退出条件，或者递归炸了。干这行的都有肌肉记忆，CPU飙高先查死循环，数据库慢查先查索引，内存溢出先查大对象。三板斧嘛。

然后我开始排查。

先用jstack把线程栈dump下来，搜了一圈BLOCKED和RUNNABLE状态的线程。看了一堆堆栈信息，没有发现明显的死循环痕迹。代码最近也没有发布，不存在新代码引入的问题。

我又用了arthas，跑了thread -n 5看最忙的线程。结果发现一个很奇怪的现象，最忙的线程全卡在日志输出那一层。

？？？

日志？打日志能打出CPU 100%？我干了六年Java，第一次碰到这种事。

仔细看了看线程栈，发现了更诡异的事情。大量线程的状态是WAITING，等的是同一个锁对象，而持有那把锁的线程也在等另一把锁。经典的死锁啊，只不过不是业务代码的死锁，是日志框架内部的死锁。

我当时就愣住了。

说好的Logger.info是最安全的操作呢？你一个打日志的，怎么还能死锁？

后来花了快一个小时，我才搞明白整件事的来龙去脉。

我们项目用的是logback，配置了一个异步appender。听起来没问题对吧？异步嘛，应该很快的。但问题是，我们还在另一个地方配了个同步的文件appender，而且两个appender共用了同一把锁。

当并发量上来的时候，Thread A拿着同步appender的锁在写文件，Thread B拿着异步appender的锁在往队列里塞日志事件。然后Thread A又需要往异步appender里写一条，Thread B又需要调一下同步appender做flush。

你等我，我等你。就这么僵住了。

而且更要命的是，死锁一旦发生，后续所有线程只要调用Logger.info或者Logger.error，就会被阻塞在锁等待上。线程越来越多，CPU上下文切换越来越频繁，表面上看就是CPU飙到100%，但实际上什么事都没干成，全在那空转。

这就好比高速公路上发生了连环追尾，后面的车不是在往前开，而是在排队等。但发动机一直在轰鸣，油表一直在往下掉。

排查到这里，我心里其实是有点后怕的。

因为这种问题，你在开发环境几乎不可能复现。单机、低并发、日志量小，根本触发不了这个条件。只有到了生产环境，几百个请求同时打进来，每个请求都在打日志的时候，死锁才会浮出水面。

而且你想想看，日志框架是什么？是我们最信任的基础设施。出了问题第一反应就是去看日志，结果日志本身就是问题的源头。这就像医生自己病了，你去找另一个医生看病，结果那个医生也病了。

聊到这，我想起了一个更有意思的事。

很多人写代码的时候，对日志的态度是能多打就多打，生怕漏掉什么关键信息。每个方法入口打一条info，每个分支判断打一条debug，每个异常catch里面打一条error。一个请求进来，光日志就能打几十行。

但很少有人想过，日志本身也是有成本的。写磁盘要IO，格式化字符串要CPU，异步队列要内存，锁竞争要上下文切换。当你的日志量大到一定程度，它就不再是旁观者了，它变成了系统的一部分，甚至是瓶颈。

这让我想起《黑客帝国》里那个经典场景，Neo看到Matrix的代码流，发现整个世界都是代码构成的。日志框架对我们来说就像Matrix的代码流，平时你不会注意到它的存在，但它一直在那里，支撑着你对系统的「感知」。一旦它出了问题，你就变成了瞎子。

回到那次事故，最终的解决方案其实很简单。

把同步appender换成异步的，让所有日志事件都走同一个队列，用单线程消费。锁竞争消失了，死锁的条件也就不存在了。改完之后重启服务，CPU立马降下来了，前后不到十分钟。

但排查的过程花了将近两个小时。凌晨两点到四点，困得要死，眼睛盯着黑乎乎的终端，一行一行地看线程栈。中间还差点跑偏，去查数据库连接池的问题，查了半天发现数据库响应很快，根本不是数据库的锅。

后来复盘的时候，leader说了一句话让我印象很深。他说，排查问题最重要的能力不是知道答案，而是知道去哪里找答案。

我当时第一反应去查死循环，是因为经验告诉我CPU高就是死循环。但经验有时候是会骗人的。如果我不是用arthas看到线程栈，可能还在那里一行一行翻代码找while循环呢。

工具比经验重要，观察比猜测重要。

你想想看，程序员这个职业最反直觉的地方是什么？是我们写的每一行代码都可能产生意想不到的后果。你以为Logger.info是最安全的操作，结果它能让你的服务器瘫痪。你以为加个索引能让查询变快，结果它能让写入变慢。你以为异步一定比同步快，结果在某些场景下，异步的开销比同步还大。

没有银弹。这句话在软件工程里被说了无数遍，但每次碰到实际情况的时候，我们还是会本能地去寻找那个「一劳永逸」的方案。

那天凌晨四点，修完bug回到床上，我脑子里一直在想一件事。

我们每天都在用各种框架、各种中间件、各种工具，但真正理解它们内部原理的人有多少？大部分人（包括我自己）都是在用，但不知道它为什么这样工作。出了问题就去Stack Overflow搜，搜到了就复制粘贴，解决了就完事。

但如果你不了解logback内部的锁机制，你碰到这次死锁，就会觉得是灵异事件。如果你不了解ConcurrentHashMap在JDK8里已经去掉了分段锁，你面试的时候还在那背JDK7的八股文，面试官听了只会觉得你很久没学习了。

就像查理芒格说的，手里拿着锤子的人，看什么都像钉子。但真正的高手，手里不只有一把锤子，他还知道什么时候该用扳手，什么时候该用螺丝刀，什么时候该把工具箱合上，用手去感受问题在哪里。

那天晚上还有一个细节我印象很深。修完之后我顺手看了一眼日志文件的大小，72小时的日志，磁盘占了将近80个G。info级别全开，每个请求打一堆，debug级别的也没关。我一边觉得离谱，一边又觉得这太常见了。多少线上项目的日志配置都是从模板里复制出来的，谁会真的去根据业务场景去调日志级别？

反正我现在学乖了。每个项目上线之前，我都会专门花半小时review一下日志配置。该info的info，该warn的warn，debug的生产环境直接关掉。异步appender和同步appender绝对不混用。磁盘告警阈值也要设好。

这些都是小事，但小事不注意，迟早变成大事。

凌晨四点半，我关上电脑，外面天已经开始亮了。楼下早餐店的灯亮着，老板在蒸包子。我忽然觉得，做程序员和蒸包子其实挺像的。表面上看都是重复劳动，但真正的功夫在你看不到的地方，面团发酵的温度，蒸笼的气压，出锅的时机。代码也一样，表面上看是if else和for循环，但真正的功夫在你对底层原理的理解，在你排查问题时的思路，在你凌晨两点被叫醒之后还能保持冷静的那份定力。

周日晚上写到这里，忽然有点感慨。今天是这个系列的最后一篇文章了，感谢你看完。希望下次你的服务器CPU飙到100%的时候，不要急着查死循环，先看看线程栈，说不定问题出在你最意想不到的地方。

晚安。