「这是我参与2022首次更文挑战的第 4 天,活动详情查看:2022首次更文挑战」
不恰当的日志打印会造成哪些问题?
降低线上问题排查效率
案例一:错误日志未打印异常栈,问题排查困难
包含如下两种情况:
- 打印日志时未打印异常体。 在这种情况下,异常信息和异常栈都是缺失的。
- 打印日志时只打印了异常信息,未打印异常栈。 在这种情况下,像 NullPointerException 打印的结果就是空,无法及时定位线上问题。
解决方案:打印整个异常体。
用 log4j 2 日志打印代码举例如下:
/**
* 假设这是一个交易流程中的下单处理器
*/
@Slf4j
class CreatOrderProcessor {
public Long createOrder(Long userId) {
try {
// 执行下单流程
return orderId;
} catch (Exception e) {
// 错误情况1
log.error("下单流程出错,用户Id为{}", userId);
// 错误情况2
log.error("下单流程出错,用户Id为{},异常为{}", userId, e.getMessage());
// 正确的日志打印方式
log.error("下单流程出错,用户Id为{},异常为:", userId, e);
}
}
}
案例二:日志打印级别不合理,真正的错误被淹没
主要是这种情况:
- 将一些不致命的错误打印为 ERROR 级别,导致 ERROR 级别日志泛滥。
这会导致两个问题:
- 团队人力成本的上升。 错误日志太多,值班的运维同学需要耗费大量的精力来分辨哪些是真正的问题,提取有效信息的难度增加,效率自然会下降。
- 小流量问题的忽视。 无效日志掩盖了真正的问题,当异常日志过多时,无法保证每一个问题都能被发现。
解决方案:制定并遵循相应的日志打印规范。
这个规范可以是业界通用的(参考上篇,推荐的四个打印级别;或者参考「阿里巴巴Java开发手册」),也可以是根据团队业务特点自己制定的,但需要团队通过 Code Review 等形式来保障落地。
附:《阿里巴巴Java开发手册》节选
案例三:日志打印泛滥,排查问题的时间范围受限
主要是这种情况:
- INFO 级别日志打印过多,导致存储资源瓶颈,反过来又限制了日志的存储范围。
这会导致两个问题:
-
应用服务器日志膨胀。
服务器日志一般是根据 log4j 配置文件来打印的。一般情况下,我们会通过配置文件指定日志分片大小(比如达到 512M 就产生一个新的日志文件)、日志文件个数(比如共打印 30 个文件)来限制日志打印的上限。
当日志打印过多时,服务器日志的可追溯时间范围就会变小:比如一天打印 1G 的日志,那么 512M*30 = 15G 的日志上限只能支持 15 天的日志追溯,当需要排查的问题来自第 16 天时,就会很难处理。
-
日志系统存储成本上升。 生产环境中,通常会将日志远程上报到数据中心,然后通过检索系统做查询。如果上报的日志量过大,数据存储的成本就会上升,同时也会导致日志系统延迟。
解决方案:数据查询类接口(读接口)尽量不打印日志;事务提交类接口(写接口)不重复打印日志、只打印关键日志。
案例四:关键上下文打印缺失或错误,缺少问题排查现场
包含如下两种情况:
- 关键上下文未打印。 比如一个交易的退款流程中,未打印订单号。
- 关键上下文对象未重写 toString 方法。 在这种情况下,会直接将对象地址打印出来。
用 log4j 2 日志打印代码举例如下:
/**
* 假设这是一个交易流程中的退款处理器
*/
@Slf4j
class RefundProcessor {
public void refund(Long orderId, User user) {
try {
// 执行退款流程
} catch (Exception e) {
// 错误情况1
log.error("退款流程出错", e);
// 错误情况2,假设User对象未重写toString方法
log.error("退款流程出错,用户为{},异常为:", userId, e);
// 正确的日志打印方式,但如果User对象重写了toString方法,按照错误情况2打印即可
log.error("退款流程出错,用户为{},异常为:", JacksonUtils.serialize(user), e);
}
}
}
// 配合错误情况2的
class User {
private Long userId;
public void setUserId(Long userId) {
this.userId = userId;
}
public Long getUserId() {
return this.userId;
}
}
建议:对于对外提供的数据传输对象(DTO),重写toString方法,以防止调用方日志打印问题。
参考代码如下:
class UserDTO {
private Long userId;
public void setUserId(Long userId) {
this.userId = userId;
}
public Long getUserId() {
return this.userId;
}
@Override
public String toString() {
return "UserDTO{" + "userId=" + this.userId + "}";
}
}
影响系统性能,甚至引发系统故障
- 造成服务瘫痪。 举例,业务出现故障时产生大量错误日志,导致磁盘 IO 急剧升高,耗费大量 CPU,进而导致服务瘫痪。
- 导致线程阻塞。 举例, 一次鞭辟入里的 Log4j2 异步日志输出阻塞问题的定位
- 引起内存泄漏。 举例,记一次log4j日志导致线上OOM问题案例
- 其他性能问题。
怎么解决这些问题?
- 制定、遵循符合业务特性的日志打印规范。
个人建议:
- 明确日志分级规范;
- 异步打印日志;
- 避免短时间内大量日志打印、避免循环打印日志;
- 打印关键上下文,但避免日志的重复;
- 参考《阿里巴巴Java开发手册》,制定符合实际情况的日志规范。