数据库、缓存、MQ 与 GC 性能链：端到端时间究竟花在哪里

数据库、缓存、MQ 与 GC 性能链高清原图

读取订单可以直接命中Redis，也可以在未命中后查询数据库、构造对象并回填缓存。订单变更还可能发布消息，等待另一个消费者处理。不同请求经过的组件和完成条件并不相同，性能分析需要先恢复这些调用关系。

JVM的分配与回收又横跨这些步骤。数据库返回十万行，可能既增加网络读取，也增加对象构造和GC；缓存减少了SQL访问后，JSON编码可能成为新的主要成本。把同一批请求经过的分支、返回数据量与各段耗时放在一起，才能解释整体变化。

一次业务工作经过哪些计时范围

同步调用与异步完成

订单读取的同步路径可以画成：

请求开始
├─ Redis GET
│  ├─ 命中：取得缓存值
│  └─ 未命中：等数据库连接 → SQL/结果读取 → 回填缓存
├─ 对象映射、序列化、响应发送
└─ 客户端读完

命中请求和未命中请求应分别统计。一个总体p99发生变化，可能来自单次SQL更慢，也可能只是未命中比例增加。缓存命中率之外，还需要保留各分支的请求数、有效结果和延迟分布。

写入与消息处理通常有更长的时间关系：

业务写入提交 → 发布消息 → Broker确认 → HTTP接纳响应
                              └─ 排队 → 投递 → 消费者提交结果 → ack

具体顺序由系统协议决定。例如事务发件箱会先把业务与待发送事件一同写入数据库，再由后台发布；HTTP响应未必等待Broker确认。无论采用哪种方式，都应分别记录请求响应时间、消息等待时间和最终业务完成时间。

Publisher confirm描述Broker对发布的确认，consumer acknowledgement描述消费方处理投递的确认，二者相互独立。消息已确认发布时，消费者可能尚未启动。RabbitMQ确认机制明确区分了这些时点。

墙钟时间沿依赖关系计算

串行且不重叠的区间可以相加。并行调用A花80ms、B花100ms，若同时开始并等待二者完成，这部分墙钟约为100ms再加协调成本，而不是180ms。

一个父Span通常包含子调用区间。父Span300ms、数据库子Span200ms、缓存子Span20ms，不能得出总耗时520ms。GC暂停也可能落在这些相同区间内；把GC耗时再加一遍，会再次重复计量。调用拓扑与Span关系可查 OpenTelemetry Traces概念。

分析时先选择完整请求或业务终态作为总区间，再将能够归属的子区间标到时间线上。剩余时间可能来自排队、编码、采集未覆盖的调用或采样缺失。跨机器时钟偏差会改变Span在图上的对齐，应结合父子关系和本机持续时间解释。

数据库、缓存、消息与回收的主要成本

数据库：执行计划只是其中一段

数据库访问包括获取连接、协议传输、解析与规划、执行、锁等待、结果发送和应用解码。慢查询列表通常只覆盖其中一部分，应用侧一次调用的耗时可能更长。

读取计划时先看输出行数与过滤比例，再看扫描、连接、排序和聚合策略。缺少合适索引可能扩大扫描范围；返回过多字段和行则增加网络、映射与内存成本；N+1访问会把本来可以批量完成的工作变成多次往返。添加索引还会增加写入与存储成本，需要结合读写负载验证。

PostgreSQL EXPLAIN 的cost是规划器估算单位，不能当毫秒。EXPLAIN ANALYZE会实际执行语句，输出实际行数、循环和执行时间；BUFFERS帮助观察共享缓冲访问。父计划节点还包含子节点成本，不能把整棵树的时间直接相加。用法与测量开销见 PostgreSQL EXPLAIN文档。

锁等待与计算成本要分开。一个按主键更新单行的语句，也可能被另一事务长时间持锁挡住；这时重新建索引通常解决不了等待。写路径还涉及WAL、提交和复制确认，性能调整必须保留所需的持久性与一致性语义。

缓存：命中、失效与回源

