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

公众号程序猿DD

共 1680字,需浏览 4分钟

 ·

2021-08-05 03:41

来源 | 阿飞的博客

事故代码

直入主题,生产环境日志级别为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);

END -


往期推荐

干掉菜鸟?微信又推出新功能:一键寄快递

IntelliJ IDEA 2021.2 正式发布了!

如何从 100 亿 URL 中找出相同的 URL?

CEO不当了,CTO也不做了!我要回去写代码,这才是我所热爱的!

用谷歌搜索技术问题一定比用百度好?也未必...



喜欢本文欢迎转发,关注我订阅更多精彩

关注我回复「加群」,加入Spring技术交流群

浏览 19
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报
评论
图片
表情
推荐
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报