本文讨论了一段可能存在问题的日志代码：使用INFO级别日志打印DTO的JSON序列化信息。当DTO对象较大时，序列化过程会消耗大量时间和CPU资源。即使日志级别设置为WARN，由于SLF4J的API设计，日志参数预处理仍然会发生。解决方案是在输出日志前进行日志级别判断，避免不必要的序列化操作。建议在项目中建立规范，确保类似代码的正确性。
点击上方“芋道源码”，选择“设为星标”
管她前浪，还是后浪？
能浪的浪，才是好浪！
每天 10:33 更新文章，每天掉亿点点头发...
源码精品专栏
事故代码
直入主题，生产环境日志级别为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);
欢迎加入我的知识星球，一起探讨架构，交流源码。加入方式，长按下方二维码噢：
已在知识星球更新源码解析如下：
最近更新《芋道 SpringBoot 2.X 入门》系列，已经 20 余篇，覆盖了 MyBatis、Redis、MongoDB、ES、分库分表、读写分离、SpringMVC、Webflux、权限、WebSocket、Dubbo、RabbitMQ、RocketMQ、Kafka、性能测试等等内容。
提供近 3W 行代码的 SpringBoot 示例，以及超 4W 行代码的电商微服务项目。
获取方式：点“在看”，关注公众号并回复 666 领取，更多内容陆续奉上。
文章有帮助的话，在看，转发吧。
谢谢支持哟 (*^__^*）
扫一扫
3866
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
