先说结论如果你遇到内存告警dump 里全是ch.qos.logback.classic.spi.LoggingEvent那十有八九是日志框架自己把堆给“喂”满了。我这次排查了一个订单网关服务8G 堆老年代占用持续飙到 85% 以上Full GC 每几分钟来一次重启只能撑几个小时。最后定位到根因不是业务代码泄漏而是 Logback 的异步 Appender 队列里积压了大量日志事件。下面我把这次内存优化的完整过程、根因分析和修复合集整理出来希望能帮你省掉几个通宵。1. 告警复盘一个“小日志”引发的内存告警1.1 现象描述一次深夜的内存告警那天晚上值班群突然跳出内存告警订单网关服务堆内存使用率超过 85%持续 10 分钟未恢复。登录服务器一看老年代已经占了将近 7GJVM 触发 Full GC 之后老年代只能回收很少一部分内存曲线像锯齿一样一路往上爬。第一反应是业务代码有集合类泄漏于是马上用jmap -dump:live,formatb,file/tmp/heap.hprof pid导了一份堆快照下来然后重启服务恢复。结果第二天上午又收到同样的告警。这说明不是偶然的流量尖刺背后一定有固定路径在制造大对象或者留住大对象。在分析 dump 之前我先看了下 GC 日志Young GC 频率很高大量对象晋升到老年代但是 Full GC 之后老年代占用压不下去。再用jmap -histo:live排个序发现了一个非常显眼的名字[Ljava.lang.Object;和ch.qos.logback.classic.spi.LoggingEvent。说实话看到LoggingEvent的时候我心里已经有点数了——内存优化十有八九得从日志框架入手。1.2 初步排查从 GC 日志到堆 dump当时我没有直接用 MAT 去刷界面而是在服务器上先跑了几条命令缩小范围# 看老年代和 FGC 频率 jstat -gcutil pid 1000 10 # 看对象统计 jmap -histo:live pid | head -50 | grep -E logback|LoggingEvent|Object\[\]|byte\[\]|char\[\]jmap -histo:live的结果里ch.qos.logback.classic.spi.LoggingEvent的实例数有十几万每个实例 retained heap 大小不算夸张但十几万个加在一起就非常可观了。更关键的是这些LoggingEvent内部引用的Object[]和String占了大头单个事件所带的 message、参数数组、异常堆栈可能有好几 KB。用 MAT 打开 dump在 Dominator Tree 里顺着LoggingEvent往回找引用链最终清晰地看到ch.qos.logback.core.AsyncAppenderBase$Worker - java.util.concurrent.ArrayBlockingQueue - ch.qos.logback.classic.spi.LoggingEvent这一条链路基本坐实了大量的日志事件被阻塞在AsyncAppender的队列里队列尾部还不断有新事件进入消费线程来不及处理于是对象一直被 GC Roots 引用老年代自然回收不掉。到这里排查方向从“业务代码泄漏”彻底转向了“日志框架配置和日志量治理”。2. 根因拆解Logback 异步队列如何变成“内存黑洞”2.1 异步 Appender 的工作机制以及队列为什么积压Logback 的AsyncAppender本质是一个生产者—消费者模型。业务线程打日志时日志事件并不会直接写文件或控制台而是先塞进一个BlockingQueue后台一个Worker线程再从队列里拉取事件转交给真正的目标 Appender比如FileAppender、ConsoleAppender输出。这听起来没什么问题但队列本身是有容量的。Logback 1.2.x 默认queueSize是 256如果日志产生速度长时间超过后台消费速度队列就会被填满。填满之后的行为由两个参数决定discardingThreshold队列剩余容量低于该比例时会丢弃 TRACE、DEBUG、INFO 级别的日志事件避免阻塞业务线程neverBlock为false时队列满后生产者线程会阻塞等待为true时业务线程直接丢弃事件不会阻塞。看起来默认值挺安全但我们的生产配置里有人把queueSize调成了 65536希望能减少日志丢失。这个想法在平时没问题可一旦日志量突发增长队列里积压的就不是几百条而是几万条日志事件。每一条可能携带一个几十 KB 的 SQL 或 JSON 报文几万条累积起来就是几百 MB 甚至上 GB 的堆内存。后台消费慢还有一个容易被忽略的原因目标 Appender 是写磁盘或走网络的。比如同步写文件时如果磁盘 IO 出现抖动Worker线程被文件锁卡住队列就会越积越深。日志输出看的是最慢环节不是最快环节。2.2 日志事件里到底装了什么被忽略的引用链这是我们最容易踩坑的地方。LoggingEvent并不只是一个简单的日志文本它内部持有message格式化之前的原始消息模板比如订单处理失败orderId{}argumentArray参数数组也就是{}对应的实参对象throwableProxy异常堆栈信息如果日志里带了异常mdcPropertyMap当前线程的 MDC 上下文。问题在于argumentArray会直接引用业务对象本身。比如有一段很常见的代码log.info(调用订单详情接口返回{}, JSON.toJSONString(response));这行日志在打点之前JSON.toJSONString(response)已经生成了一整个 JSON 字符串。这个字符串先传给argumentArray再被LoggingEvent引用。如果队列里积压了 1 万条这样的日志就相当于有 1 万个 JSON 大字符串被强制留在堆里业务代码里对应的 response 对象反而因为已经序列化完变成不可达了但 JSON 字符串本身却牢牢挂在队列上。更夸张的是打印异常堆栈。如果代码里写的是log.error(调用外部系统失败, ex);而日志格式是%d %level %msg%n%ex那么每次出现异常时ThrowableProxy会一直引用整个异常栈里的 StackTraceElement 数组。一个有很多嵌套异常的业务抛错堆栈展开可能上百行。配合循环重试日志内存压力瞬间就上去了。还有一个隐藏问题是includeCallerData。网上很多配置喜欢加includeCallerDatatrue/includeCallerData目的是在日志里显示调用类和方法名。这个配置会让 Logback 在处理每条日志时主动获取调用栈信息生成大量的StackTraceElement对象并保存在事件里。在高并发场景下这不仅是 CPU 开销也会显著放大单个日志事件的堆内存占用。2.3 MDC 与线程池一个小坑如果说队列积压是内存告警的“主犯”那么 MDC 没清理就是“从犯”。我们用 Logback 的 MDC 来传递 traceId 很常见一般是在过滤器里MDC.put(traceId, uuid)请求结束再MDC.remove()。但一旦业务用到了线程池很多人会在任务执行前写MDC.put(traceId, request.getHeader(x-trace-id));然后直接在任务里log.info忘了在 finally 里MDC.remove()。线程池里线程是复用的任务执行完MDC 的 Map 仍然挂在当前线程的 ThreadLocal 上下一个任务进来又往里塞新的键值时间长了这个 Map 会越来越大其中的 value 如果恰好是个大对象或大字符串等于线程池里的每个线程都在帮我们“持有”垃圾。我在这次排查里也看到不少ThreadLocalMap的残留虽然不是内存告警的主要原因但如果不一起清理掉优化效果会打折扣。要根治这个问题只有一条原则MDC 的 put 和 remove 必须成对出现最好放在 try-finally 里。3. 修复与优化从配置到代码逐层“瘦身”3.1 logback.xml 核心参数调整定位到根因之后我改的第一件事就是 Logback 的异步配置。原来生产的 logback.xml 大概是这样的appender nameASYNC classch.qos.logback.classic.AsyncAppender queueSize65536/queueSize discardingThreshold0/discardingThreshold neverBlockfalse/neverBlock includeCallerDatatrue/includeCallerData appender-ref refFILE/ /appender这个配置里queueSize过大是直接诱因includeCallerDatatrue又放大了每条日志的体量neverBlockfalse一旦队列满了还会让业务线程阻塞引发接口超时。修复后我用的配置是appender nameASYNC classch.qos.logback.classic.AsyncAppender queueSize2048/queueSize discardingThreshold512/discardingThreshold neverBlocktrue/neverBlock includeCallerDatafalse/includeCallerData maxFlushTime5000/maxFlushTime appender-ref refFILE/ appender-ref refCONSOLE/ /appender逐个解释下为什么这么调queueSize2048单条日志平均 1KB 到几 KB2048 条也就是几 MB 到十几 MB即使积压也不会对堆造成威胁。如果你对日志丢失率要求极高可以放到 4096但一般不建议超过 8192。日志量大时真正该做的是减少日志量而不是无限放大队列。discardingThreshold512代表队列剩余容量低于 512 时开始丢弃低级别日志保留 WARN/ERROR。这算是一个“熔断”机制宁可丢几条 INFO也不能让内存爆掉。neverBlocktrue生产环境我建议开。日志打不出去不应该反噬业务线程尤其对网关这类对延迟敏感的服务来说业务线程被日志阻塞是不可接受的。代价是极端情况下连 WARN/ERROR 也可能丢但这个概率很低优先级低于服务可用性。includeCallerDatafalse默认就是 false不要去开。如果不关心日志里的类名行号就保持关闭。maxFlushTime5000应用关闭时最多等 5 秒让队列内的日志刷完避免优雅停机时日志直接丢光。另外如果你的 Appender 同时挂在多个目标上比如文件和控制台业务高峰期控制台输出本身也会有锁竞争影响 Worker 消费速度。建议生产环境去掉 ConsoleAppender只保留文件或者集中式日志客户端。3.2 日志内容和级别治理配置参数只是“治标”真正“治本”还是要控制日志产生量和单条日志大小。这次事件里日志量暴增的直接原因是某次发布时把一个 Mapper 的日志级别从 INFO 改成了 DEBUG生产环境原本不该打的 SQL 开始全量打出来。SQL 打印本身就很占空间尤其是有大量IN查询和长参数时一条 SQL 格式化出来能有好几 KB。建议做这几件事生产环境禁止 DEBUG。代码里可以有 DEBUG 日志但生产日志级别统一 INFO特殊情况用专门的 logger 控制改完要记得恢复。不打印完整大对象。需要打印接口入参或返回结果时只打摘要信息比如订单号、状态码、耗时不要直接JSON.toJSONString(整个对象)。不要用字符串拼接构造日志消息。很多人喜欢写log.info(order: orderId , result: result)这样即使日志级别是 INFO字符串也已经拼接完成。正确写法是log.info(order: {}, result: {}, orderId, result)级别不满足时 Logback 不会执行参数格式化能省下很多临时对象。异常堆栈要限制。如果业务确实需要打印异常堆栈考虑只打印概要或限制堆栈深度或是在日志格式里用%ex{5}限制输出前 5 行。不要图省事整个%ex一打到底。日志内容要做脱敏和截断。尤其是报文日志、响应体日志超过 1024 字符就应该截断不然一条日志几十 KB谁看了都害怕。还有一个容易被忽视的点日志模板常量与动态参数的组合。LoggingEvent并不会缓存模板对应的解析结果如果模板是动态拼出来的Logback 每次都要重新解析一遍 patternCPU 和内存都会涨。尽量用常量模板不要把整条 message 动态拼到一个巨大字符串里再打。3.3 结合 Maven 项目的 logback 配置实战查看并控制 SQL 日志这次排查中我们还需要快速确认生产环境到底打出了多少 SQL所以我临时在 Maven 项目里改了 logback.xml 来观察。Maven 项目的 logback.xml 一般放在src/main/resources下Spring Boot 项目也可以直接在application.yml里通过logging.level配置。想临时看到 MyBatis 的 SQL 日志可以在 logback.xml 里加logger nameorg.mybatis levelDEBUG/ logger namecom.xxx.order.mapper levelDEBUG/注意这里有两个层面org.mybatis控制 MyBatis 整体日志com.xxx.order.mapper控制具体 Mapper 接口。如果用了 MyBatis-Spring更常见的配置是通过configuration设置logImpl为Slf4jImpl然后上面的 logger 才生效。如果你只想在本地控制台看 SQL不想影响日志文件可以把 ConsoleAppender 单独抽出来再用logger的additivityfalse只让它打到控制台appender nameSQL_CONSOLE classch.qos.logback.core.ConsoleAppender encoder pattern%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n/pattern /encoder /appender logger namecom.xxx.order.mapper levelDEBUG additivityfalse appender-ref refSQL_CONSOLE/ /logger这样配置之后控制台会瞬间刷出大量 SQL肉眼可见日志量有多恐怖。我当时就站在服务器旁边看着控制台滚动五分钟不到生成了 200MB 日志文件。确认完问题立刻把 level 改回 INFO重新发布。这里给一个更实用的建议使用 Maven 的 profile 来区分环境。比如logback-dev.xml里开启 DEBUGlogback-prod.xml里固定 INFO并用springProfile或 Maven resource 过滤去控制激活哪个文件可以最大程度避免“本地调试爽、线上爆炸”的操作失误。4. 排查工具与问题速查下次别走弯路4.1 确认 Logback 是内存元凶的标准流程如果你也想快速判断自己的内存告警是否和日志框架有关可以按照下面这套流程走省时省力第一步jmap -histo:live看对象统计。执行以下命令jmap -histo:live pid | head -50重点关注ch.qos.logback.classic.spi.LoggingEvent、ch.qos.logback.core.spi.LoggingEvent、byte[]、char[]、Object[]这几类对象。如果LoggingEvent排在前十基本可以断定日志有嫌疑。第二步用 MAT 打开堆 dump在 Histogram 里输入LoggingEvent找到实例列表随便选几个实例右键Merge Shortest Paths to GC Roots看引用链。如果引用链指向ArrayBlockingQueue、AsyncAppenderBase这类对象那就是 Logback 异步队列积压无疑。第三步用jstack查看 Logback 的 Worker 线程状态jstack pid | grep -A 20 AsyncAppender-Worker如果线程状态是WAITING或BLOCKED说明它没有及时消费队列。配合日志文件大小增长速度能很直观地判断消费端是不是“卡住”了。还有一个更轻量的办法直接在代码里临时加一个定时任务输出 AsyncAppender 队列的剩余容量。不过这样要动代码适合短时间验证不适合线上长期跑。4.2 常见问题排查表这里把我这次排查中遇到的和常见的问题整理成一个表格方便你对照排查。现象可能原因排查/处理方式老年代持续增长FGC 后不降Logback 异步队列积压大量日志事件dump 分析引用链调整 queueSize、丢弃阈值治理日志量业务线程阻塞接口 RT 飙高AsyncAppender 队列满neverBlockfalse设置 neverBlocktrue或减少日志输出量日志文件异常巨大磁盘占用高日志级别 DEBUG 残留SQL/报文全量输出生产关闭 DEBUG限制单条日志长度异步日志输出延迟严重Worker 线程消费慢目标 Appender 是同步文件或网络排查磁盘 IO、网络优化目标 Appender 或独立通道日志偶尔丢失discardingThreshold 设置过高队列满触发丢弃调低阈值、增加队列容量或接受此取舍线程池中出现“脏”MDC 数据MDC 未 remove线程复用在 finally 中 MDC.remove()或使用任务包装器使用集中式日志 Appender 后内存上涨Loki/Logstash 等 appender 内部还有独立队列查看对应 appender 的队列/批处理参数限制缓存大小4.3 容易忽略的细节除了 Logback 本身的 AsyncAppender我们还要警惕其他日志通道。比如现在流行把日志异步发送到 Lokiloki-logback-appender这类组件内部通常也维护了自己的发送队列和批处理 buffer。如果 Loki 服务端不稳定、网络延迟高发送动作也会积压日志事件导致内存上涨。排查时不要只看 AsyncAppender还要打开这些第三方 Appender 的配置找到它内部的缓存队列参数按实际吞吐量调整或限制。另外动态创建的 LoggerContext 也是一个隐蔽的泄漏点。有些人会在代码里手动new LoggerContext来动态输出日志用完却没有loggerContext.stop()导致这个上下文里的 Appender 和队列一直存活。这种问题在 dump 里能看到多个 LoggerContext而且 GC Root 都指向代码里的强引用。建议把动态日志方案改造成复用静态 Logger不要在业务代码里频繁创建上下文。还有一个很多人忽略的点Logback 的LevelFilter和ThresholdFilter的使用。如果你只想记录某个级别的日志直接用LevelFilter设置匹配级别如果用ThresholdFilter要注意它是“高于等于”级别放行配置反了可能会让 INFO 日志混进 ERROR 文件导致文件增长失控。检查过滤器配置也是日志量治理的一部分。5. 效果验证与个人体会5.1 优化后的数据对比修复配置并发布之后我这边持续观察了一周。优化前的数据是老年代占用 85% 以上Full GC 频率平均每 5 分钟一次单次 FGC 停顿最长超过 1.5 秒。优化后老年代基本稳定在 40%~55% 之间Full GC 变成一天几次而且几乎都发生在流量高峰时段停顿也降到 200ms 以内。日志文件从每天 200GB 降到 30GB 左右对磁盘 IO 的压力也小了很多。从内存优化角度看这次最大的收益不是省了多少 MB而是把“GC 问题”和“日志框架”之间的因果关系看清了。之前很多同事觉得日志就是砸钱买硬盘的事多打几条没问题但站在 JVM 内存视角每条日志在队列里被引用多久、占据多大空间都是真实的内存消耗。5.2 几点教训我自己总结了三句话也算给后来者提个醒。第一日志配置属于基础设施改之前要评估峰值场景。不要拍脑袋把queueSize调到几万也不要盲目开includeCallerData。异步队列不是越大越好它只是把“日志丢失风险”换成了“内存风险”最终还是要靠减少日志量来解决问题。第二生产环境慎开 DEBUG。查问题可以临时开查完必须恢复。最好用环境隔离的配置方式从机制上杜绝“误发布”。第三内存告警不要只盯“集合类泄漏”。Java 内存里日志框架占用的比例往往比我们想象的大得多。堆 dump 里出现大量LoggingEvent时要立刻顺着引用链找是不是队列积压而不是反复去翻业务代码。最后再分享一个小技巧如果你要对现有系统做一次日志治理可以先单独统计每个 Logger 在单位时间内的输出数量和字节数找到 TOP 10 的 Logger然后针对性优化对应业务代码里的日志打点。这个方法比全局降日志级别精准得多也能避免把有用日志误伤掉。我这次就是先通过jmap -histo锁定了异常堆栈相关日志再回到代码里做重点治理效果立竿见影。希望这次的踩坑记录能帮你少走一些弯路。
先说结论如果你遇到内存告警dump 里全是ch.qos.logback.classic.spi.LoggingEvent那十有八九是日志框架自己把堆给“喂”满了。我这次排查了一个订单网关服务8G 堆老年代占用持续飙到 85% 以上Full GC 每几分钟来一次重启只能撑几个小时。最后定位到根因不是业务代码泄漏而是 Logback 的异步 Appender 队列里积压了大量日志事件。下面我把这次内存优化的完整过程、根因分析和修复合集整理出来希望能帮你省掉几个通宵。1. 告警复盘一个“小日志”引发的内存告警1.1 现象描述一次深夜的内存告警那天晚上值班群突然跳出内存告警订单网关服务堆内存使用率超过 85%持续 10 分钟未恢复。登录服务器一看老年代已经占了将近 7GJVM 触发 Full GC 之后老年代只能回收很少一部分内存曲线像锯齿一样一路往上爬。第一反应是业务代码有集合类泄漏于是马上用jmap -dump:live,formatb,file/tmp/heap.hprof pid导了一份堆快照下来然后重启服务恢复。结果第二天上午又收到同样的告警。这说明不是偶然的流量尖刺背后一定有固定路径在制造大对象或者留住大对象。在分析 dump 之前我先看了下 GC 日志Young GC 频率很高大量对象晋升到老年代但是 Full GC 之后老年代占用压不下去。再用jmap -histo:live排个序发现了一个非常显眼的名字[Ljava.lang.Object;和ch.qos.logback.classic.spi.LoggingEvent。说实话看到LoggingEvent的时候我心里已经有点数了——内存优化十有八九得从日志框架入手。1.2 初步排查从 GC 日志到堆 dump当时我没有直接用 MAT 去刷界面而是在服务器上先跑了几条命令缩小范围# 看老年代和 FGC 频率 jstat -gcutil pid 1000 10 # 看对象统计 jmap -histo:live pid | head -50 | grep -E logback|LoggingEvent|Object\[\]|byte\[\]|char\[\]jmap -histo:live的结果里ch.qos.logback.classic.spi.LoggingEvent的实例数有十几万每个实例 retained heap 大小不算夸张但十几万个加在一起就非常可观了。更关键的是这些LoggingEvent内部引用的Object[]和String占了大头单个事件所带的 message、参数数组、异常堆栈可能有好几 KB。用 MAT 打开 dump在 Dominator Tree 里顺着LoggingEvent往回找引用链最终清晰地看到ch.qos.logback.core.AsyncAppenderBase$Worker - java.util.concurrent.ArrayBlockingQueue - ch.qos.logback.classic.spi.LoggingEvent这一条链路基本坐实了大量的日志事件被阻塞在AsyncAppender的队列里队列尾部还不断有新事件进入消费线程来不及处理于是对象一直被 GC Roots 引用老年代自然回收不掉。到这里排查方向从“业务代码泄漏”彻底转向了“日志框架配置和日志量治理”。2. 根因拆解Logback 异步队列如何变成“内存黑洞”2.1 异步 Appender 的工作机制以及队列为什么积压Logback 的AsyncAppender本质是一个生产者—消费者模型。业务线程打日志时日志事件并不会直接写文件或控制台而是先塞进一个BlockingQueue后台一个Worker线程再从队列里拉取事件转交给真正的目标 Appender比如FileAppender、ConsoleAppender输出。这听起来没什么问题但队列本身是有容量的。Logback 1.2.x 默认queueSize是 256如果日志产生速度长时间超过后台消费速度队列就会被填满。填满之后的行为由两个参数决定discardingThreshold队列剩余容量低于该比例时会丢弃 TRACE、DEBUG、INFO 级别的日志事件避免阻塞业务线程neverBlock为false时队列满后生产者线程会阻塞等待为true时业务线程直接丢弃事件不会阻塞。看起来默认值挺安全但我们的生产配置里有人把queueSize调成了 65536希望能减少日志丢失。这个想法在平时没问题可一旦日志量突发增长队列里积压的就不是几百条而是几万条日志事件。每一条可能携带一个几十 KB 的 SQL 或 JSON 报文几万条累积起来就是几百 MB 甚至上 GB 的堆内存。后台消费慢还有一个容易被忽略的原因目标 Appender 是写磁盘或走网络的。比如同步写文件时如果磁盘 IO 出现抖动Worker线程被文件锁卡住队列就会越积越深。日志输出看的是最慢环节不是最快环节。2.2 日志事件里到底装了什么被忽略的引用链这是我们最容易踩坑的地方。LoggingEvent并不只是一个简单的日志文本它内部持有message格式化之前的原始消息模板比如订单处理失败orderId{}argumentArray参数数组也就是{}对应的实参对象throwableProxy异常堆栈信息如果日志里带了异常mdcPropertyMap当前线程的 MDC 上下文。问题在于argumentArray会直接引用业务对象本身。比如有一段很常见的代码log.info(调用订单详情接口返回{}, JSON.toJSONString(response));这行日志在打点之前JSON.toJSONString(response)已经生成了一整个 JSON 字符串。这个字符串先传给argumentArray再被LoggingEvent引用。如果队列里积压了 1 万条这样的日志就相当于有 1 万个 JSON 大字符串被强制留在堆里业务代码里对应的 response 对象反而因为已经序列化完变成不可达了但 JSON 字符串本身却牢牢挂在队列上。更夸张的是打印异常堆栈。如果代码里写的是log.error(调用外部系统失败, ex);而日志格式是%d %level %msg%n%ex那么每次出现异常时ThrowableProxy会一直引用整个异常栈里的 StackTraceElement 数组。一个有很多嵌套异常的业务抛错堆栈展开可能上百行。配合循环重试日志内存压力瞬间就上去了。还有一个隐藏问题是includeCallerData。网上很多配置喜欢加includeCallerDatatrue/includeCallerData目的是在日志里显示调用类和方法名。这个配置会让 Logback 在处理每条日志时主动获取调用栈信息生成大量的StackTraceElement对象并保存在事件里。在高并发场景下这不仅是 CPU 开销也会显著放大单个日志事件的堆内存占用。2.3 MDC 与线程池一个小坑如果说队列积压是内存告警的“主犯”那么 MDC 没清理就是“从犯”。我们用 Logback 的 MDC 来传递 traceId 很常见一般是在过滤器里MDC.put(traceId, uuid)请求结束再MDC.remove()。但一旦业务用到了线程池很多人会在任务执行前写MDC.put(traceId, request.getHeader(x-trace-id));然后直接在任务里log.info忘了在 finally 里MDC.remove()。线程池里线程是复用的任务执行完MDC 的 Map 仍然挂在当前线程的 ThreadLocal 上下一个任务进来又往里塞新的键值时间长了这个 Map 会越来越大其中的 value 如果恰好是个大对象或大字符串等于线程池里的每个线程都在帮我们“持有”垃圾。我在这次排查里也看到不少ThreadLocalMap的残留虽然不是内存告警的主要原因但如果不一起清理掉优化效果会打折扣。要根治这个问题只有一条原则MDC 的 put 和 remove 必须成对出现最好放在 try-finally 里。3. 修复与优化从配置到代码逐层“瘦身”3.1 logback.xml 核心参数调整定位到根因之后我改的第一件事就是 Logback 的异步配置。原来生产的 logback.xml 大概是这样的appender nameASYNC classch.qos.logback.classic.AsyncAppender queueSize65536/queueSize discardingThreshold0/discardingThreshold neverBlockfalse/neverBlock includeCallerDatatrue/includeCallerData appender-ref refFILE/ /appender这个配置里queueSize过大是直接诱因includeCallerDatatrue又放大了每条日志的体量neverBlockfalse一旦队列满了还会让业务线程阻塞引发接口超时。修复后我用的配置是appender nameASYNC classch.qos.logback.classic.AsyncAppender queueSize2048/queueSize discardingThreshold512/discardingThreshold neverBlocktrue/neverBlock includeCallerDatafalse/includeCallerData maxFlushTime5000/maxFlushTime appender-ref refFILE/ appender-ref refCONSOLE/ /appender逐个解释下为什么这么调queueSize2048单条日志平均 1KB 到几 KB2048 条也就是几 MB 到十几 MB即使积压也不会对堆造成威胁。如果你对日志丢失率要求极高可以放到 4096但一般不建议超过 8192。日志量大时真正该做的是减少日志量而不是无限放大队列。discardingThreshold512代表队列剩余容量低于 512 时开始丢弃低级别日志保留 WARN/ERROR。这算是一个“熔断”机制宁可丢几条 INFO也不能让内存爆掉。neverBlocktrue生产环境我建议开。日志打不出去不应该反噬业务线程尤其对网关这类对延迟敏感的服务来说业务线程被日志阻塞是不可接受的。代价是极端情况下连 WARN/ERROR 也可能丢但这个概率很低优先级低于服务可用性。includeCallerDatafalse默认就是 false不要去开。如果不关心日志里的类名行号就保持关闭。maxFlushTime5000应用关闭时最多等 5 秒让队列内的日志刷完避免优雅停机时日志直接丢光。另外如果你的 Appender 同时挂在多个目标上比如文件和控制台业务高峰期控制台输出本身也会有锁竞争影响 Worker 消费速度。建议生产环境去掉 ConsoleAppender只保留文件或者集中式日志客户端。3.2 日志内容和级别治理配置参数只是“治标”真正“治本”还是要控制日志产生量和单条日志大小。这次事件里日志量暴增的直接原因是某次发布时把一个 Mapper 的日志级别从 INFO 改成了 DEBUG生产环境原本不该打的 SQL 开始全量打出来。SQL 打印本身就很占空间尤其是有大量IN查询和长参数时一条 SQL 格式化出来能有好几 KB。建议做这几件事生产环境禁止 DEBUG。代码里可以有 DEBUG 日志但生产日志级别统一 INFO特殊情况用专门的 logger 控制改完要记得恢复。不打印完整大对象。需要打印接口入参或返回结果时只打摘要信息比如订单号、状态码、耗时不要直接JSON.toJSONString(整个对象)。不要用字符串拼接构造日志消息。很多人喜欢写log.info(order: orderId , result: result)这样即使日志级别是 INFO字符串也已经拼接完成。正确写法是log.info(order: {}, result: {}, orderId, result)级别不满足时 Logback 不会执行参数格式化能省下很多临时对象。异常堆栈要限制。如果业务确实需要打印异常堆栈考虑只打印概要或限制堆栈深度或是在日志格式里用%ex{5}限制输出前 5 行。不要图省事整个%ex一打到底。日志内容要做脱敏和截断。尤其是报文日志、响应体日志超过 1024 字符就应该截断不然一条日志几十 KB谁看了都害怕。还有一个容易被忽视的点日志模板常量与动态参数的组合。LoggingEvent并不会缓存模板对应的解析结果如果模板是动态拼出来的Logback 每次都要重新解析一遍 patternCPU 和内存都会涨。尽量用常量模板不要把整条 message 动态拼到一个巨大字符串里再打。3.3 结合 Maven 项目的 logback 配置实战查看并控制 SQL 日志这次排查中我们还需要快速确认生产环境到底打出了多少 SQL所以我临时在 Maven 项目里改了 logback.xml 来观察。Maven 项目的 logback.xml 一般放在src/main/resources下Spring Boot 项目也可以直接在application.yml里通过logging.level配置。想临时看到 MyBatis 的 SQL 日志可以在 logback.xml 里加logger nameorg.mybatis levelDEBUG/ logger namecom.xxx.order.mapper levelDEBUG/注意这里有两个层面org.mybatis控制 MyBatis 整体日志com.xxx.order.mapper控制具体 Mapper 接口。如果用了 MyBatis-Spring更常见的配置是通过configuration设置logImpl为Slf4jImpl然后上面的 logger 才生效。如果你只想在本地控制台看 SQL不想影响日志文件可以把 ConsoleAppender 单独抽出来再用logger的additivityfalse只让它打到控制台appender nameSQL_CONSOLE classch.qos.logback.core.ConsoleAppender encoder pattern%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n/pattern /encoder /appender logger namecom.xxx.order.mapper levelDEBUG additivityfalse appender-ref refSQL_CONSOLE/ /logger这样配置之后控制台会瞬间刷出大量 SQL肉眼可见日志量有多恐怖。我当时就站在服务器旁边看着控制台滚动五分钟不到生成了 200MB 日志文件。确认完问题立刻把 level 改回 INFO重新发布。这里给一个更实用的建议使用 Maven 的 profile 来区分环境。比如logback-dev.xml里开启 DEBUGlogback-prod.xml里固定 INFO并用springProfile或 Maven resource 过滤去控制激活哪个文件可以最大程度避免“本地调试爽、线上爆炸”的操作失误。4. 排查工具与问题速查下次别走弯路4.1 确认 Logback 是内存元凶的标准流程如果你也想快速判断自己的内存告警是否和日志框架有关可以按照下面这套流程走省时省力第一步jmap -histo:live看对象统计。执行以下命令jmap -histo:live pid | head -50重点关注ch.qos.logback.classic.spi.LoggingEvent、ch.qos.logback.core.spi.LoggingEvent、byte[]、char[]、Object[]这几类对象。如果LoggingEvent排在前十基本可以断定日志有嫌疑。第二步用 MAT 打开堆 dump在 Histogram 里输入LoggingEvent找到实例列表随便选几个实例右键Merge Shortest Paths to GC Roots看引用链。如果引用链指向ArrayBlockingQueue、AsyncAppenderBase这类对象那就是 Logback 异步队列积压无疑。第三步用jstack查看 Logback 的 Worker 线程状态jstack pid | grep -A 20 AsyncAppender-Worker如果线程状态是WAITING或BLOCKED说明它没有及时消费队列。配合日志文件大小增长速度能很直观地判断消费端是不是“卡住”了。还有一个更轻量的办法直接在代码里临时加一个定时任务输出 AsyncAppender 队列的剩余容量。不过这样要动代码适合短时间验证不适合线上长期跑。4.2 常见问题排查表这里把我这次排查中遇到的和常见的问题整理成一个表格方便你对照排查。现象可能原因排查/处理方式老年代持续增长FGC 后不降Logback 异步队列积压大量日志事件dump 分析引用链调整 queueSize、丢弃阈值治理日志量业务线程阻塞接口 RT 飙高AsyncAppender 队列满neverBlockfalse设置 neverBlocktrue或减少日志输出量日志文件异常巨大磁盘占用高日志级别 DEBUG 残留SQL/报文全量输出生产关闭 DEBUG限制单条日志长度异步日志输出延迟严重Worker 线程消费慢目标 Appender 是同步文件或网络排查磁盘 IO、网络优化目标 Appender 或独立通道日志偶尔丢失discardingThreshold 设置过高队列满触发丢弃调低阈值、增加队列容量或接受此取舍线程池中出现“脏”MDC 数据MDC 未 remove线程复用在 finally 中 MDC.remove()或使用任务包装器使用集中式日志 Appender 后内存上涨Loki/Logstash 等 appender 内部还有独立队列查看对应 appender 的队列/批处理参数限制缓存大小4.3 容易忽略的细节除了 Logback 本身的 AsyncAppender我们还要警惕其他日志通道。比如现在流行把日志异步发送到 Lokiloki-logback-appender这类组件内部通常也维护了自己的发送队列和批处理 buffer。如果 Loki 服务端不稳定、网络延迟高发送动作也会积压日志事件导致内存上涨。排查时不要只看 AsyncAppender还要打开这些第三方 Appender 的配置找到它内部的缓存队列参数按实际吞吐量调整或限制。另外动态创建的 LoggerContext 也是一个隐蔽的泄漏点。有些人会在代码里手动new LoggerContext来动态输出日志用完却没有loggerContext.stop()导致这个上下文里的 Appender 和队列一直存活。这种问题在 dump 里能看到多个 LoggerContext而且 GC Root 都指向代码里的强引用。建议把动态日志方案改造成复用静态 Logger不要在业务代码里频繁创建上下文。还有一个很多人忽略的点Logback 的LevelFilter和ThresholdFilter的使用。如果你只想记录某个级别的日志直接用LevelFilter设置匹配级别如果用ThresholdFilter要注意它是“高于等于”级别放行配置反了可能会让 INFO 日志混进 ERROR 文件导致文件增长失控。检查过滤器配置也是日志量治理的一部分。5. 效果验证与个人体会5.1 优化后的数据对比修复配置并发布之后我这边持续观察了一周。优化前的数据是老年代占用 85% 以上Full GC 频率平均每 5 分钟一次单次 FGC 停顿最长超过 1.5 秒。优化后老年代基本稳定在 40%~55% 之间Full GC 变成一天几次而且几乎都发生在流量高峰时段停顿也降到 200ms 以内。日志文件从每天 200GB 降到 30GB 左右对磁盘 IO 的压力也小了很多。从内存优化角度看这次最大的收益不是省了多少 MB而是把“GC 问题”和“日志框架”之间的因果关系看清了。之前很多同事觉得日志就是砸钱买硬盘的事多打几条没问题但站在 JVM 内存视角每条日志在队列里被引用多久、占据多大空间都是真实的内存消耗。5.2 几点教训我自己总结了三句话也算给后来者提个醒。第一日志配置属于基础设施改之前要评估峰值场景。不要拍脑袋把queueSize调到几万也不要盲目开includeCallerData。异步队列不是越大越好它只是把“日志丢失风险”换成了“内存风险”最终还是要靠减少日志量来解决问题。第二生产环境慎开 DEBUG。查问题可以临时开查完必须恢复。最好用环境隔离的配置方式从机制上杜绝“误发布”。第三内存告警不要只盯“集合类泄漏”。Java 内存里日志框架占用的比例往往比我们想象的大得多。堆 dump 里出现大量LoggingEvent时要立刻顺着引用链找是不是队列积压而不是反复去翻业务代码。最后再分享一个小技巧如果你要对现有系统做一次日志治理可以先单独统计每个 Logger 在单位时间内的输出数量和字节数找到 TOP 10 的 Logger然后针对性优化对应业务代码里的日志打点。这个方法比全局降日志级别精准得多也能避免把有用日志误伤掉。我这次就是先通过jmap -histo锁定了异常堆栈相关日志再回到代码里做重点治理效果立竿见影。希望这次的踩坑记录能帮你少走一些弯路。
