压测发现的坑：String.format() 在日志里用多了真能压垮你的服务

最新推荐文章于 2026-06-17 10:40:45 发布

原创最新推荐文章于 2026-06-17 10:40:45 发布 · 966 阅读

23 ·

本内容遵循CC 4.0 BY-SA版权协议

GEO检测

标签

#java #java-ee #后端

先说结论：高并发下日志打得太勤，尤其是用 String.format() 构造复杂消息时，锁竞争 + 对象分配 直接拉满 GC，拖垮 TPS。解法看正文。

1、场景还原（线上真事儿）

某订单查询接口，平时 QPS 1000 左右挺稳。大促时流量翻倍到 2000 QPS，接口 RT 突然从 20ms 暴涨到 200ms+，CPU 飚到 90%，大量线程卡在 TIMED_WAITING 状态。gc.log 显示 Young GC 频率从 10秒/次变成 1秒/次，单次暂停时间没变长，但总暂停时间占比暴涨。

2、揪出元凶：看似无害的日志工具方法

排查发现，核心查询方法里有一段这样的日志代码：

问题分析：

**String.format() 底层有锁： java.util.Formatter 初始化时会获取 Locale 锁。高并发下，N 个线程同时构造日志消息时，锁竞争激烈 -> 大量线程等待锁 -> TIMED_WAITING (parking)。**
频繁创建临时对象： 每次调用 String.format() 至少创建 1 个 Formatter 对象 + 1 个新 String 对象。流量翻倍后，对象分配速率成倍增加，Young 区很快塞满 -> Young GC 频率激增。 虽然 GC 暂停时间不长，但频率高了，CPU 花在 GC 上的时间比例暴涨，挤压业务线程执行时间。
DEBUG 日志级别没控制： 生产环境一般开 INFO 级别，但问题方法在开发测试阶段用了 DEBUG，上线忘切回 INFO，导致线上也在打大量 DEBUG 日志。

3、硬核测试：String.format() VS 手动拼接

写段代码模拟压力（JMH 基准测试更严谨，这里写个简单Demo）：

public class StringFormatStressTest {
// 模拟业务参数
private static final String user = "user123";
private static final String traceId = "req-abc123";
private static final long orderId = 1234567890L;

// 压力次数
private static final int LOOP_COUNT = 1000_0000; // 1000万次

//  测试1: String.format()
public static void testStringFormat() {
long start = System.currentTimeMillis();
for (int i = 0; i < LOOP_COUNT; i++) {
String log = String.format("开始查询订单. ID=%d, 调用方=%s, 追踪ID=%s", orderId, user, traceId);
// do nothing with log (模拟日志框架丢弃)
}
System.out.println("[Format] Time: " + (System.currentTimeMillis() - start) + "ms");
}

//  测试2: StringBuilder 手动拼接
public static void testStringBuilder() {
long start = System.currentTimeMillis();
for (int i = 0; i < LOOP_COUNT; i++) {
// 用StringBuilder提前分配大概容量
String log = new StringBuilder(64)
.append("开始查询订单. ID=").append(orderId)
.append(", 调用方=").append(user)
.append(", 追踪ID=").append(traceId)
.toString();
}
System.out.println("[Builder] Time: " + (System.currentTimeMillis() - start) + "ms");
}

public static void main(String[] args) {
testStringFormat();
testStringBuilder();
}
}

结果（仅作定性参考）：

1000万次调用量级下：
- String.format() 耗时：约 4500 ms
- StringBuilder 耗时：约 500 ms
- 差距近 10 倍！

背后开销：

String.format()：锁竞争、解析格式字符串（%d, %s）、动态装箱（如 long 变 Long）
StringBuilder：纯内存拷贝

4、最终解决方案：四板斧

第一斧：严控日志级别
生产环境非必要不开 DEBUG，核心方法的高频日志升级为 INFO 并评估必要性。
第二斧：日志消息惰性求值
利用 SLF4J / Log4j2 等现代框架的特性：

优势：

- 无锁： 框架内部用 StringBuilder 或类似机制拼装。
- 惰性： 当日志级别不够时，根本不构造参数对象。即使参数构造很复杂（如调用 getExpensiveLogInfo()）也不会浪费资源。
第三斧：复杂消息用 StringBuilder 显式控制
如日志构造涉及多次循环或复杂逻辑：

第四斧：对象重用（高级）
极端性能场景（如金融行情日志），用 ThreadLocal<StringBuilder> 或 Apache Commons Lang 的 StrBuilder 池化减少对象分配：

事后效果

将问题方法中的 String.format() 日志改为 SLF4J 的 {} 占位符写法：

RT 从 200ms+ 降回 25ms
Young GC 频率恢复至正常水平
TIMED_WAITING 线程数显著下降

核心总结：
日志不是免费的： 高并发下，低级API的微小开销会被无限放大。
**String.format() 有锁：** 避免在热点代码路径中使用。占位符日志是更安全的选择。
参数构造要懒惰： 用 logger.isXxxEnabled() 保护复杂参数计算。
监控 GC 和线程状态： TIMED_WAITING + GC 频繁往往是这类瓶颈的信号。
写日志是基本功，但能写“对性能无害”的日志，才是真水平。