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