缓存命中消除了部分下游工作，但仍有网络往返、客户端排队、服务端命令执行和解码成本。大key、长时间命令、过期/淘汰活动、持久化与宿主调度都可能影响Redis响应；排查入口见 Redis延迟诊断。

命中率低时，先看哪些对象未命中以及为什么：新实例冷启动、工作集超过容量、TTL过短、随机访问或频繁主动失效，处理方法不同。热点key同时失效会让大量请求一起回源，可以按业务选择合并同key加载、预热、分散过期时间或对回源设置并发上限。

缓存失败后的“直接查数据库”也要计算总量。数据库原来只承担10%的请求，缓存整体不可用时可能突然接到十倍访问；降级路径需要单独压测和保护。

旧值的可接受时间属于数据契约。更新数据库后删除缓存是常见安排，但跨系统操作仍可能失败或与并发读取交错。严格一致性、版本校验与事件修复应在状态设计中处理，不能以“更快”替代正确结果。相关基础见从写入到一致状态。

消息：发布速率、积压与消费完成

消息系统把部分工作移到异步执行，并提供缓冲空间。发布确认很快，而消费者很慢时，积压仍会持续增长。应同时观察发布/确认、ready、unacknowledged、消费尝试、重投递和业务完成数，以及最老未完成消息的年龄。

prefetch控制未确认投递的数量。适当的prefetch减少消费者等待下一条消息的空闲时间，过大则可能把大量消息保留在消费者内存中，降低任务在消费者间重新分配的灵活性。RabbitMQ的per-consumer语义和组合限制见 Consumer Prefetch。

批量确认、批量发布与并发消费者会改变吞吐，也改变失败后的重放范围、顺序和内存需求。业务提交后ack可避免在工作尚未完成时确认，但提交成功、ack丢失仍可能导致重投递，需要幂等处理或去重。队列清空只是某个队列状态，业务结果还应从目标存储核对。

JVM：分配速度与存活对象

短命对象频繁分配，会增加分配带宽与回收工作；大批结果、反复复制缓冲区和重复构造JSON树都可能产生这种成本。长期缓存和积压任务则提高存活对象数量，影响老年代占用和回收空间。

GC不仅有暂停，也可能有并发阶段CPU消耗；应用线程等待资源和GC暂停是不同现象。调优要在吞吐、暂停目标与内存占用之间选择，并核对容器限额。收集器与权衡的概述见 Oracle GC调优指南。

看到GC与慢请求同一时间出现，可以提出相关性假设，但仍需要查看暂停区间、分配来源和请求是否真的受影响。CPU已经被并发GC占用时，扩大业务线程数可能进一步竞争CPU；只增加堆也可能延长其他回收阶段。先减少无用分配和保留，再在可比负载下评估参数变化。

运行真实缓存、锁与消息实验

准备隔离的三个服务

下载性能链实验包，解压进入 chain-lab。Linux与Docker/Compose环境下，使用有Docker权限的普通用户。版本固定为PostgreSQL18.6、Redis8.10.1、RabbitMQ4.3.5，Java源码兼容17，默认Temurin25运行；pgJDBC42.7.13、Lettuce7.5.2和RabbitMQ Java客户端5.33.0由pom.xml固定。

mkdir -p .m2 recordings
docker run --rm --user "$(id -u):$(id -g)" \
  -e HOME=/tmp -e MAVEN_CONFIG=/tmp/.m2 --entrypoint mvn \
  -v "$PWD:/lab" -v "$PWD/.m2:/cache" -w /lab \
  maven:3.9.12-eclipse-temurin-25 -B -ntp \
  -Dmaven.repo.local=/cache clean verify dependency:copy-dependencies
docker compose up -d --wait pg redis mq
docker compose run --rm lab

构建与运行都应退出0。数据库与消息服务没有宿主发布端口，口令仅供这个可删除实验；Java应用使用10001，Redis使用redis账号，PostgreSQL和RabbitMQ镜像的初始化入口可能以root准备目录，服务进程降权为各自账号。Maven显式使用宿主UID/GID和可写缓存。

