山东建设科技产品推广网站,岳阳公司网站开发,手机电脑网站建设,网站推荐正能量只有被线上服务问题毒打过的人才明白日志有多重要#xff01;
谁赞成#xff0c;谁反对#xff1f;如果你深有同感#xff0c;那恭喜你是个社会人了#xff1a;#xff09;
日志对程序的重要性不言而喻#xff0c;轻巧、简单、无需费脑#xff0c;程序代码中随处可见…
只有被线上服务问题毒打过的人才明白日志有多重要
谁赞成谁反对如果你深有同感那恭喜你是个社会人了
日志对程序的重要性不言而喻轻巧、简单、无需费脑程序代码中随处可见帮助我们排查定位一个有一个问题问题。但看似不起眼的日志却隐藏着各式各样的“坑”如果使用不当不仅不能帮助我们反而会成为服务“杀手”。
本文主要介绍生产环境日志使用不当导致的“坑”及避坑指北高并发系统下尤为明显。同时提供一套实现方案能让程序与日志“和谐共处”。
避坑指北
本章节我将介绍过往线上遇到的日志问题并逐个剖析问题根因。
不规范的日志书写格式
// 格式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 日志尤其在高峰期大量的日志磁盘写入极具消耗服务性能。
那这就变成了博弈论日志多了好排查问题但是服务性能被“吃了”日志少了服务稳定性没啥影响了但是排查问题难了程序员“苦”啊。
提问为何 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.(ThrowableProxy.java:112)
at org.apache.logging.log4j.core.impl.ThrowableProxy.(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 这么多线程呢
一番查阅分析后得出如下结论
使用 Log4j 的 Logger.error 去打印异常堆栈的时候为了打印出堆栈中类的位置信息需要使用 Classloader 进行类加载 Classloader加载是线程安全的虽然并行加载可以提高加载不同类的效率但是多线程加载相同的类时还是需要互相同步等待尤其当不同的线程打印的异常堆栈完全相同时就会增加线程 Block 的风险而 Classloader 去加载一个无法加载的类时效率会急剧下降使线程Block的情况进一步恶化 因为反射调用效率问题JDK 对反射调用进行了优化动态生成 Java 类进行方法调用替换原来的 native 调用而生成的动态类是由 DelegatingClassLoader 进行加载的不能被其他的 Classloader 加载异常堆栈中有反射优化的动态类在高并发的条件下就非常容易产生线程 Block 的情况。 结合上文堆栈卡在此处就很明清晰了
大量的线程涌进导致下游的服务超时使得超时异常堆栈频繁打印堆栈的每一层需要通过反射去拿对应的类、版本、行数等信息loadClass 是需要同步等待的一个线程加锁导致大部分线程 block 住等待类加载成功影响性能。 讲道理即使大部分线程等待一个线程 loadClass也只是一瞬间的卡顿为何这个报错这会一直 loadClass类呢结合上述结论分析程序代码得出此处线程内的请求下游服务逻辑包含 Groovy 脚本执行逻辑属于动态类生成上文结论三表明动态类在高并发情况下无法被log4j正确反射加载到那么堆栈反射又要用进入了死循环越来越多的线程只能加入等待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 log4j 为了拿到函数名称和行号信息利用了异常机制首先抛出一个异常之后捕获异常并打印出异常信息的堆栈内容再从堆栈内容中解析出行号。而实现源码中增加了锁的获取及解析过程高并发下性能损耗可想而知。
如下是比较影响性能的参数配置请大家酌情配置
%C - 调用者的类名(速度慢,不推荐使用) %F - 调用者的文件名(速度极慢,不推荐使用) %l - 调用者的函数名、文件名、行号(极度不推荐非常耗性能) %L - 调用者的行号(速度极慢,不推荐使用) %M - 调用者的函数名(速度极慢,不推荐使用)
解决方案——日志级别动态调整
项目代码需要打印大量 INFO级别日志以支持问题定位及测试排查等。但这些大量的 INFO日志对生产环境是无效的大量的日志会吃掉 CPU 性能此时需要能动态调整日志级别既满足可随时查看 INFO日志又能满足不需要时可动态关闭不影响服务性能需要。
方案结合 Apollo 及 log4j2 特性从 api层面动态且细粒度的控制全局或单个 Class 文件内的日志级别。优势是随时生效生产排查问题可指定打开单个 class 文件日志级别排查完后可随时关闭。
限于本篇篇幅具体实现代码就不贴出了其实实现很简单就是巧妙的运用 Apollo 的动态通知机制去重置日志级别如果大家感兴趣的话可以私信或者留言我我开一篇文章专门来详细讲解如何实现。
总结与展望
本篇带你了解了日志在日常软件服务中常见的问题以及对应的解决方法。切记简单的东西 高并发 不简单要对生产保持敬畏之心
总结
感谢每一个认真阅读我文章的人
作为一位过来人也是希望大家少走一些弯路如果你不想再体验一次学习时找不到资料没人解答问题坚持几天便放弃的感受的话在这里我给大家分享一些自动化测试的学习资源希望能给你前进的路上带来帮助。 文档获取方式
加入我的软件测试交流群632880530免费获取~同行大佬一起学术交流每晚都有大佬直播分享技术知识点
这份文档对于想从事【软件测试】的朋友来说应该是最全面最完整的备战仓库这个仓库也陪伴我走过了最艰难的路程希望也能帮助到你 以上均可以分享只需要你搜索vx公众号程序员雨果即可免费领取
