- 生产环境日志级别为info,请看如下这行代码:
LOGGER.debug("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,所以不论日志是否打印,JSON序列化都会执行。那么logger.info这个info在什么时候起作用呢?答案是它只能 在输出日志这个动作时起作用:
2. 解决方案
如何解决这个问题?很简单,在输入日志时加个级别判断(需要说明的是,这种规范很容易被忽略,比如项目成员更替时,很容易引入有问题的代码。所以笔者写了一段脚本:扫描所有Java代码,如果logger.info()中有JSON序列化动作,那么必须判断优先级后才能输出日志。即可以简单的认为它的前一行代码必须是logger.isInfoEnabled()。如果你的项目有CICD环境,那么把这段脚本集成到扫描规范中,才是解决这个问题最完美的方案):
if (LOGGER.isInfoEnabled()) {
LOGGER.info("the DTO info: {}", JSON.toJSONString(DTO));
}