服务日志性能调优,由log引出的巨坑

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

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

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

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

避坑指北

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

不规范的日志书写格式

// 格式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公众号:程序员雨果,即可免费领取

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.rhkb.cn/news/162473.html

如若内容造成侵权/违法违规/事实不符,请联系长河编程网进行投诉反馈email:809451989@qq.com,一经查实,立即删除!

相关文章

Ubuntu:Arduino IDE 开发环境配置【保姆级】

物联网开发学习笔记——目录索引 本章主要介绍在Ubuntu系统搭建Arduino IDE 开发环境&#xff0c;windows系统请移步&#xff1a;Windows&#xff1a;Arduino IDE 开发环境配置【保姆级】 参考官网&#xff1a;Arduino - Home 有关更多详细信息&#xff0c;请参阅 Arduino I…

Centos7 安装 MySQL5.7 步骤

Centos7 安装 MySQL5.7 步骤 前言&#xff1a;一 .使用yum源方式安装1、卸载系统自带 mariadb查看并卸载系统自带的 Mariadb 2、下载并安装MySQL官方的 Yum2.1 下载mysql的yum源配置2.2 安装mysql的yum源2.3 使用yum方式安装mysql2.3.1 安装过程中报错解决问题描述解决方案 3、…

python爬虫练习,爬取iview,element组件库图标名称

简单的爬虫 先举一个爬取图片网站图片保存到本地文件夹的例子 原博客&#xff1a;http://t.csdnimg.cn/Cjv3o 这是一个图片网站 https://pic.netbian.com/ 在空白处右键&#xff0c;查看页面源代码&#xff0c;我们发现有具体内容的 我们使用下面的代码可以爬取这个页面所…

如何使用Python抓取PDF文件并自动下载到本地

目录 一、导入必要的库 二、发送HTTP请求并获取PDF文件内容 三、将PDF文件内容写入到本地文件中 四、完整代码示例 五、注意事项 六、错误处理和异常处理 七、进一步优化 总结 在Python中&#xff0c;抓取PDF文件并自动下载到本地需要使用几个不同的库。首先&#xff0…

工业交换机的应用场景

在选择工业交换机的时候&#xff0c;很多人会疑惑自己的场景是否适用工业交换机&#xff0c;工业交换机广泛应用于以下场景&#xff0c;大家可以参考了解 1. 工业自动化&#xff1a;工业交换机用于连接各种工业设备&#xff0c;如PLC&#xff08;可编程逻辑控制器&#xff09;、…

MSQL系列(四) Mysql实战-索引 Explain实战

Mysql实战-索引 Explain实战 前面我们讲解了索引的存储结构&#xff0c;我们知道了BTree的索引结构&#xff0c;也了解了索引最左侧匹配原则&#xff0c;到底最左侧匹配原则在我们的项目中有什么用&#xff1f;或者说有什么影响&#xff1f;今天我们来实战操作一下&#xff0c…

IDEA如何拉取gitee项目?

1.登录gitee 说明&#xff1a;打开idea&#xff0c;在设置上面搜索框输入gitee&#xff0c;然后登录gitee注册的账号。 2. 创建gitee仓库 说明&#xff1a;创建idea中的gitee仓库。 3.寻找项目文件 说明&#xff1a;为需要添加gitee仓库的项目进行添加。 4.项目右键 说明&a…

百度地图高级进阶开发:圆形区域周边搜索地图监听事件(覆盖物重叠显示层级\图像标注监听事件、setZIndex和setTop方法)

百度地图API 使用百度地图API添加多覆盖物渲染时&#xff0c;会出现覆盖物被相互覆盖而导致都无法触发它们自己的监听&#xff1b;在百度地图API里&#xff0c;map的z-index为0&#xff0c;但是触发任意覆盖物的监听如click时也必定会触发map的监听&#xff1b; 项目需求 在…

L2-030 冰岛人

2018年世界杯&#xff0c;冰岛队因1:1平了强大的阿根廷队而一战成名。好事者发现冰岛人的名字后面似乎都有个“松”&#xff08;son&#xff09;&#xff0c;于是有网友科普如下&#xff1a; 冰岛人沿用的是维京人古老的父系姓制&#xff0c;孩子的姓等于父亲的名加后缀&#x…

AI系统ChatGPT源码+详细搭建部署教程+支持GPT4.0+支持ai绘画(Midjourney)/支持OpenAI GPT全模型+国内AI全模型