服务启动失败时运行 docker compose ps 和对应 docker compose logs pg redis mq，先处理就绪、认证与资源问题。不可用的服务不属于下面预期的业务负例。Lettuce连接方式见 Redis官方Java客户端指南，RabbitMQ连接、Channel与确认操作见 Java客户端指南。

冷读、命中与旧缓存

程序先清除本实验key，读取订单1。第一次从数据库取得NEW并缓存，第二次读取相同key时检查数据库读取次数仍为1。输出中的cold/hot毫秒来自真实客户端调用，但单次运行不保证命中一定比冷读快；网络、首次连接和调度会影响短测量。

随后用两个真实数据库连接制造锁竞争：

-- 会话A：开始事务并锁住订单1
SELECT id FROM orders WHERE id=1 FOR UPDATE;
-- 会话B：限制等锁时间，再更新同一行
SET lock_timeout = '200ms';
UPDATE orders SET state='PAID' WHERE id=1;

会话A由程序关闭自动提交后开始事务。会话B应因锁等待返回SQLSTATE 55P03；程序只接受这个错误。A回滚释放锁后，B重新更新并提交成功。行锁与等待行为见 PostgreSQL显式锁文档。

数据库现在为PAID，缓存仍为NEW，下一次缓存读取会实际返回旧值。程序核对这一现象，然后删除本实验key，回源得到PAID，数据库读取计数增加为2：

row_lock_timeout SQLSTATE=55P03
committed_database=PAID cached_read=NEW
cache_invalidation_recovery=PAID db_reads=2

这是一个可控的顺序实验，用来观察锁等待与缓存分支；删除缓存没有与数据库更新形成原子事务，也没有覆盖并发失效竞态。生产设计需要按业务一致性要求补足这些情况。

Broker已确认，业务仍没有完成

程序声明一条仅供当前连接使用的临时队列，发布6条消息并等待Publisher Confirms，检查没有mandatory return且ready为6。此时还没启动消费者，数据库业务结果表为0。

消费者随后以 prefetch=1、手动ack启动。第一条投递到达后先等待闩锁，程序通过另一Channel查询Broker队列，观察到ready为5；消费回调的已投递计数为1。

publisher_confirmed=6 queue_ready=6 database_processed=0
held_consumer delivered=1 queue_ready=5 prefetch=1

释放闩锁后，每次消费先在PostgreSQL提交一行结果，再ack。所有消息处理结束后，程序检查队列ready为0、结果表行数为6，输出 consumer_recovery 并退出0。临时队列无持久化和副本保证，仅供这次隔离实验使用。

单独记录分配与GC

包内 AllocationLab真实创建8,192个64KiB字节数组，用32个槽保留最近一批对象，读取内容并校验总和。通过较小堆观察回收活动，避免把长录制引入其他服务实验：

docker run --rm --user "$(id -u):$(id -g)" --network none \
  -v "$PWD/target/classes:/lab:ro" -v "$PWD/recordings:/out" \
  eclipse-temurin:25.0.4_7-jdk java -Xms48m -Xmx48m \
  -XX:StartFlightRecording=filename=/out/allocation.jfr,settings=profile,dumponexit=true \
  -cp /lab AllocationLab
docker run --rm --user 10001:10001 --network none \
  -v "$PWD/recordings:/out:ro" eclipse-temurin:25.0.4_7-jdk \
  jfr summary /out/allocation.jfr

程序应打印 allocated_arrays=8192 retained_arrays=32 checksum=-4096，录制中应能找到 jdk.GarbageCollection及相关分配事件。继续查看实际事件：

docker run --rm --user 10001:10001 --network none \
  -v "$PWD/recordings:/out:ro" eclipse-temurin:25.0.4_7-jdk \
  jfr print --events jdk.GarbageCollection,jdk.ObjectAllocationSample /out/allocation.jfr

