 了，可能比你想的更坑)
写在前面
处方物流信息同步优化：从 36 秒到亚秒级的踩坑记录
最近在排查一个线上接口性能问题，处理时间从正常的几百毫秒飙到了 30 多秒。排查过程中翻了一遍代码，发现一处很"不起眼"的日志：
log.info("药品订单回调,参数:{}", JSONUtil.toJsonPrettyStr(dto));当时第一反应是：日志而已，能有多耗时？但当我去掉这行重新测试，接口耗时直接降了一个量级（我发现这个dto对象字段几十个，全打印有点多啊！！）。这件事让我开始认真审视"日志打印对象"这件每天都在做的小事，越研究越发现里面的坑比想象的多。
这篇文章把我在排查过程中梳理的几个核心问题记录下来，希望对同行有参考价值。
一、完整对象打印 vs 字段打印：到底差在哪
先看两种最常见的写法：
// 写法 A：完整对象打印 log.info("dto:{}", JSONUtil.toJsonPrettyStr(dto)); // 写法 B：指定字段打印 log.info("hosCode:{}, recipeSize:{}, deliveryStatus:{}", dto.getInput().getHosCode(), dto.getInput().getRecipeList().size(), dto.getInput().getDeliveryStatus());很多同事看到这两行代码，会觉得"不就是日志多一行、少一行的事吗？能有多大区别"。但实际上差距远不止于此。
1.1 信息完整性的差异
| 维度 | 完整对象打印 | 字段打印 |
|---|---|---|
| 信息覆盖 | 全部字段，理论上面面俱到 | 仅打印选定字段 |
| 信息噪声 | 高，大量无关字段混杂其中 | 低，聚焦关键信息 |
| 可读性 | 差，大段 JSON 需要逐行扫描 | 好，关键信息一目了然 |
完整对象打印看似"信息更全"，但实际排查问题时，90% 的字段是用不上的。而真正有用的那几个字段，反而淹没在几十行 JSON 里，需要肉眼搜索。我之前排查一个订单问题，光是从日志里找到orderSeq这一个字段，就翻了好几屏。
1.2 性能消耗的差异（重点）
这才是核心。完整对象打印在性能上有四个层面的开销：
第一层：序列化开销
JSONUtil.toJsonPrettyStr(dto)要做的事情：
用反射遍历 dto 的所有字段
遇到嵌套对象递归序列化
遇到 List/Map 集合逐个元素序列化
最后还要加上缩进、换行、空格等格式化处理
如果 dto 里包含 50 个处方对象，每个对象 20 个字段，序列化一次可能就要几十毫秒。这在高频接口里是实打实的 CPU 开销。
第二层：内存分配开销
序列化生成的字符串可能从几百字节到几兆不等。JVM 要在堆上分配这些大字符串，用完之后又迅速变成垃圾，触发频繁的 Minor GC。压测时观察 GC 日志，去掉大对象日志打印后，GC 频率能下降一半。
第三层：磁盘 I/O 开销
Logback 写日志是要加锁的。一个大字符串写文件，意味着：
buffer 被占满触发更频繁的 flush
磁盘 IO 带宽被日志吃掉
多线程争抢同一个 appender 锁
第四层：日志收集传输开销
如果用了 ELK/Filebeat 这类日志收集系统，大日志会导致：
Filebeat 传输压力增大
Logstash 解析大 JSON 卡顿
Elasticsearch 存储膨胀，查询变慢
1.3 一个容易被忽视的陷阱：SLF4J 占位符救不了你
有人会说："SLF4J 用{}占位符，如果日志级别不够，不会拼接字符串。"
这话本身没错，但对JSONUtil.toJsonPrettyStr(dto)这种写法完全无效。原因看下面：
log.info("dto:{}", JSONUtil.toJsonPrettyStr(dto));执行顺序是：
JVM 先求值方法参数 → 调用
JSONUtil.toJsonPrettyStr(dto)序列化已经发生，大字符串已经生成
把生成好的字符串传给
log.infoSLF4J 才判断日志级别
也就是说，无论当前日志级别是 INFO 还是 ERROR，序列化都已经在第 1 步完成了。SLF4J 的延迟求值机制对已经生成的参数无能为力。
正确做法是用isDebugEnabled守卫：
if (log.isDebugEnabled()) { log.debug("dto:{}", JSONUtil.toJsonStr(dto)); }二、直接log.info("{}", dto)行不行？
既然JSONUtil.toJsonPrettyStr(dto)有性能问题，那直接把序列化去掉，写成下面这样是不是就 OK 了？
log.info("dto:{}", dto);不行。这种写法可能比JSONUtil.toJsonPrettyStr更坑。
原因在于：当日志框架处理{}占位符时，会调用dto.toString()把对象转成字符串。而toString()的行为完全取决于 DTO 的实现，常见三种情况，每一种都有问题。
2.1 情况一：DTO 用了 Lombok @ToString
这是最常见的场景：
@Data @ToString public class SyncDeliveryDTO { private Input input; // 嵌套对象 private List<RecipeIdDTO> recipeList; // 列表 }Lombok 生成的toString()会递归打印所有字段，输出类似：
SyncDeliveryDTO(input=Input(hosCode=VM001, deliveryStatus=1, recipeList=[...]), recipeList=[RecipeIdDTO(recipeId=123456, ...), RecipeIdDTO(...)])如果recipeList有 50 个元素，这个字符串照样 KB 级甚至更大。和JSONUtil.toJsonPrettyStr相比只是格式从 JSON 换成了 Lombok 风格，体积没有本质区别，性能开销一点没省。
2.2 情况二：DTO 没有覆写 toString()
如果 DTO 是个纯 POJO，没加@ToString也没手写toString()，那调用的就是Object.toString()：
// Object 默认实现 public String toString() { return getClass().getName() + "@" + Integer.toHexString(hashCode()); }日志输出变成：
dto:com.chinaunicom.medical.ihm.api.patient.model.dto.SyncDeliveryDTO@6a5fc7f7这确实很小、很快，但完全没有任何业务信息。出问题排查时，等于日志白打了，反而误导排查方向。
2.3 情况三：toString() 触发副作用（最危险）
这是最隐蔽的坑。如果 DTO 是 JPA/Hibernate 实体，或者字段里有懒加载代理：
@Entity @Data public class Order { @OneToMany(fetch = FetchType.LAZY) private List<OrderPrescription> prescriptions; }当你log.info("order:{}", order)时：
日志框架调用
order.toString()Lombok 的
@ToString会调用prescriptions.toString()prescriptions是懒加载代理，触发真正的 DB 查询一次日志打印，悄悄执行了 N 条 SQL
这种问题排查起来极其困难——你在业务代码里根本找不到那条 SQL 是哪里发出的，因为它来自日志打印时触发的懒加载。
类似的副作用还有：
循环引用：A 持有 B，B 持有 A，
toString()递归调用导致StackOverflowError代理对象：Spring AOP 代理的
toString()行为不可控敏感信息泄露：密码、token 等字段被 toString 输出到日志
2.4 三种写法的横向对比
| 写法 | 可读性 | 信息准确性 | 性能开销 | 调试便捷性 | 副作用风险 |
|---|---|---|---|---|---|
JSONUtil.toJsonPrettyStr(dto) | 好（格式化JSON） | 高 | 高（反射+格式化） | 好（结构清晰） | 低 |
log.info("{}", dto)+ @ToString | 一般（Lombok格式） | 高 | 高（递归toString） | 一般 | 中-高（懒加载/循环引用） |
log.info("{}", dto)无toString | 差（仅类名+hash） | 无 | 低 | 极差 | 低 |
字段打印log.info("k:{}", dto.getK()) | 好 | 高 | 极低 | 好 | 无 |
三、不同场景下的最佳实践
讨论了这么多坑，那到底该怎么打日志？结合实际工程经验，我总结了几个场景的最佳实践。
3.1 生产环境 INFO 日志：只打关键字段
这是最推荐的做法。核心原则是只打印排查问题必需的最小信息集：
// 反例 log.info("处理订单 dto:{}", JSONUtil.toJsonPrettyStr(dto)); // 正例 log.info("syncOrderDeliveryInfo 开始 hosCode:{}, recipeSize:{}, deliveryStatus:{}", dto.getInput().getHosCode(), CollUtil.size(dto.getInput().getRecipeList()), dto.getInput().getDeliveryStatus());选择字段的依据：
业务主键：orderSeq、recipeId、patientId 等
状态字段：orderStatus、deliveryStatus 等
规模信息：list.size() 而不是 list 本身
上下文：userId、tenantId 等
3.2 确实需要看完整对象：用 DEBUG + 守卫
某些排查场景确实需要完整对象，这时应该用 DEBUG 级别 +isDebugEnabled守卫：
if (log.isDebugEnabled()) { log.debug("完整请求 dto:{}", JSONUtil.toJsonStr(dto)); }注意几点：
用
JSONUtil.toJsonStr而不是toJsonPrettyStr，去掉缩进换行，体积小一半必须
isDebugEnabled守卫，否则 DEBUG 关闭时序列化照样发生生产环境默认关闭 DEBUG，需要时临时开启
3.3 需要追踪完整请求链路：用专门的 Trace 机制
如果是分布式追踪需求，不要靠业务日志扛，应该用：
SkyWalking / Zipkin：自动埋点追踪调用链
MDC + TraceId：在日志里注入 traceId 串联请求
专门的上报系统：把完整请求体单独上报，不混在业务日志里
3.4 异常场景：打印异常栈而不是对象
很多同学打异常日志时喜欢把相关对象也序列化进去：
// 反例 log.error("处理失败 dto:{}", JSONUtil.toJsonPrettyStr(dto), e); // 正例 log.error("处理失败 orderSeq:{}, deliveryStatus:{}", orderSeq, deliveryStatus, e);异常日志的核心是异常栈，对象信息打关键字段足矣。把大对象塞进异常日志，会让异常栈这种本该优先保证的信息被冲淡。
3.5 对象本身就该打日志：覆写一个精简的 toString()
如果某个 DTO 频繁出现在日志里，可以为它定制一个精简的toString()：
@Data public class Order { private Long id; private String orderSeq; private Integer orderStatus; private List<OrderPrescription> prescriptions; // 大字段 // ... 其他几十个字段 @Override public String toString() { return "Order{id=" + id + ", orderSeq=" + orderSeq + ", orderStatus=" + orderStatus + "}"; } }这样log.info("order:{}", order)既安全又有用。但要注意：不要在 toString() 里访问懒加载字段或调用有副作用的方法。
四、回到那个 36 秒的接口
最后回到开头的那个性能问题。syncDeliveryInfo接口里，V1 代码有这两行日志：
log.info("药品订单回调,参数:{}", JSONUtil.toJsonPrettyStr(dto)); log.info("处方信息:{}", prescriptionList);每次 HIS 回调都会执行，Dto 里包含整个物流请求体（含处方列表、地址信息等），单次序列化就可能耗时几十到上百毫秒。叠加 N+1 查询和事务内外部调用等问题，最终导致接口可能耗时 36~50 秒。
V2 优化时改成了：
log.info("syncOrderDeliveryInfoV2 开始 hosCode:{}, recipeSize:{}, deliveryStatus:{}", dto.getInput().getHosCode(), CollUtil.size(dto.getInput().getRecipeList()), dto.getInput().getDeliveryStatus());只取 3 个关键字段，彻底移除反射序列化开销。这只是 7 项优化中的一项，但单独这一项的收益就已经很明显。
五、总结
把全文核心观点浓缩成几条：
日志打印对象的真正开销不在
log.info这一行，而在传给它的字符串是怎么构造的。JSONUtil.toJsonPrettyStr(dto)作为方法参数，在调用log.info之前就已经完成了序列化，SLF4J 占位符救不了。直接
log.info("{}", dto)不等于"省掉了序列化"。它只是把序列化从 JSON 换成了toString()，而toString()的行为完全取决于 DTO 实现——可能是巨大的 Lombok 字符串，可能是无意义的类名+hash，最危险的是可能触发懒加载副作用。生产环境 INFO 日志只打关键字段，完整对象交给 DEBUG 级别 +
isDebugEnabled守卫，或者专门的 Trace 系统。判断一个日志写法是否有问题，看三点：序列化是否在
log.info之前发生、toString()是否有副作用、生成的字符串体积是否可控。性能问题往往藏在"不起眼"的地方。一行日志看起来无害，但在高频接口里乘以 QPS 就是实打实的开销。这次排查的 36 秒接口，日志只是其中一个因素，但积少成多。
性能优化的本质，很多时候就是"把不必要的开销去掉"。日志这件小事，值得每位 Java 开发者认真对待。
