万万没想到 logger.info() 还能出导致线上故障
共 1314字，需浏览 3分钟
·
2021-07-29 10:05
事故代码
直入主题，生产环境日志级别为warn，请看如下这行代码：
LOGGER.info("the DTO info: {}", JSON.toJSONString(DTO));
先做个小调查，你觉得这段代码会不会有问题。
如果你的答案为“有问题”，并且你有充足的理由，那么这篇文章已经没有往下看的必要了，因为你已经掌握了笔者此文要传达的知识点。如果你的答案为“没有问题”或者“无法分辨”，那么，请继续往下看。
原因分析
这段代码主要有两个需要注意的地方：
- 日志级别为info，而线上环境是warn级别。我们可以得出结论，线上环境肯定不会输出这行日志。
- 打印日志的行为中有JSON序列化动作。
第二点是此文的关键。我们假设DTO是一个很小的对象，JSON序列化时间以及开销可以忽略不计，那么这行代码依然没有问题。但是，如果DTO是一个很大的对象，比如10k，甚至100k，即使快如fastjson，其耗时依然高达数百毫秒，并且非常消耗CPU。如果是在高并发的系统中，这么大的开销完全不可接受，甚至可能就会拖垮整个系统。
有同学就会说了，我不是info日志么，为什么还会执行这行代码？请继续往下看。我们首先看一下slf4j中logger.info()这个方法是如何申明的：第二个参数为Object类型。我们的代码中传递给第二个参数的值为：JSON.toJSONString(DTO)，很明显这行代码是传递一个String类型的字段给Object arg。那么String如何来呢？答案也很明显，必须先执行JSON序列化才能得到String。那么logger.info这个info在什么时候起作用呢？答案是它只能在输出日志这个动作时起作用：
public void info(String format, Object arg);解决方案
如何解决这个问题？很简单，在输入日志时加个级别判断（需要说明的是，这种规范很容易被忽略，比如项目成员更替时，很容易引入有问题的代码。所以笔者写了一段脚本：扫描所有Java代码，如果logger.info()中有JSON序列化动作，那么必须判断优先级后才能输出日志。即可以简单的认为它的前一行代码必须是logger.isInfoEnabled()。如果你的项目有CICD环境，那么把这段脚本集成到扫描规范中，才是解决这个问题最完美的方案）：
if(LOGGER.isInfoEnabled()) {
LOGGER.info("the DTO info: {}", JSON.toJSONString(DTO));
}
当然，需要说明的是，通过上面的分析，如果我们的打印日志那行代码中没有JSON序列化等耗时动作的话，那么日志级别判断就没必要了，比如下面这行代码：
String reqId = "...";
String msg = "...";
LOGGER.info("the DTO info: {}", msg);
- END -
「技术分享」某种程度上，是让作者和读者，不那么孤独的东西。欢迎关注我的微信公众号：「Kirito的技术分享」