一、AI创作系统 SparkAi创作系统是基于OpenAI很火的ChatGPT进行开发的Ai智能问答系统AI绘画系统&#xff0c;支持OpenAI GPT全模型国内AI全模型。本期针对源码系统整体测试下来非常完美&#xff0c;可以说SparkAi是目前国内一款的ChatGPT对接OpenAI软件系统。那么如何搭建部署…

基于梯度优化的BP神经网络(分类应用) - 附代码

基于梯度优化的BP神经网络&#xff08;分类应用&#xff09; - 附代码 文章目录 基于梯度优化的BP神经网络&#xff08;分类应用&#xff09; - 附代码1.鸢尾花iris数据介绍2.数据集整理3.梯度优化BP神经网络3.1 BP神经网络参数设置3.2 梯度算法应用 4.测试结果&#xff1a;5.M…

一、初识 Elasticsearch:概念,安装,设置分词器

文章目录 01、初识 Elasticsearch正向索引和倒排索引索引MySQL与ES的概念映射安装ES分词器分词器的设置结束语 01、初识 Elasticsearch 本次ES基于&#xff1a;7.12.1 版本 学习资源为&#xff1a;https://www.bilibili.com/video/BV1Gh411j7d6 什么是ES&#xff08;Elastics…

解决jmeter软件显示为英文、返回数据乱码、设置编码格式的问题

一.jmeter软件每次打开都需要手动切换中文 1.修改配置文件&#xff0c;可以把jmeter设置成中文&#xff1a; 2.打开jmeter.properties配置文件&#xff0c;修改languagezh_CN 二.返回数据乱码 改配置文件 进入Jmeter的bin目录下&#xff0c;找到jmeter.properties文件&#…

Java构建Web项目

对无底线服务型的系统&#xff0c;业务代码和界面代码脚本化是及其重要的。一是脚本化能确保部署本地就是再用的代码&#xff0c;不存在为每个项目管理代码的问题。然后脚本化不需要人为编译和投放程序库。极大的简化维护难度和成本。能不能脚本化直接决定了能否全面铺开运维&a…

【爬虫教程】2023最详细的爬虫入门教程~

初识爬虫 学习爬虫之前&#xff0c;我们首先得了解什么是爬虫。 来自于百度百科的解释&#xff1a; 网络爬虫&#xff08;又称为网页蜘蛛&#xff0c;网络机器人&#xff0c;在FOAF社区中间&#xff0c;更经常的称为网页追逐者&#xff09;&#xff0c;是一种按照一定的规则&a…

React之受控组件和非受控组件以及高阶组件

一、受控组件 受控组件&#xff0c;简单来讲&#xff0c;就是受我们控制的组件&#xff0c;组件的状态全程响应外部数据 举个简单的例子&#xff1a; class TestComponent extends React.Component {constructor (props) {super(props);this.state { username: lindaidai }…

Java版本+企业电子招投标系统源代码+支持二开+招投标系统+中小型企业采购供应商招投标平台

功能模块&#xff1a; 待办消息&#xff0c;招标公告&#xff0c;中标公告&#xff0c;信息发布 描述&#xff1a; 全过程数字化采购管理&#xff0c;打造从供应商管理到采购招投标、采购合同、采购执行的全过程数字化管理。通供应商门户具备内外协同的能力&#xff0c;为外部供…

轻量级超分网络:Edge-oriented Convolution Block for Real-timeMM21_ECBSR 和 eSR

文章目录 ECBSR&#xff08;Edge-oriented Convolution Block for Real-timeMM21_ECBSR&#xff09;1. 作者目的是开发一个高效的适合移动端的超分网络。2. 作者决定使用plain net &#xff0c;但是效果不好&#xff0c;因此利用重参数化方法&#xff0c;丰富特征表示。3. re-p…

openssl生成SM2公私钥对命令详解

&#xff08;1&#xff09;获得openssl支持椭圆曲线算法列表 命令&#xff1a;openssl ecparam -list_curves 返回结果&#xff1a; secp112r1 : SECG/WTLS curve over a 112 bit prime field secp112r2 : SECG curve over a 112 bit prime field secp128r1 : SE…

工程云平台源码 建筑工地劳务实名制、危大工程监管平台源码

智慧工地的核心是数字化&#xff0c;它通过传感器、监控设备、智能终端等技术手段&#xff0c;实现对工地各个环节的实时数据采集和传输&#xff0c;如环境温度、湿度、噪音等数据信息&#xff0c;将数据汇集到云端进行处理和分析&#xff0c;生成各种报表、图表和预警信息&…