接口没慢在 SQL,也没慢在 RPC。
压测线程加到 16 个以后,CPU 开始往上顶,业务方法看着都正常,最后顺着火焰图一层层翻,时间居然耗在了日志上。
这种问题我一般不急着删日志。日志本身没错,真正该查的是:谁在业务线程里拼字符串、格式化对象、刷磁盘。
项目里用的是 Spring Boot 默认带的 Logback:
log.info("订单校验完成,订单信息:" + order);
这行代码看着没什么,放在高频接口里就不太老实了。
不管 INFO 是否开启,字符串拼接和 order.toString() 都已经执行。如果对象字段多一点,再带几个集合,日志还没写出去,CPU 已经先忙了一轮。
至少应该改成参数化日志:
log.info(
"order_checked traceId={} orderId={} channel={} result={}",
traceId,
order.getId(),
order.getChannel(),
checkResult
);
不过,这只能解决无效字符串拼接,解决不了日志框架在高并发下的竞争。
Logback 和 Log4j2 真正拉开差距的地方,通常不是一句普通的同步日志,而是多线程持续写入时的异步模型。
Logback 的 AsyncAppender 更像一个中转站:业务线程把日志事件放进阻塞队列,后台线程再交给真正的文件 Appender。队列一旦挤满,要么阻塞,要么按配置丢掉部分低级别日志。Logback 文档也明确说明,默认情况下 TRACE、DEBUG、INFO 事件可能被当作可丢弃事件处理。
Log4j2 的 AsyncLogger 走的是另一条路,它使用 LMAX Disruptor 在业务线程和日志线程之间传递事件,目的就是减少多线程入队时的锁竞争,尽快让业务线程从 log() 调用中返回。
注意,是 AsyncLogger,不是只在外面套一层 AsyncAppender。这两个名字很像,性能路径不是一回事。
网上那些“Log4j2 比 Logback 快十几倍”的图,我一般不直接信。更有意思的是,Logback 官方自己的某组测试反而显示 Logback 1.3 在部分同步和异步场景中快于 Log4j2;Apache 的历史测试则给出了 Log4j2 异步日志明显领先的结果。
两边都没必要急着站队。日志格式、线程数、队列大小、是否立即刷盘、磁盘类型,随便改一个,结果都可能翻过来。
要测就放进自己的机器里测。下面这段 JMH,我会分别绑定 Logback 和 Log4j2 跑两次,不让两个实现混在同一个 JVM 里:
@State(Scope.Benchmark)
@BenchmarkMode(Mode.Throughput)
@OutputTimeUnit(TimeUnit.SECONDS)
@Threads(16)
public class OrderAuditLogBench {
private static final Logger LOG =
LoggerFactory.getLogger("order-audit");
private final AtomicLong sequence = new AtomicLong(600_000);
@Benchmark
public void writeAuditLog() {
long orderId = sequence.incrementAndGet();
long cost = orderId & 31;
LOG.info(
"order_checked traceId={} orderId={} costMs={} result={}",
Long.toHexString(orderId),
orderId,
cost,
"PASS"
);
}
}
两次测试必须使用相同的日志内容、文件路径、字符集、滚动策略和队列容量。一个开启立即刷盘,另一个批量写入,这种对比没有意义。
在多线程异步写文件的场景里,Log4j2 跑出接近一倍的吞吐优势并不奇怪。线程越多,阻塞队列竞争越明显,Disruptor 的优势越容易露出来。但如果日志最终卡在慢磁盘上,或者每条日志都要序列化一个大 JSON、提取调用位置、打印完整异常栈,框架之间的差距反而可能被这些开销盖住。
还有一个坑得说清楚:异步日志不是把成本消灭了,只是把成本从业务线程搬到了后台线程。
日志产生速度长期高于磁盘写入速度,队列早晚会满。到时候到底是阻塞请求,还是丢掉 INFO 日志,必须提前定。交易、审计、状态变更这类日志,我宁可单独拆 Appender,也不会和普通访问日志挤在同一个异步队列里。
Logback 不是不能用。普通后台系统、日志量不大、Spring Boot 默认配置够用,没必要为了一个压测数字折腾依赖。
但高并发网关、批量任务、消息消费这类日志密集服务,还抱着“日志框架都差不多”的想法,就有点危险了。先把自己的日志链路压一遍,再决定要不要换。
有时候接口慢的那几毫秒,不在数据库,也不在线程池。
就在那句看起来最无辜的 log.info() 里。