华为内测版onlog好不好用,华为no log和log版本怎么选

首页 > 经验 > 作者:YD1662022-11-06 07:40:38

引言

“只有被线上服务问题毒打过的人才明白日志有多重要!”

我先说结论,谁赞成,谁反对?如果你深有同感,那恭喜你是个社会人了:)

日志对程序的重要性不言而喻,轻巧、简单、无需费脑,程序代码中随处可见,帮助我们排查定位一个有一个问题问题。但看似不起眼的日志,却隐藏着各式各样的“坑”,如果使用不当,不仅不能帮助我们,反而会成为服务“*手”。

本文主要介绍生产环境日志使用不当导致的“坑”及避坑指北,高并发系统下尤为明显。同时提供一套实现方案能让程序与日志“和谐共处”。

避坑指北

本章节我将介绍过往线上遇到的日志问题,并逐个剖析问题根因。

不规范的日志书写格式

场景

// 格式1 log.debug("get user" uid " from DB is Empty!"); // 格式2 if (log.isdebugEnable()) { log.debug("get user" uid " from DB is Empty!"); } // 格式3 log.debug("get user {} from DB is Empty!", uid);

如上三种写法,我相信大家或多或少都在项目代码中看到过,那么他们之前有区别呢,会对性能造成什么影响?

如果此时关闭 DEBUG 日志级别,差异就出现了,格式1 依然还是要执行字符串拼接,即使它不输出日志,属于浪费。

格式2 的缺点就是就在于需要加入额外的判断逻辑,增加了废代码,一点都不优雅。

所以推荐格式3,只有在执行时才会动态地拼接,关闭相应日志级别后,不会有任何性能损耗。

生产打印大量日志消耗性能

尽量多的日志,能够把用户的请求串起来,更容易断定出问题的代码位置。由于当前分布式系统,且业务庞杂,任何日志的缺失对于程序员定位问题都是极大的障碍。所以,吃过生产问题苦的程序员,在开发代码过程中,肯定是尽量多打日志。

为了以后线上出现问题能尽快定位问题并修复,程序员在编程实现阶段,就会尽量多打关键日志。那上线后是能快速定位问题了,但是紧接着又会有新的挑战:随着业务的快速发展,用户访问不断增多,系统压力越来越大,此时线上大量的 INFO 日志,尤其在高峰期,大量的日志磁盘写入,极具消耗服务性能。

那这就变成了博弈论,日志多了好排查问题,但是服务性能被“吃了”,日志少了服务稳定性没啥影响了,但是排查问题难了,程序员“苦”啊。

华为内测版onlog好不好用,华为no log和log版本怎么选(1)

提问:为何 INFO 日志打多了,性能会受损(此时 CPU 使用率很高)?

根因一:同步打印日志磁盘 I/O 成为瓶颈,导致大量线程 Block

可以想象,如果日志都输出到同一个日志文件时,此时有多个线程都往文件里面写,是不是就乱了套了。那解决的办法就是加锁,保证日志文件输出不会错乱,如果是在高峰期,锁的争抢无疑是最耗性能的。当有一个线程抢到锁后,其他的线程只能 Block 等待,严重拖垮用户线程,表现就是上游调用超时,用户感觉卡顿。

如下是线程卡在写文件时的堆栈

Stack Trace is: java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352) - waiting to lock <0x000000063d668298> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96) at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32) at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228) .....

那么是否线上减少 INFO 日志就没问题了呢?同样的,ERROR 日志量也不容小觑,假设线上出现大量异常数据,或者下游大量超时,瞬时会产生大量 ERROR 日志,此时还是会把磁盘 I/O 压满,导致用户线程 Block 住。

提问:假设不关心 INFO 排查问题,是不是生产只打印 ERROR 日志就没性能问题了?

根因二:高并发下日志打印异常堆栈造成线程 Block

有次线上下游出现大量超时,异常都被我们的服务捕获了,庆幸的是容灾设计时预计到会有这种问题发生,做了兜底值逻辑,本来庆幸没啥影响是,服务器开始“教做人”了。线上监控开始报警, CPU 使用率增长过快,CPU 一路直接增到 90% ,此时紧急扩容止损,并找一台拉下流量,拉取堆栈。

Dump 下来的线程堆栈查看后,结合火焰退分析,大部分现成都卡在如下堆栈位置:

Stack Trace is: java.lang.Thread.State: BLOCKED (on object monitor) at java.lang.ClassLoader.loadClass(ClassLoader.java:404) - waiting to lock <0x000000064c514c88> (a java.lang.Object) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:205) at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:112) at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:112) at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:96) at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629) ...

此处堆栈较长,大部分现场全部 Block 在 java.lang.ClassLoader.loadClass,而且往下盘堆栈发现都是因为这行代码触发的

