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

本文涉及的产品
日志服务 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日志并进行多维度分析。
相关文章
|
5月前
|
SQL 存储 监控
|
6月前
|
Java
使用Java代码打印log日志
使用Java代码打印log日志
315 1
|
5月前
|
存储 算法 Go
go语言并发实战——日志收集系统(七) etcd的介绍与简单使用
go语言并发实战——日志收集系统(七) etcd的介绍与简单使用
|
6月前
|
C++ 开发者 Python
实现Python日志点击跳转到代码位置的方法
本文介绍了如何在Python日志中实现点击跳转到代码位置的功能,以提升调试效率。通过结合`logging`模块的`findCaller()`方法记录代码位置信息,并使用支持点击跳转的日志查看工具(如VS Code、PyCharm),开发者可以从日志直接点击链接定位到出错代码,加快问题排查。
08-06-06>pe_xscan 精简log分析代码 速度提升一倍
08-06-06>pe_xscan 精简log分析代码 速度提升一倍
|
2月前
|
SQL 安全 数据库
基于SQL Server事务日志的数据库恢复技术及实战代码详解
基于事务日志的数据库恢复技术是SQL Server中一个非常强大的功能,它能够帮助数据库管理员在数据丢失或损坏的情况下,有效地恢复数据。通过定期备份数据库和事务日志,并在需要时按照正确的步骤恢复,可以最大限度地减少数据丢失的风险。需要注意的是,恢复数据是一个需要谨慎操作的过程,建议在执行恢复操作之前,详细了解相关的操作步骤和注意事项,以确保数据的安全和完整。
116 0
|
3月前
|
消息中间件 Kubernetes Kafka
微服务从代码到k8s部署应有尽有系列(十一、日志收集)
微服务从代码到k8s部署应有尽有系列(十一、日志收集)
|
3月前
分享一份 .NET Core 简单的自带日志系统配置,平时做一些测试或个人代码研究,用它就可以了
分享一份 .NET Core 简单的自带日志系统配置,平时做一些测试或个人代码研究,用它就可以了
|
5月前
|
监控 Go
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
go语言并发实战——日志收集系统(八) go语言操作etcd以及利用watch实现对键值的监控
|
5月前
|
存储 Go 索引
go语言并发实战——日志收集系统(一) 项目前言
go语言并发实战——日志收集系统(一) 项目前言
go语言并发实战——日志收集系统(一) 项目前言

热门文章

最新文章

  • 1
    高并发场景下,到底先更新缓存还是先更新数据库?
    66
  • 2
    Java面试题:解释Java NIO与BIO的区别,以及NIO的优势和应用场景。如何在高并发应用中实现NIO?
    74
  • 3
    Java面试题:设计一个线程安全的单例模式,并解释其内存占用和垃圾回收机制;使用生产者消费者模式实现一个并发安全的队列;设计一个支持高并发的分布式锁
    68
  • 4
    Java面试题:如何实现一个线程安全的单例模式,并确保其在高并发环境下的内存管理效率?如何使用CyclicBarrier来实现一个多阶段的数据处理任务,确保所有阶段的数据一致性?
    62
  • 5
    Java面试题:结合建造者模式与内存优化,设计一个可扩展的高性能对象创建框架?利用多线程工具类与并发框架,实现一个高并发的分布式任务调度系统?设计一个高性能的实时事件通知系统
    55
  • 6
    Java面试题:假设你正在开发一个Java后端服务,该服务需要处理高并发的用户请求,并且对内存使用效率有严格的要求,在多线程环境下,如何确保共享资源的线程安全?
    69
  • 7
    在Java中实现高并发的数据访问控制
    42
  • 8
    使用Java构建一个高并发的网络服务
    29
  • 9
    微服务06----Eureka注册中心,微服务的两大服务,订单服务和用户服务,订单服务需要远程调用我们的用,户服务,消费者,如果环境改变,硬编码问题就会随之产生,为了应对高并发,我们可能会部署成一个集
    37
  • 10
    如何设计一个秒杀系统,(高并发高可用分布式集群)
    129