写在前面处方物流信息同步优化从 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 ListRecipeIdDTO recipeList; // 列表 }Lombok 生成的toString()会递归打印所有字段输出类似SyncDeliveryDTO(inputInput(hosCodeVM001, deliveryStatus1, recipeList[...]), recipeList[RecipeIdDTO(recipeId123456, ...), 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.SyncDeliveryDTO6a5fc7f7这确实很小、很快但完全没有任何业务信息。出问题排查时等于日志白打了反而误导排查方向。2.3 情况三toString() 触发副作用最危险这是最隐蔽的坑。如果 DTO 是 JPA/Hibernate 实体或者字段里有懒加载代理Entity Data public class Order { OneToMany(fetch FetchType.LAZY) private ListOrderPrescription prescriptions; }当你log.info(order:{}, order)时日志框架调用order.toString()Lombok 的ToString会调用prescriptions.toString()prescriptions是懒加载代理触发真正的 DB 查询一次日志打印悄悄执行了 N 条 SQL这种问题排查起来极其困难——你在业务代码里根本找不到那条 SQL 是哪里发出的因为它来自日志打印时触发的懒加载。类似的副作用还有循环引用A 持有 BB 持有 AtoString()递归调用导致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 ListOrderPrescription 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 里包含整个物流请求体含处方列表、地址信息等单次序列化就可能耗时几十到上百毫秒。叠加 N1 查询和事务内外部调用等问题最终导致接口可能耗时 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 开发者认真对待。
Java 日志打印：别再 log.info(“dto:{}“, dto) 了，可能比你想的更坑
写在前面处方物流信息同步优化从 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 ListRecipeIdDTO recipeList; // 列表 }Lombok 生成的toString()会递归打印所有字段输出类似SyncDeliveryDTO(inputInput(hosCodeVM001, deliveryStatus1, recipeList[...]), recipeList[RecipeIdDTO(recipeId123456, ...), 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.SyncDeliveryDTO6a5fc7f7这确实很小、很快但完全没有任何业务信息。出问题排查时等于日志白打了反而误导排查方向。2.3 情况三toString() 触发副作用最危险这是最隐蔽的坑。如果 DTO 是 JPA/Hibernate 实体或者字段里有懒加载代理Entity Data public class Order { OneToMany(fetch FetchType.LAZY) private ListOrderPrescription prescriptions; }当你log.info(order:{}, order)时日志框架调用order.toString()Lombok 的ToString会调用prescriptions.toString()prescriptions是懒加载代理触发真正的 DB 查询一次日志打印悄悄执行了 N 条 SQL这种问题排查起来极其困难——你在业务代码里根本找不到那条 SQL 是哪里发出的因为它来自日志打印时触发的懒加载。类似的副作用还有循环引用A 持有 BB 持有 AtoString()递归调用导致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 ListOrderPrescription 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 里包含整个物流请求体含处方列表、地址信息等单次序列化就可能耗时几十到上百毫秒。叠加 N1 查询和事务内外部调用等问题最终导致接口可能耗时 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 开发者认真对待。