// 定位到的业务代码位置 at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319) // 对应的业务代码为 log.error("ds fetcher get error", e);

啊这。。。就很离谱,你打个日志为何会加载类呢?加载类为何会 Block 这么多线程呢?

一番查阅分析后,得出如下结论:

结合上文堆栈,卡在此处就很明清晰了:

最佳实践1. 去掉不必要的异常堆栈打印

明显知道的异常,就不要打印堆栈,省点性能吧,任何事 高并发,意义就不一样了:)

try { System.out.println(Integer.parseInt(number) 100); } catch (Exception e) { // 改进前 log.error("parse int error : " number, e); // 改进后 log.error("parse int error : " number); }

如果Integer.parseInt发生异常,导致异常原因肯定是出入的number不合法,在这种情况下,打印异常堆栈完全没有必要,可以去掉堆栈的打印。

2. 将堆栈信息转换为字符串再打印

public static String stacktraceToString(Throwable throwable) { StringWriter stringWriter = new StringWriter(); throwable.printStackTrace(new PrintWriter(stringWriter)); return stringWriter.toString(); }

log.error得出的堆栈信息会更加完善,JDK 的版本,Class 的路径信息,jar 包中的类还会打印 jar 的名称和版本信息,这些都是去加载类反射得来的信息,极大的损耗性能。
调用 stacktraceToString 将异常堆栈转换为字符串,相对来说,确实了一些版本和 jar 的元数据信息,此时需要你自己决策取舍,到底是否有必要打印出这些信息(比如类冲突排查基于版本还是很有用的)。

3. 禁用反射优化

使用 Log4j 打印堆栈信息,如果堆栈中有反射优化生成的动态代理类,这个代理类不能被其它的Classloader加载,这个时候打印堆栈,会严重影响执行效率。但是禁用反射优化也会有副作用,导致反射执行的效率降低。

4.异步打印日志

生产环境,尤其是 QPS 高的服务,一定要开启异步打印,当然开启异步打印,有一定丢失日志的可能,比如服务器强行“*死”,这也是一个取舍的过程。

5. 日志的输出格式

我们看戏日志输出格式区别

// 格式1 [%d{yyyy/MM/dd HH:mm:ss.SSS}[%X{traceId}] %t [%p] %C{1} (%F:%M:%L) %msg%n // 格式2 [%d{yy-MM-dd.HH:mm:ss.SSS}] [%thread] [%-5p %-22c{0} -] %m%n

官网也有明确的性能对比提示,如果使用了如下字段输出,将极大的损耗性能

%C or $class, %F or %file, %l or %location, %L or %line, %M or %method

华为内测版onlog好不好用,华为no log和log版本怎么选(2)

log4j 为了拿到函数名称和行号信息,利用了异常机制,首先抛出一个异常,之后捕获异常并打印出异常信息的堆栈内容,再从堆栈内容中解析出行号。而实现源码中增加了锁的获取及解析过程,高并发下,性能损耗可想而知。

如下是比较影响性能的参数配置,请大家酌情配置:

%C - 调用者的类名(速度慢,不推荐使用) %F - 调用者的文件名(速度极慢,不推荐使用) %l - 调用者的函数名、文件名、行号(极度不推荐,非常耗性能) %L - 调用者的行号(速度极慢,不推荐使用) %M - 调用者的函数名(速度极慢,不推荐使用)解决方案——日志级别动态调整

项目代码需要打印大量 INFO级别日志,以支持问题定位及测试排查等。但这些大量的 INFO日志对生产环境是无效的,大量的日志会吃掉 CPU 性能,此时需要能动态调整日志级别,既满足可随时查看 INFO日志,又能满足不需要时可动态关闭,不影响服务性能需要。

方案:结合 Apollo 及 log4j2 特性,从 api层面,动态且细粒度的控制全局或单个 Class 文件内的日志级别。优势是随时生效,生产排查问题,可指定打开单个 class 文件日志级别,排查完后可随时关闭。

限于本篇篇幅,具体实现代码就不贴出了,其实实现很简单,就是巧妙的运用 Apollo 的动态通知机制去重置日志级别,如果大家感兴趣的话,可以私信或者留言我,我开一篇文章专门来详细讲解如何实现。

总结与展望

本篇带你了解了日志在日常软件服务中常见的问题,以及对应的解决方法。切记,简单的东西 高并发 = 不简单!要对生产保持敬畏之心!

能读到结尾说明你真是铁粉了,有任何问题请私信或者评论,我看到了一定会第一时间回复。如果你觉得本人分享的内容够“干”,麻烦点赞、关注、转发,这是对我最大鼓励,感谢支持!

栏目热文

文档排行

本站推荐

Copyright © 2018 - 2021 www.yd166.com., All Rights Reserved.