查看原文
其他

万万没想到! logger.info() 还能导致线上故障?

ImportNew 2022-09-23

The following article is from 阿飞的博客 Author 阿飞


事故代码

直入主题,生产环境日志级别为warn,请看如下这行代码:

LOGGER.info("the DTO info: {}", JSON.toJSONString(DTO));

先做个小调查,你觉得这段代码会不会有问题:

如果你的答案为“有问题”,并且你有充足的理由,那么这篇文章已经没有往下看的必要了,因为你已经掌握了笔者此文要传达的知识点。如果你的答案为“没有问题”或者“无法分辨”,那么,请继续往下看。


原因分析

这段代码主要有两个需要注意的地方:

  1. 日志级别为info,而线上环境是warn级别。我们可以得出结论,线上环境肯定不会输出这行日志。
  2. 打印日志的行为中有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);


- EOF -

推荐阅读  点击标题可跳转

1、高并发下秒杀商品,你必须知道的 9 个细节

2、再见MybatisPlus,阿里推出新ORM框架!

3、不吹不擂,一文揭秘鸿蒙操作系统


看完本文有收获?请转发分享给更多人

关注「ImportNew」,提升Java技能

点赞和在看就是最大的支持❤️

您可能也对以下帖子感兴趣

文章有问题?点此查看未经处理的缓存