为什么我建议线上高并发量的日志输出的时候不能带有代码位置(上)

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 为什么我建议线上高并发量的日志输出的时候不能带有代码位置(上)

2022-3-27更新,感谢这些网友的留言,补充如下:


image.png


image.png


image.png


image.png


image.png


个人创作公约:本人声明创作的所有文章皆为自己原创,如果有参考任何文章的地方,会标注出来,如果有疏漏,欢迎大家批判。如果大家发现网上有抄袭本文章的,欢迎举报,并且积极向这个 github 仓库 提交 issue,谢谢支持~本文是“为什么我建议”系列第二篇,本系列中会针对一些在高并发场景下,我对于组内后台开发的一些开发建议以及开发规范的要求进行说明和分析解读,相信能让各位在面对高并发业务的时候避开一些坑。往期回顾: 为什么我建议在复杂但是性能关键的表上所有查询都加上 force index


在业务一开始上线的时候,我们线上日志级别是 INFO,并且在日志内容中输出了代码位置,格式例如:

2022-03-02 19:57:59.425  INFO [service-apiGateway,,] [35800] [main][org.springframework.cloud.gateway.route.RouteDefinitionRouteLocator:88]: Loaded RoutePredicateFactory [Query]

我们使用的日志框架是 Log4j2,方式是异步日志,Log4j2 的 Disruptor 的 WaitStrategy 采用了比较平衡 CPU 占用比较小的 Sleep,即配置了:AsyncLoggerConfig.WaitStrategy=Sleep。随着业务的增长,我们发现经常有的实例 CPU 占用非常之高(尤其是那种短时间内有大量日志输出的),我们 dump 了 JFR 进行进一步定位:

首先我们来看 GC,我们的 GC 算法是 G1,主要通过 G1 Garbage Collection这个事件查看:


image.png


发现 GC 全部为 Young GC,且耗时比较正常,频率上也没有什么明显异常。

接下来来看,CPU 占用相关。直接看 Thread CPU Load 这个事件,看每个线程的 CPU 占用情况。发现reactor-http-epoll线程池的线程,CPU 占用很高,加在一起,接近了 100%。


image.png


这些线程是 reactor-netty 处理业务的线程,观察其他实例,发现正常情况下,并不会有这么高的 CPU 负载。那么为啥会有这么高的负载呢?通过 Thread Dump 来看一下线程堆栈有何发现.

通过查看多个线程堆栈 dump,发现这些线程基本都处于 Runnable,并且执行的方法是原生方法,和StackWalker相关,例如(并且这个与 JFR 中采集的 Method Runnable 事件中占比最高的吻合,可以基本确认这个线程的 CPU 主要消耗在这个堆栈当前对应的方法上):


image.jpeg



主要和这两个原生方法有关

  • java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk
  • java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames

并且需要注意微服务中线程堆栈会很深(150左右),对于响应式代码更是如此(可能会到300),主要是因为 servlet 与 filter 的设计是责任链模式,各个 filter 会不断加入堆栈。响应式的代码就更是这样了,一层套一层,各种拼接观察点。上面列出的堆栈就是响应式的堆栈。

会到那两个原生方法,其实这里的代码是在做一件事,就是日志中要输出调用打印日志方法的代码位置,包括类名,方法名,方法行数这些。在上面我给出的线程堆栈的例子中,调用打印日志方法的代码位置信息就是这一行:at com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144),这一行中,我们使用 log.info() 输出了一些日志。

可以看出,Log4j2 是通过获取当前线程堆栈来获取调用打印日志方法的代码位置的。并且并不是堆栈中的栈顶就是调用打印日志方法的代码位置,而是找到 log4j2 堆栈元素之后的第一个堆栈元素才是打印日志方法的代码位置

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
6月前
|
SQL 存储 监控
|
17天前
|
监控 测试技术 开发者
一行代码改进:Logtail的多行日志采集性能提升7倍的奥秘
一个有趣的现象引起了作者的注意:当启用行首正则表达式处理多行日志时,采集性能出现下降。究竟是什么因素导致了这种现象?本文将探索Logtail多行日志采集性能提升的秘密。
|
20天前
|
运维 监控 Cloud Native
一行代码都不改,Golang 应用链路指标日志全知道
本文将通过阿里云开源的 Golang Agent,帮助用户实现“一行代码都不改”就能获取到应用产生的各种观测数据,同时提升运维团队和研发团队的幸福感。
|
6月前
|
存储 算法 Go
go语言并发实战——日志收集系统(七) etcd的介绍与简单使用
go语言并发实战——日志收集系统(七) etcd的介绍与简单使用
08-06-06>pe_xscan 精简log分析代码 速度提升一倍
08-06-06>pe_xscan 精简log分析代码 速度提升一倍
|
3月前
|
SQL 安全 数据库
基于SQL Server事务日志的数据库恢复技术及实战代码详解
基于事务日志的数据库恢复技术是SQL Server中一个非常强大的功能,它能够帮助数据库管理员在数据丢失或损坏的情况下,有效地恢复数据。通过定期备份数据库和事务日志,并在需要时按照正确的步骤恢复,可以最大限度地减少数据丢失的风险。需要注意的是,恢复数据是一个需要谨慎操作的过程,建议在执行恢复操作之前,详细了解相关的操作步骤和注意事项,以确保数据的安全和完整。
167 0
|
4月前
|
消息中间件 Kubernetes Kafka
微服务从代码到k8s部署应有尽有系列(十一、日志收集)
微服务从代码到k8s部署应有尽有系列(十一、日志收集)
|
4月前
分享一份 .NET Core 简单的自带日志系统配置,平时做一些测试或个人代码研究,用它就可以了
分享一份 .NET Core 简单的自带日志系统配置,平时做一些测试或个人代码研究,用它就可以了
|
6月前
|
监控 Go
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
|
6月前
|
存储 Go 索引
go语言并发实战——日志收集系统(一) 项目前言
go语言并发实战——日志收集系统(一) 项目前言
go语言并发实战——日志收集系统(一) 项目前言
下一篇
DataWorks