《Dubbo 实现原理与源码解析 —— 精品合集》 《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》 《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》 《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》 《Java 面试题 + Java 学习指南》

摘要: 原创出处 阿飞的博客 「阿飞」欢迎转载,保留摘要,谢谢!


🙂🙂🙂关注**微信公众号:【芋道源码】**有福利:

  1. RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表
  2. RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址
  3. 您对于源码的疑问每条留言将得到认真回复。甚至不知道如何读源码也可以请教噢
  4. 新的源码解析文章实时收到通知。每周更新一篇左右
  5. 认真的源码交流微信群。

事故代码

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

文章目录
  1. 1. 事故代码
  2. 2. 原因分析
  3. 3. 解决方案