聚合国内IT技术精华文章,分享IT技术精华,帮助IT从业人士成长

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

2023-04-23 11:44 浏览: 1196206 次 我要评论(0 条) 字号:

「 关注“石杉的架构笔记”,大厂架构经验倾囊相授 


文章来源:【公众号:阿飞的博客




事故代码





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

欢迎扫码加入儒猿技术交流群,每天晚上20:00都有Java面试、Redis、MySQL、RocketMQ、SpringCloudAlibaba、Java架构等技术答疑分享,更能跟小伙伴们一起交流技术


另外推荐儒猿课堂的9.9元系列课程给您,欢迎加入一起学习~


互联网Java工程师面试突击课
(9.9元专享)

SpringCloudAlibaba零基础入门到项目实战
9.9元专享)

亿级流量下的电商详情页系统实战项目
9.9元专享)

Kafka消息中间件内核源码精讲
9.9元专享)

12个实战案例带你玩转Java并发编程
9.9元专享)

Elasticsearch零基础入门到精通
9.9元专享)

基于Java手写分布式中间件系统实战
9.9元专享)

基于ShardingSphere的分库分表实战课
9.9元专享)



网友评论已有0条评论, 我也要评论

发表评论

*

* (保密)

Ctrl+Enter 快捷回复