JFR事件是否存在取决于录制配置和实际运行；分配采样事件不是逐个对象的完整清单，不能把事件条数当成实际分配对象数。命令与事件过滤方式见 jfr官方手册。若录制为空或路径不可写，先修复采集，不根据程序分配字节数推断“必然发生了多少次GC”。

该录制只演示独立分配负载。它与前面Redis、SQL和MQ实验没有共同请求时间线，不能把这段GC耗时加到前面三个组件的调用耗时里。

Java17复验把构建镜像替换为 maven:3.9.12-eclipse-temurin-17，运行镜像替换为 eclipse-temurin:17.0.20_8-jdk；主程序使用 JDK_IMAGE=... docker compose run --rm lab。结束后执行：

docker compose down --remove-orphans --volumes

这个命令删除本组容器及其匿名卷，实验数据库、Redis和消息数据均可丢弃；源码、缓存和recordings保留。录制可能包含环境与线程信息，检查后再分享，不直接作为公开附件。

从局部异常回到业务完成时间

SQL已经变快，接口收益很小

对照相同请求类型的调用次数、返回行数和完整响应时间。SQL从100ms降到50ms后，如果响应编码仍需300ms，总时间改善有限；若优化改变了缓存命中率，两个版本可能经过了不同路径。

查看同一时间窗口内的数据库连接等待、对象分配与网络字节。下一步应针对新的主要成本，不继续追求已经很小的SQL片段。返回结果要逐字段保持一致，避免因少查数据获得表面的性能收益。

缓存命中率正常，仍出现长尾

先拆命中请求与未命中请求的长尾，再按key大小、命令、实例和流量热点分组。高命中率可能由大量小请求贡献，少数大对象仍然耗费主要带宽和解码时间。还要检查客户端事件循环是否被阻塞，以及Redis宿主是否受到CPU或持久化活动影响。

如果失效或故障把流量转向数据库，观察回源并发与数据库排队，优先限制突然放大的工作量。重试同一慢缓存请求也可能增加客户端队列，不能只关注服务端命中计数。

消息确认很快，但订单迟迟没有结果

沿发布确认、ready、未确认、消费重试和结果提交逐段核对。如果ready持续增长，消费能力不足或消费者未正常工作；ready很低而未确认很高，检查prefetch、消费者卡住的位置和数据库事务。

消费者日志里的“收到消息”对应投递时点，完成时间应以目标存储中的业务结果为准。恢复后继续跟踪最老消息年龄，直到旧积压排空；新消息处理速度恢复时，旧消息可能仍在等待。

GC频率增加，但原因尚不明确

比较单位业务工作分配字节、存活对象、堆使用与容器内存；再定位大结果映射、重复缓冲和队列保留。调整GC参数前固定数据规模和负载，避免将缓存冷启动或压测流量变化混进对照。

如果链路中多个资源同时繁忙，先降低输入或保护关键请求，保留必要的诊断数据。容量保护方法见限流、降级与容量保护，可比实验组织见基线、压测与性能回归。

权威资料与规范地址

• RabbitMQ发布与消费确认：https://www.rabbitmq.com/docs/confirms
• OpenTelemetry Traces：https://opentelemetry.io/docs/concepts/signals/traces/
• PostgreSQL EXPLAIN：https://www.postgresql.org/docs/18/using-explain.html
• Redis延迟诊断：https://redis.io/docs/latest/operate/oss_and_stack/management/optimization/latency/
• RabbitMQ Consumer Prefetch：https://www.rabbitmq.com/docs/consumer-prefetch
• Oracle GC调优概述：https://docs.oracle.com/en/java/javase/25/gctuning/introduction-garbage-collection-tuning.html
• Redis Lettuce客户端：https://redis.io/docs/latest/develop/clients/lettuce/
• RabbitMQ Java客户端：https://www.rabbitmq.com/client-libraries/java-api-guide
• PostgreSQL显式锁：https://www.postgresql.org/docs/18/explicit-locking.html
• JDK jfr命令：https://docs.oracle.com/en/java/javase/25/docs/specs/man/jfr.html