压测下 RPC 接口大量失败排查记录
1. 背景及当前结论
2026-10-28，UAT 压测期间，midAboss-code 的 queryBatch 出现耗时上涨、成功率下降，queryByTypes 同期也变慢。
已确认直接失败原因：目标 code 实例的 RPC 服务端线程池繁忙，拒绝调用。最终根因尚未确认。 同期 GC 升高、老年代占用上涨，可能参与或加剧处理变慢，但不能直接判定内存泄漏，也不能把全部失败归因于 GC。
2. 第一路：从接口指标圈定异常窗口
| 时间 | 请求数 | 成功量 | 成功率 | 平均耗时 | 失败数 |
|---|---|---|---|---|---|
| 00:35 | 1320 | 1317 | 99.77% | 633.22 | 3 |
| 00:36 | 2479 | 1517 | 61.19% | 8791.68 | 962 |
| 00:37 | 2056 | 433 | 21.06% | 16057.15 | 1623 |
耗时单位需核实，若为毫秒则最后平均约 16 秒。请求数属于统计窗口内总量，不能直接当成并发数或 QPS。
耗时和失败率同步上升，优先沿处理变慢、请求积压、超时查。多个方法同时受影响，应关注共享线程池、缓存、数据库与 JVM。
向压测方核实：升压时间、并发量、每次批次条数、type 分布、超时时间、有无自动重试。
3. 第二路：对齐系统和 JVM 监控
时间对齐是前提
最初系统图覆盖约 00:33～15:09，短时异常被压缩。JVM 页面曾出现输入框时间与横轴不一致，不能据此判断故障窗口健康。
- 将窗口缩小到故障前后，例如 00:33～00:43。
- 点击回放或查询，确认横轴、悬浮时间确实更新。
- 选择日志中的目标实例，核对时区，避免应用平均值掩盖单实例异常。
对齐后看到的现象
- 约 00:35～00:42，Young GC 次数和耗时曲线明显升高，同时出现 Full GC 活动。
- 老年代占用从约 33% 上升到约 60%，随后到约 75%，之后仍保持较高水平。
- 宽时间范围的 CPU 图未显示持续打满，不能排除具体实例、具体分钟的异常。
- 系统内存约 53% 不能证明 JVM 堆没有压力。
YGCT、FGCT 的单位、统计周期及聚合口径待核实，不能把曲线值直接当作单次停顿秒数。老年代上涨不等于泄漏，需要 GC 回收效果及对象证据。
4. 第三路：用日志确认直接失败点
调用方日志中的关键异常：
InvokeServerBusyException: Server thread pool busy!| 项目 | 内容 |
|---|---|
| 时间 | 2026-10-28 00:37:59 |
| 调用方 | midaboss-document |
| 被调用方 | midaboss-code |
| 方法 | com.aliyun.fsi.insurance.dict.api.CodeRPCFacade.queryBatch |
| 协议 | bolt |
| 目标地址 | 10.197.136.170:13305 |
查到的是 document 日志，但繁忙的是目标 code 实例，后续应定位该 IP 对应实例。该日志只能证实这次调用被拒绝，不能直接代表所有实例或全部失败请求。
当前可能的过程：处理速度下降或压力超过容量，工作线程被占用、请求积压，最终拒绝新请求。线程为何占用过久仍需取证。
服务日志可搜索：
System exception
Business exception
timeout
RejectedExecution
Server thread pool busy保留完整异常、Caused by、traceId、时间和实例。请求在进入业务方法前被拒绝时，业务异常日志可能没有记录。
5. 第四路：结合代码定位处理变慢的原因
当前工作区调用链：
CodeRPCFacadeImpl.queryBatch
→ BasicCodeBatchQryExe.execute
→ BasicCodeGateway.queryCacheByType
→ 缓存命中返回；未命中查询数据库
→ 遍历该类型码表，匹配目标 code源码位置（仓库相对路径）：
- aboss-code-app/src/main/java/com/aliyun/fsi/insurance/code/app/impl/code/CodeRPCFacadeImpl.java
- aboss-code-app/src/main/java/com/aliyun/fsi/insurance/code/app/executor/code/query/BasicCodeBatchQryExe.java
- aboss-code-infrastructure/src/main/java/com/aliyun/fsi/insurance/code/infra/gateway/BasicCodeGatewayImpl.java
- aboss-code-infrastructure/src/main/java/com/aliyun/fsi/insurance/code/infra/config/RequestLogAspect.java
- aboss-code-app/src/main/java/com/aliyun/fsi/insurance/code/app/template/BaseOperateTemplate.java
代码确认的事实：
- queryBatch 逐条校验并串行处理批量入参，入口未见批次数量上限检查。
- 每条获取完整类型码表再遍历匹配；同批次重复 type 会重复调用缓存查询和遍历。
- 单参数 queryCacheByType 配置 @Cacheable，以 type 为 key；未命中时按 typeCode、isValid 查询并排序。
- 带 status 的方法获取类型码表后再过滤出状态列表。
- 请求日志开关开启且调用方信息有效时，按入参条目打印日志，可能放大日志量。
待验证方向：大批次和重复 type 放大读取、过滤及遍历；缓存慢或未命中增加；数据库或连接池等待；对象分配及积压提高 GC 压力；日志输出阻塞。
缓存介质、序列化行为、命中率、部署版本是否与当前代码一致均需核实。以上只是线索，不能直接作为根因。
6. 下一步取证顺序
先看目标实例线程池
查看 10.197.136.170 对应实例在 00:34～00:40 的 RPC 活跃线程、线程上限、队列长度、队列上限和拒绝数；对比其他实例判断流量是否集中。没有现成指标时，从运行日志和运行时配置补证，不假设默认值。
故障仍在发生时取线程快照
间隔 5～10 秒取 3 次，观察 RPC 工作线程反复停留的位置。
| 主要停留位置 | 后续核查 |
|---|---|
| 数据库连接获取 | 连接池活跃数、等待数、慢 SQL |
| 数据库网络读取 | SQL 耗时、数据库负载、网络 |
| 缓存调用或连接获取 | 缓存耗时、连接池、命中率 |
| 锁等待 | 持锁线程及其调用栈 |
| 日志写入 | 日志量、输出阻塞、磁盘 |
| 码表遍历或转换 | 批次大小、类型数据量、CPU、对象分配 |
故障结束后新取的线程快照不能代表历史状态；缺少历史快照时结合历史 trace，或在可控复测中采集。
用 GC 日志核实影响
取同实例 00:34～00:43 的 GC 日志，核实收集器、触发原因、单次暂停、累计暂停、回收前后堆占用，与接口异常对齐。若回收后仍有大量存活对象，再评估对象统计或堆分析的必要性及采集开销。
用慢调用链验证下游
找一条慢 queryBatch 的完整 trace，核对缓存、SQL、连接等待耗时及调用次数，结合真实批次参数验证重复工作。
7. 处置与验证原则
- 压测仍持续时，可协调降低一档压力，观察拒绝、耗时、队列和 GC 是否一起回落。
- 不仅凭线程池繁忙就调大线程池：下游已慢时，更多线程可能增加积压和内存压力。
- 不仅凭老年代高占用就调大堆，也不凭 Full GC 曲线直接判断泄漏。
- 根据证据选择批次上限、同批次类型去重、减少重复读取过滤、缓存或 SQL 优化。
- 每次只改变明确变量，以相同压测参数对比成功率、吞吐、延迟、拒绝数及 GC，保留前后数据。
8. 当前排查状态
已证实： 目标实例发生 RPC 线程池拒绝；故障窗口同期 GC 活动明显、老年代上涨。
未证实： 工作线程占用过久的首要原因、GC 的具体贡献、缓存或数据库瓶颈、单实例压力不均、其他失败是否同因。
优先补证： 目标实例线程池指标、故障期线程快照、GC 日志、慢调用 trace，以及压测批次和并发参数。
线程池机制、业务异步池与 RPC 池的区别及本地复现实验，见 Java/工作实践/线程池使用与排查。