OSIV 导致持久化上下文无限增长 —— 一次长耗时同步任务的排查复盘一、现象一个长时间运行的同步任务单行处理耗时呈现单调递增的趋势阶段单行耗时趋势起步毫秒级中途持续上升无明显拐点后期秒级三个关键特征同一批次的耗时随批次序号递增不是偶发抖动是持续的单调恶化只有写入分支在变慢——只做读取判定的分支耗时自始至终保持在毫秒级几乎不变数据库侧所有指标正常没有慢查询没有锁等待没有资源饱和。二、排查过程第 1 轮怀疑索引缺失【数据库操作】SHOWINDEXFROMa;SHOWINDEXFROMb;SHOWINDEXFROMc;SHOWINDEXFROMd;结论索引都在基数正常不存在缺失。排除。第 2 轮怀疑优化器选错索引【数据库操作】EXPLAINSELECT...FROMaWHEREa.xx_id?ANDyy_idIN(?);EXPLAINSELECT*FROMbWHEREb.xx_id?;结论typerange、key命中预期索引、rows极小、Extra: Using index condition。执行计划是正确的。排除。第 3 轮怀疑写入路径 / 提交刷盘饱和【数据库操作】SHOWGLOBALSTATUSLIKEinnodb_log_waits;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_wait_free;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_pages_dirty;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_pages_free;SHOWGLOBALSTATUSLIKEInnodb_data_fsyncs;SHOWVARIABLESLIKEinnodb_flush_log_at_trx_commit;SHOWVARIABLESLIKEinnodb_log_file_size;SHOWVARIABLESLIKEinnodb_io_capacity%;SHOWVARIABLESLIKEinnodb_max_dirty_pages_pct%;SHOWVARIABLESLIKEinnodb_buffer_pool_size;结论innodb_log_waits 0自启动累计→ 从未等待过 redo 空间Innodb_buffer_pool_wait_free 0累计→ 从未等待过空闲页脏页数量远低于触发阈值缓冲池余量充足。写路径与刷盘不是瓶颈。排除。第 4 轮怀疑锁等待与长事务【数据库操作】SHOWENGINEINNODBSTATUS\G-- 重点看 TRANSACTIONS 段SELECTtrx_id,trx_state,trx_started,trx_mysql_thread_id,trx_rows_modifiedFROMinformation_schema.innodb_trxORDERBYtrx_started;SELECT*FROMperformance_schema.data_lock_waits;SHOWGLOBALSTATUSLIKEInnodb_row_lock%;结论History list length极低purge 完全追平没有任何长事务没有锁等待。排除。第 5 轮怀疑某条语句在慢【数据库操作】SELECTDIGEST_TEXT,COUNT_STAR,SUM_ROWS_EXAMINED,SUM_ROWS_AFFECTED,AVG_TIMER_WAIT,SUM_TIMER_WAITFROMperformance_schema.events_statements_summary_by_digestORDERBYSUM_TIMER_WAITDESCLIMIT15;结论榜上确实有几条长期高耗的语句但都属于别的业务同步自己的语句一条都没进榜。同时注意到一个方法论问题events_statements_summary_by_digest是自启动以来的累计值它说明的是这台库长期被什么拖累不能证明此刻正在发生什么。第 6 轮手工验证语句本身是否慢在库上手工执行 INSERT / UPDATE都不慢。结论这一条直接否掉了前面几轮写路径慢的假设也说明时间不在 SQL 语句本身。第 7 轮怀疑加解密写微基准测AESUtil.encrypt的单次成本当前实现每次调用都会Cipher.getInstanceinit并对比缓存Cipher后的成本。结论单次在微秒级按每行调用两次计算对单行耗时秒级的贡献是千分之一量级——数量级差了几十万倍。排除。顺带发现缓存Cipher能让这个调用快约 27 倍值得作为微优化做但注意Cipher非线程安全需用ThreadLocal。这与本次问题无关。第 8 轮转折点停止逐点验证改为直接观测线程到这一步逐个验证单点是否快的路线已经走完——每一个单独的操作都被证明是快的但整行就是慢的。必须换方法直接看线程停在哪里。【JVM 操作】第一步按端口定位 PID。同一台机器上跑着多个同 jar 的实例jps | grep分不出谁是谁必须按端口定位lsof-t-i:port-sTCP:LISTEN# 或ss-lptnsport :port|grep-oPpid\K[0-9]# 或netstat-tlnp|awk$4 ~ /:port$/ {split($7,a,/); print a[1]; exit}第二步采集。jstackpidjstack-i.txt# 线程栈多次采样间隔数秒top-H-ppid-b-n1# 线程级 CPU与 jstack 配套jstat-gcpid5s12# GC 曲线top-b-n1-ppid# 进程整体⚠️ 本次踩的坑jstat采集失败报Could not map vmid to user Name—— 脚本以普通用户执行而 Java 进程属于root。采集脚本必须以运行 Java 进程的同一用户或 root执行。本次因此没拿到 GC 数据靠top -H的线程级 CPU 顶上了。采集结果三个决定性观察进程 iowait 接近 0而 CPU 使用率很高→不是 IO 等待是纯计算。top -H显示几乎独占一整个核心的正是跑同步的那个线程用 TID 换算成十六进制与jstack里的nid对齐确认。多份线程栈里该线程停在完全相同的代码路径上AbstractEntityPersister.getPropertyValues / getPropertyValue DirtyHelper.isDirty DefaultFlushEntityEventListener.onFlushEntity AbstractFlushingEventListener.flushEntities AbstractFlushingEventListener.flushEverythingToExecutions SessionImpl.doFlush → flushBeforeTransactionCompletion → beforeTransactionCompletion JpaTransactionManager.doCommit → AbstractPlatformTransactionManager.commit $Proxy.save → 业务代码的 save 调用点三条合起来说明线程在 Hibernate 提交时遍历持久化上下文、逐个实体做脏检查纯 CPU 密集。第 9 轮确认前提读自动配置的实际条件读 Spring Boot 自动配置 jar 里JpaBaseConfiguration$JpaWebConfiguration的实际注解ConditionalOnMissingBean({ OpenEntityManagerInViewInterceptor.class, OpenEntityManagerInViewFilter.class }) ConditionalOnProperty(prefixspring.jpa, nameopen-in-view, havingValuetrue, matchIfMissingtrue)再确认项目配置里没有配spring.jpa.open-in-view→ 取默认值true。重要这条条件里没有WebMvcConfigurer。排查早期曾据项目自定义了WebMvcConfigurer自动配置会退避推断 OSIV 已关闭——这个推断是错的。它把后面若干轮排查全带偏到了数据库侧。三、根因3.1 两个概念PCPersistence Context持久化上下文EntityManager 管理的实体集合即 JPA 的一级缓存。事务提交时Hibernate 会遍历整个 PC逐个实体与加载时的快照比对有变化才生成 UPDATE——这就是脏检查。关键脏检查是遍历整张工作台。工作台越大每次提交前检查的时间越长。OSIVOpen Session In View把 EntityManager 的关闭时机从事务结束推迟到整个 HTTP 请求结束目的是让视图渲染阶段仍能触发懒加载。Spring Boot 默认开启启动时会打一条 WARN 提示。3.2 组合出来的问题正常情况无 OSIV 每行 save() → 新建 PC → 装入少量实体 → 提交前检查少量实体 → 关闭 PC 单行成本常数 OSIV 开启 长时间运行的 HTTP 请求 请求开始 → 建立 PC ─────────────────────────────────┐ │ 第 1 行 save() → PC 实体数增长 → 提交前遍历增长 │ PC 在整个请求 ... │ 周期内不释放 第 n 行 save() → 提交前遍历全部累积实体 │ │ 请求结束 → PC 释放 ───────────────────────────────────┘总成本 Σ(每次提交时 PC 内的实体数) O(n²)。这正好解释了全部观察观察解释单行耗时单调递增PC 随处理进度增长每次遍历越来越久只有写入分支慢只有写入会触发提交与脏检查只读判定分支不提交数据库所有指标正常瓶颈在 JVM 堆内与数据库无关iowait 为 0、CPU 满载纯内存对象比对手工执行 SQL 不慢手写 SQL 不经过 Hibernate没有 PC加密不是瓶颈微秒级量级差几十万倍四、修复4.1 立即止血重启 JVM中断任务执行。PC 绑定在请求线程上不结束请求就无法释放而该请求在 O(n²) 下只会越来越慢不可能自行跑完。4.2 根治spring:jpa:open-in-view:false当前项目不需要 OSIV它是 REST 接口服务返回 JSON不存在视图渲染阶段触发懒加载的场景——开着 OSIV 只承担代价拿不到任何好处。关闭前需评估懒加载波及面统计实体上的关联注解OneToMany/ManyToOne/OneToOne/ManyToMany与fetch FetchType.LAZY的使用点回归测试相关接口。4.3 配套长任务不要用阻塞 HTTP 触发改用异步任务 状态查询。这样即使配置有误PC 也不会绑定在长请求上。排查其他长请求 / 大批量接口OSIV 开启时所有 HTTP 请求的 PC 都是 request-scoped都有同样风险。4.4 验证指标预期top -H -p pid中同步线程的 %CPU大幅下降不再独占核心单行 / 单批耗时趋势平稳不随处理进度增长jstat -gc pid老年代占用不再持续上涨五、可复用的排查手段清单5.1 数据库侧目的操作索引是否存在、基数SHOW INDEX FROM 表执行计划EXPLAIN SELECT累计语句开销排行performance_schema.events_statements_summary_by_digest索引实际使用情况performance_schema.table_io_waits_summary_by_index_usage当前连接在做什么SHOW FULL PROCESSLISTredo / 刷盘是否饱和innodb_log_waits、Innodb_buffer_pool_wait_free、Innodb_data_fsyncs缓冲池与脏页Innodb_buffer_pool_pages_dirty/_free、innodb_buffer_pool_size长事务与 purge 滞后SHOW ENGINE INNODB STATUS\GHistory list length、information_schema.innodb_trx锁等待performance_schema.data_lock_waits、Innodb_row_lock_*逐条真实耗时开慢查询日志slow_query_log/long_query_time⚠️events_statements_summary_by_digest是自启动累计值能说明长期被什么拖累不能证明此刻正在发生什么。要定性必须做窗口化测量或看慢查询日志。5.2 JVM 侧目的操作按端口定位 PIDlsof -t -i:port -sTCP:LISTEN/ss -lptn/netstat -tlnp线程栈看卡在哪jstack pid多次采样看是否反复停在同一处线程级 CPUtop -H -p pid用 TID 换算十六进制与jstack的nid对齐GC 曲线jstat -gc pid 5s 12看YGC/YGCT/FGC/FGCT增量与OC/OU趋势进程整体 CPU / iowaittop -b -n 1 -p pid判读要点进程 iowait 接近 0 而 CPU 高→ 纯计算不要去数据库里找某个业务线程独占一个核心→ 用top -H的 TID 与jstack的nid对上直接看它的栈顶多次采样停在同一处→ 稳定瓶颈分散则可能是环境噪声栈顶是socketRead0/mysql包→ 确实在等数据库栈顶是 Hibernate/JPA 内部方法→ 在 JVM 里与数据库无关。5.3 采集脚本的注意事项必须以运行 Java 进程的同一用户或 root执行否则jstat/jstack会因权限失败本次jstat就因此没采到同一台机器多实例时必须按端口定位 PID不能靠进程名多个快照要配套采集线程栈 线程 CPU GC单独一份信息量有限日志若按端口分目录定位实例最快的方式是看哪个目录的日志还在更新。六、经验教训OSIV 对 REST 服务负担。Spring Boot 默认开启只为兼容视图渲染场景接口服务应显式关闭。长生命周期 每次全量遍历 O(n²)。不止 PC——任何随处理进度增长、又每次操作都要全量扫一遍的结构都有同样风险。先定位层次再定位原因。在数据库里找 JVM 的问题找多久都是空的。每个单点都快、整体却慢是明确信号瓶颈在调用之间的累积或在某个每次调用都做全量工作的隐藏环节。不要依赖对框架默认行为的记忆判断去读 jar 里的实际条件。本次一次错误的条件推断导致后续多轮排查方向性偏差。排查工具要能证明此刻不只是长期。累计型指标digest、自启动计数器很容易把人带偏。
OSIV 导致持久化上下文无限增长 —— 一次长耗时同步任务的排查复盘一、现象一个长时间运行的同步任务单行处理耗时呈现单调递增的趋势阶段单行耗时趋势起步毫秒级中途持续上升无明显拐点后期秒级三个关键特征同一批次的耗时随批次序号递增不是偶发抖动是持续的单调恶化只有写入分支在变慢——只做读取判定的分支耗时自始至终保持在毫秒级几乎不变数据库侧所有指标正常没有慢查询没有锁等待没有资源饱和。二、排查过程第 1 轮怀疑索引缺失【数据库操作】SHOWINDEXFROMa;SHOWINDEXFROMb;SHOWINDEXFROMc;SHOWINDEXFROMd;结论索引都在基数正常不存在缺失。排除。第 2 轮怀疑优化器选错索引【数据库操作】EXPLAINSELECT...FROMaWHEREa.xx_id?ANDyy_idIN(?);EXPLAINSELECT*FROMbWHEREb.xx_id?;结论typerange、key命中预期索引、rows极小、Extra: Using index condition。执行计划是正确的。排除。第 3 轮怀疑写入路径 / 提交刷盘饱和【数据库操作】SHOWGLOBALSTATUSLIKEinnodb_log_waits;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_wait_free;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_pages_dirty;SHOWGLOBALSTATUSLIKEInnodb_buffer_pool_pages_free;SHOWGLOBALSTATUSLIKEInnodb_data_fsyncs;SHOWVARIABLESLIKEinnodb_flush_log_at_trx_commit;SHOWVARIABLESLIKEinnodb_log_file_size;SHOWVARIABLESLIKEinnodb_io_capacity%;SHOWVARIABLESLIKEinnodb_max_dirty_pages_pct%;SHOWVARIABLESLIKEinnodb_buffer_pool_size;结论innodb_log_waits 0自启动累计→ 从未等待过 redo 空间Innodb_buffer_pool_wait_free 0累计→ 从未等待过空闲页脏页数量远低于触发阈值缓冲池余量充足。写路径与刷盘不是瓶颈。排除。第 4 轮怀疑锁等待与长事务【数据库操作】SHOWENGINEINNODBSTATUS\G-- 重点看 TRANSACTIONS 段SELECTtrx_id,trx_state,trx_started,trx_mysql_thread_id,trx_rows_modifiedFROMinformation_schema.innodb_trxORDERBYtrx_started;SELECT*FROMperformance_schema.data_lock_waits;SHOWGLOBALSTATUSLIKEInnodb_row_lock%;结论History list length极低purge 完全追平没有任何长事务没有锁等待。排除。第 5 轮怀疑某条语句在慢【数据库操作】SELECTDIGEST_TEXT,COUNT_STAR,SUM_ROWS_EXAMINED,SUM_ROWS_AFFECTED,AVG_TIMER_WAIT,SUM_TIMER_WAITFROMperformance_schema.events_statements_summary_by_digestORDERBYSUM_TIMER_WAITDESCLIMIT15;结论榜上确实有几条长期高耗的语句但都属于别的业务同步自己的语句一条都没进榜。同时注意到一个方法论问题events_statements_summary_by_digest是自启动以来的累计值它说明的是这台库长期被什么拖累不能证明此刻正在发生什么。第 6 轮手工验证语句本身是否慢在库上手工执行 INSERT / UPDATE都不慢。结论这一条直接否掉了前面几轮写路径慢的假设也说明时间不在 SQL 语句本身。第 7 轮怀疑加解密写微基准测AESUtil.encrypt的单次成本当前实现每次调用都会Cipher.getInstanceinit并对比缓存Cipher后的成本。结论单次在微秒级按每行调用两次计算对单行耗时秒级的贡献是千分之一量级——数量级差了几十万倍。排除。顺带发现缓存Cipher能让这个调用快约 27 倍值得作为微优化做但注意Cipher非线程安全需用ThreadLocal。这与本次问题无关。第 8 轮转折点停止逐点验证改为直接观测线程到这一步逐个验证单点是否快的路线已经走完——每一个单独的操作都被证明是快的但整行就是慢的。必须换方法直接看线程停在哪里。【JVM 操作】第一步按端口定位 PID。同一台机器上跑着多个同 jar 的实例jps | grep分不出谁是谁必须按端口定位lsof-t-i:port-sTCP:LISTEN# 或ss-lptnsport :port|grep-oPpid\K[0-9]# 或netstat-tlnp|awk$4 ~ /:port$/ {split($7,a,/); print a[1]; exit}第二步采集。jstackpidjstack-i.txt# 线程栈多次采样间隔数秒top-H-ppid-b-n1# 线程级 CPU与 jstack 配套jstat-gcpid5s12# GC 曲线top-b-n1-ppid# 进程整体⚠️ 本次踩的坑jstat采集失败报Could not map vmid to user Name—— 脚本以普通用户执行而 Java 进程属于root。采集脚本必须以运行 Java 进程的同一用户或 root执行。本次因此没拿到 GC 数据靠top -H的线程级 CPU 顶上了。采集结果三个决定性观察进程 iowait 接近 0而 CPU 使用率很高→不是 IO 等待是纯计算。top -H显示几乎独占一整个核心的正是跑同步的那个线程用 TID 换算成十六进制与jstack里的nid对齐确认。多份线程栈里该线程停在完全相同的代码路径上AbstractEntityPersister.getPropertyValues / getPropertyValue DirtyHelper.isDirty DefaultFlushEntityEventListener.onFlushEntity AbstractFlushingEventListener.flushEntities AbstractFlushingEventListener.flushEverythingToExecutions SessionImpl.doFlush → flushBeforeTransactionCompletion → beforeTransactionCompletion JpaTransactionManager.doCommit → AbstractPlatformTransactionManager.commit $Proxy.save → 业务代码的 save 调用点三条合起来说明线程在 Hibernate 提交时遍历持久化上下文、逐个实体做脏检查纯 CPU 密集。第 9 轮确认前提读自动配置的实际条件读 Spring Boot 自动配置 jar 里JpaBaseConfiguration$JpaWebConfiguration的实际注解ConditionalOnMissingBean({ OpenEntityManagerInViewInterceptor.class, OpenEntityManagerInViewFilter.class }) ConditionalOnProperty(prefixspring.jpa, nameopen-in-view, havingValuetrue, matchIfMissingtrue)再确认项目配置里没有配spring.jpa.open-in-view→ 取默认值true。重要这条条件里没有WebMvcConfigurer。排查早期曾据项目自定义了WebMvcConfigurer自动配置会退避推断 OSIV 已关闭——这个推断是错的。它把后面若干轮排查全带偏到了数据库侧。三、根因3.1 两个概念PCPersistence Context持久化上下文EntityManager 管理的实体集合即 JPA 的一级缓存。事务提交时Hibernate 会遍历整个 PC逐个实体与加载时的快照比对有变化才生成 UPDATE——这就是脏检查。关键脏检查是遍历整张工作台。工作台越大每次提交前检查的时间越长。OSIVOpen Session In View把 EntityManager 的关闭时机从事务结束推迟到整个 HTTP 请求结束目的是让视图渲染阶段仍能触发懒加载。Spring Boot 默认开启启动时会打一条 WARN 提示。3.2 组合出来的问题正常情况无 OSIV 每行 save() → 新建 PC → 装入少量实体 → 提交前检查少量实体 → 关闭 PC 单行成本常数 OSIV 开启 长时间运行的 HTTP 请求 请求开始 → 建立 PC ─────────────────────────────────┐ │ 第 1 行 save() → PC 实体数增长 → 提交前遍历增长 │ PC 在整个请求 ... │ 周期内不释放 第 n 行 save() → 提交前遍历全部累积实体 │ │ 请求结束 → PC 释放 ───────────────────────────────────┘总成本 Σ(每次提交时 PC 内的实体数) O(n²)。这正好解释了全部观察观察解释单行耗时单调递增PC 随处理进度增长每次遍历越来越久只有写入分支慢只有写入会触发提交与脏检查只读判定分支不提交数据库所有指标正常瓶颈在 JVM 堆内与数据库无关iowait 为 0、CPU 满载纯内存对象比对手工执行 SQL 不慢手写 SQL 不经过 Hibernate没有 PC加密不是瓶颈微秒级量级差几十万倍四、修复4.1 立即止血重启 JVM中断任务执行。PC 绑定在请求线程上不结束请求就无法释放而该请求在 O(n²) 下只会越来越慢不可能自行跑完。4.2 根治spring:jpa:open-in-view:false当前项目不需要 OSIV它是 REST 接口服务返回 JSON不存在视图渲染阶段触发懒加载的场景——开着 OSIV 只承担代价拿不到任何好处。关闭前需评估懒加载波及面统计实体上的关联注解OneToMany/ManyToOne/OneToOne/ManyToMany与fetch FetchType.LAZY的使用点回归测试相关接口。4.3 配套长任务不要用阻塞 HTTP 触发改用异步任务 状态查询。这样即使配置有误PC 也不会绑定在长请求上。排查其他长请求 / 大批量接口OSIV 开启时所有 HTTP 请求的 PC 都是 request-scoped都有同样风险。4.4 验证指标预期top -H -p pid中同步线程的 %CPU大幅下降不再独占核心单行 / 单批耗时趋势平稳不随处理进度增长jstat -gc pid老年代占用不再持续上涨五、可复用的排查手段清单5.1 数据库侧目的操作索引是否存在、基数SHOW INDEX FROM 表执行计划EXPLAIN SELECT累计语句开销排行performance_schema.events_statements_summary_by_digest索引实际使用情况performance_schema.table_io_waits_summary_by_index_usage当前连接在做什么SHOW FULL PROCESSLISTredo / 刷盘是否饱和innodb_log_waits、Innodb_buffer_pool_wait_free、Innodb_data_fsyncs缓冲池与脏页Innodb_buffer_pool_pages_dirty/_free、innodb_buffer_pool_size长事务与 purge 滞后SHOW ENGINE INNODB STATUS\GHistory list length、information_schema.innodb_trx锁等待performance_schema.data_lock_waits、Innodb_row_lock_*逐条真实耗时开慢查询日志slow_query_log/long_query_time⚠️events_statements_summary_by_digest是自启动累计值能说明长期被什么拖累不能证明此刻正在发生什么。要定性必须做窗口化测量或看慢查询日志。5.2 JVM 侧目的操作按端口定位 PIDlsof -t -i:port -sTCP:LISTEN/ss -lptn/netstat -tlnp线程栈看卡在哪jstack pid多次采样看是否反复停在同一处线程级 CPUtop -H -p pid用 TID 换算十六进制与jstack的nid对齐GC 曲线jstat -gc pid 5s 12看YGC/YGCT/FGC/FGCT增量与OC/OU趋势进程整体 CPU / iowaittop -b -n 1 -p pid判读要点进程 iowait 接近 0 而 CPU 高→ 纯计算不要去数据库里找某个业务线程独占一个核心→ 用top -H的 TID 与jstack的nid对上直接看它的栈顶多次采样停在同一处→ 稳定瓶颈分散则可能是环境噪声栈顶是socketRead0/mysql包→ 确实在等数据库栈顶是 Hibernate/JPA 内部方法→ 在 JVM 里与数据库无关。5.3 采集脚本的注意事项必须以运行 Java 进程的同一用户或 root执行否则jstat/jstack会因权限失败本次jstat就因此没采到同一台机器多实例时必须按端口定位 PID不能靠进程名多个快照要配套采集线程栈 线程 CPU GC单独一份信息量有限日志若按端口分目录定位实例最快的方式是看哪个目录的日志还在更新。六、经验教训OSIV 对 REST 服务负担。Spring Boot 默认开启只为兼容视图渲染场景接口服务应显式关闭。长生命周期 每次全量遍历 O(n²)。不止 PC——任何随处理进度增长、又每次操作都要全量扫一遍的结构都有同样风险。先定位层次再定位原因。在数据库里找 JVM 的问题找多久都是空的。每个单点都快、整体却慢是明确信号瓶颈在调用之间的累积或在某个每次调用都做全量工作的隐藏环节。不要依赖对框架默认行为的记忆判断去读 jar 里的实际条件。本次一次错误的条件推断导致后续多轮排查方向性偏差。排查工具要能证明此刻不只是长期。累计型指标digest、自启动计数器很容易把人带偏。
