153 lines
13 KiB
Markdown
153 lines
13 KiB
Markdown
|
||
source:[加Log就卡？不加Log就瞎？”——这个插件治好了我的精神内耗](https://mp.weixin.qq.com/s/Nii4fC15eKoNN8MOAzrmDQ)
|
||
|
||
---
|
||
|
||
|
||
#
|
||
|
||
- 1 现有日志打印情况
|
||
|
||
|
||
- 1 日志阻塞
|
||
|
||
- 2 从调试到生产，日志策略的抉择
|
||
|
||
|
||
- 2 问题出现原因
|
||
|
||
|
||
- 2.1 日志打印原理分析
|
||
|
||
- 2.2 log4j2 Disruptor 的初始化
|
||
|
||
- 2.3 队列满导致日志阻塞
|
||
|
||
- 2.4 产生的根本原因
|
||
|
||
|
||
- 3 应对方案
|
||
|
||
|
||
- 3.1 方案选择
|
||
|
||
- 3.2 技术选择
|
||
|
||
- 3.3 落地实现
|
||
|
||
|
||
- 4 总结
|
||
|
||
|
||
|
||
|
||
## 1 现有日志打印情况
|
||
|
||
日志作为软件工程实践中的重要基础设施，在系统监控、异常诊断及行为追溯等关键环节发挥着不可替代的作用。Apache Log4j2作为当前主流的日志框架，凭借其模块化架构和高度可扩展的特性，为开发者提供了灵活的多维度日志管理方案。然而若未能深入理解其异步日志机制、缓冲区策略等核心原理，或存在配置参数与业务场景匹配度不足等问题，则可能导致日志I/O阻塞、内存资源过度消耗等负面效应，甚至引发严重的服务性能瓶颈。因此，在实际工程实践中需遵循科学合理的使用准则，通过日志分级管理、输出格式优化、滚动策略定制等手段，方能充分发挥其技术优势，有效规避潜在风险。
|
||
|
||
### 1 日志阻塞
|
||
|
||
日志导致线程Block的问题，相信你或许已经遇到过，对此应该深有体会；或许你还没遇到过，但不代表没有问题，只是可能还没有触发而已。常见的现象是出现大量的block线程，查看jstack常常是下图现象：
|
||
|
||
### 2 从调试到生产，日志策略的抉择
|
||
|
||
在软件项目的全生命周期中，从开发阶段到生产环境的演进过程中，日志管理往往面临着微妙的平衡。开发阶段我们倾向于采用详尽的日志策略：业务接口的入参出参被完整记录，跨系统的调用链路被清晰标注，甚至非核心逻辑的辅助性信息也得以留存——这些详实的日志如同开发者的双目，为联调排障与功能验证提供了不可或缺的洞察。
|
||
|
||
然而当服务迈向生产环境时，过度日志带来的问题便逐渐显现。冗余的调试信息不仅会影响系统性能，更可能淹没真正关键的业务轨迹。尽管我们尝试在上线前进行日志裁剪，但总存在令人踌躇的灰色地带：某些开发期辅助日志是否暗含未来的诊断价值？那些看似非核心的流程记录会否在某个异常场景下成为关键线索？这种取舍的困境，本质上反映了我们对系统可观测性与运行效能之间永续的权衡。
|
||
|
||
## 2 问题出现原因
|
||
|
||
### 2.1 日志打印原理分析
|
||
|
||
在我们使用的log4j的应用中采用的是异步日志配置，简单的说明一下一条日志打印在log4j中的处理流程如下图所示： 简单点来说，就是多线程通过 log4j2 的门面类进行日志的打印，日志经过一系列的处理（过滤，包装）后放入到Disruptor的环形 buffer 中，在服务器的消费端会单启一个线程进行这些日志的消费，最终放入到我们指定的文件中。
|
||
|
||
### 2.2 log4j2 Disruptor 的初始化
|
||
|
||
当LoggerContext启动时，所有AsyncLoggerConfig会通过start()方法初始化其Disruptor： 其中Disruptor 是一个环形 buffer，官方做了很多的性能优化，这里有兴趣的可以了解其实现原理，这里不进行深入的讨论，其中在我们的应用log4j.xml配置中，没对RingBuffer进行自定义的配置，使用的是默认的大小256K。
|
||
|
||
### 2.3 队列满导致日志阻塞
|
||
|
||
Disruptor 的 RingBuffer 是一个固定大小的环形队列，其发布逻辑：
|
||
|
||
队列满时的默认行为：AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=true，此时会等待着消费出下一个可以生产的环形 buffer 槽；此时所有打印日志的线程会尝试获取全局锁。此时会阻塞线程，也就是我们上述堆栈中看到的异常。
|
||
|
||
### 2.4 产生的根本原因
|
||
|
||
生产者速度 > 消费者速度：
|
||
|
||
AsyncAppender 的后台线程从队列中取出事件并交给实际 Appender（如 FileAppender）处理，如果实际 Appender 的写入速度慢（如磁盘 I/O 高），消费者线程无法及时清空队列，导致队列积压。其实log4j消费时会调用多次 flush，这些flush的调用根本在文件写入的 native 调用，当这种native调用太多时，系统写入不过来。
|
||
|
||
## 3 应对方案
|
||
|
||
### 3.1 方案选择
|
||
|
||
上述问题情况解决，大致分成两个方向：生产者方向&消费者方向，具体行为如下图简述： 在应对日志管理的挑战时，除了调整日志队列容量等基础优化（需警惕OOM风险），更核心的问题在于如何平衡日志的详实性与系统稳定性。开发者往往陷入两难：若详尽记录日志，可能引发阻塞风险；若过度精简，则排查问题时如盲人摸象，难溯根源。
|
||
|
||
为此，可考虑将日志划分为两类：
|
||
|
||
功能日志（必须）：如埋点数据、核心流程记录，确保业务可观测性；
|
||
|
||
业务排查日志（非必须）：如RPC入参/出参、调试断点等，按需动态启停；
|
||
|
||
通过这种分层策略，既能在高并发场景下保障核心日志的稳定输出，又能灵活控制辅助日志的打印量，使系统整体具备更强的适应性与可控性。如此，我们既能从容应对生产环境的严苛要求，又能在需要时快速激活详尽的诊断信息，实现运维效率与系统性能的兼得。
|
||
|
||
### 3.2 技术选择
|
||
|
||
在日志打印的精细化控制中，核心在于灵活性与精准度的平衡。传统的全局级别过滤（如INFO/WARN/ERROR）虽能粗放管理，却难以适配复杂多变的业务场景。理想的方案应突破层级限制，实现行级细粒度控制——无论是核心链路的关键节点，还是特定业务场景的临时调试，均可针对单行日志动态启停。
|
||
|
||
这种设计赋予开发者更高的自主权：业务视角：按需捕获特定模块的完整上下文；链路视角：精准聚焦某次调用的全生命周期轨迹；应急场景：即时激活深层诊断日志，无需重启或改码。
|
||
|
||
通过将控制粒度细化至代码行，我们既能维持生产环境的日志精简，又能随时按业务诉求“点亮”关键路径，使系统可观测性兼具严谨与弹性。
|
||
|
||
#### 3.2.1 区分必要日志和非必要日志打印：
|
||
|
||
自定义封装日志打印的方式如下图所示：
|
||
|
||
#### 3.2.2 如何对非必要日志进行行级别控制
|
||
|
||
1、自定义Appender中的filter：
|
||
|
||
在实现行级日志控制时，若需精确控制特定代码行（如第133行）的日志输出，采用自定义Appender过滤机制是一种可行方案。其核心思路在于：通过解析日志调用的堆栈信息，动态判断当前行号是否符合预设的打印条件，若不符合则直接过滤。
|
||
|
||
然而，该方案存在若干固有局限： 堆栈解析的可靠性问题：Lambda表达式中的日志调用往往难以准确获取行号信息，即使通过堆栈缓存优化，仍存在定位失准的风险；性能损耗隐患：频繁的堆栈遍历操作会引入不可忽视的性能开销，在高并发场景下可能成为新的瓶颈；分类管理缺失：该机制难以与既有的日志分级体系（必需/非必需日志）形成有机协同，增加了运维复杂度。
|
||
|
||
2、在打印日志前获取日志的行信息：
|
||
|
||
最简单的方式是人工的形式，在写日志的时候同时将日志的行信息写入进去，比如：这种方式在可扩展性和可观测性维度存在设计缺陷。
|
||
|
||
3、在编译的时候获取日志的行信息：
|
||
|
||
我们想使用LogUtils.debug(()->log.info("业务日志"));这种方式，但是我们不会在代码中明显的写入，可以在代码编译期间将行信息获取到后使用字节码修改这行代码，利用Java的重写。将它转变成 LogUtils.debug("类+行",()->log.info("业务日志")); 然后再这个方法执行中进行条件判断。
|
||
|
||
字节码技术选择：
|
||
 在本次实现中需要更灵活的方式操作字节码，还要考虑性能的问题，以及对应用框架的支持， 我们选择ASM的形式。
|
||
|
||
4、如何随心控制开启和关闭：
|
||
|
||
这里我们采用的是ider插件的方式，有idea插件上报我们的对这行日志的控制行为，如下图所示：
|
||
|
||
### 3.3 落地实现
|
||
|
||
#### 3.3.1 Maven编译插件
|
||
|
||
目的：获取日志所在的类和行信息。
|
||
|
||
运行时获取的方式：在 Logger 配置中启用 includeLocation，代码从 LogEvent通过堆栈分析获取行号。这种方式存在很大的弊端，堆栈跟踪生成开销很大，每次调用 getStackTrace() 时，JVM 需要遍历当前线程的调用栈，生成完整的堆栈信息，这是一个 同步且耗时 的操作（尤其在深调用链中），如果每秒有数万次日志调用，频繁生成堆栈跟踪可能导致 CPU 使用率飙升，直接影响吞吐量。
|
||
|
||
Maven的process-classes阶段获取：通过Maven编译之后获取到字节码文件时，对字节码文件进行修改，存放日志的类和行信息。对运行期间无额外消耗。处理逻辑如下图所示：
|
||
|
||
#### 3.3.2 Idea插件
|
||
|
||
目的：精准的控制某一行日志是否进行打印。
|
||
|
||
利用Idea的插件能力，将我们对某一行日志的开启和关闭状态进行上报，整个过程不阻塞主线程，保持Idea操作流畅性。提供定时能力，保障线上我们可以更灵活的控制日志是否打印的状态。处理逻辑如下图所示；
|
||
|
||
#### 3.3.3 整体流程
|
||
|
||
使用方式：通过在项目中使用上述Maven插件对项目进行编译部署，使用Idea插件对目标日志的是否开启打印状态进行上报，存储状态采用的Apollo的能力，通过自定义打印工具类中对Apollo配置内容的分析，进一步做判断逻辑，最终将日志进行打印或者不打印。处理逻辑如下图所示：
|
||
|
||
## 4 总结
|
||
|
||
在分布式系统日益复杂的今天，日志管理已从简单的信息记录演进为系统可观测性的核心支柱。本文揭示的日志阻塞与策略困境，折射出现代化服务在稳定性与可维护性之间的深层博弈。通过剖析Log4j2异步日志机制的内在原理，我们识别出队列积压导致线程阻塞的关键症结，并由此展开对日志治理体系的深度重构。
|
||
|
||
本次优化方案突破传统日志分级思维的桎梏，创新性地提出双轨制日志管理体系：将日志划分为功能型与诊断型两类，前者确保核心业务脉络的持续可见，后者实现按需动态管控。通过编译期字节码增强技术，我们实现代码行级别的精准控制，配合IDE插件的可视化操作，使开发人员能够像调试断点般自由启停日志输出。这种"外科手术式"的日志管理，既避免了传统方案"一刀切"的弊端，又赋予系统在高负载场景下的弹性适应能力。 |