【使用环境】
生产环境
【OB or 其他组件】
OceanBase CE / OBKV-HBase / SQL Audit / OCP 慢查询告警
【使用版本】
OceanBase_CE 4.4.2.1
集群部署形态：多 Zone 部署，业务通过 OBKV-HBase 方式访问 OceanBase。
【问题描述】
业务服务 SERVICE_A 在某次访问 OceanBase 时触发慢查询告警。
告警信息如下：
告警时间：2026-06-09 20:55:30
服务：SERVICE_A
指标：log_ob_query_cost
告警值：96ms
阈值：50ms
告警规则：30s 内 max(log_ob_query_cost) > 50ms
排查 SQL Audit 后发现，本次告警不是 SQL/OBKV 实际执行慢，也不是租户排队、磁盘 IO 或大扫描导致，而是少量请求的 get_plan_time 阶段出现偶发长尾。
需要说明的是：
1. 业务侧确认该请求为强一致性读。
2. 曾尝试将 weak_read_version_refresh_interval 从 100ms 调整为 50ms，但对该类尖刺无明显改善。
3. 因此目前不再判断为弱读版本刷新间隔导致。
4. 当前疑问是：强一致 OBKV-HBase 读请求中，为什么 trace 日志只看到 ob_weak_read_service.cpp 的 get_cluster_version，并且该阶段耗时会计入 SQL Audit 的 get_plan_time。
【复现路径】
本次问题不是稳定复现，而是在高频 OBKV-HBase 读请求中偶发出现 max RT 尖刺。
1. 查询告警窗口内业务请求总体情况
查询 20:55:00 ~ 20:56:00 这一分钟内，业务账号在 SQL Audit 中的总体情况。
SELECT
COUNT(*) AS cnt,
SUM(CASE WHEN elapsed_time / 1000 >= 50 THEN 1 ELSE 0 END) AS slow_50ms_cnt,
ROUND(MAX(elapsed_time) / 1000, 3) AS max_elapsed_ms,
ROUND(AVG(elapsed_time) / 1000, 3) AS avg_elapsed_ms,
ROUND(AVG(queue_time) / 1000, 3) AS avg_queue_ms,
ROUND(AVG(execute_time) / 1000, 3) AS avg_execute_ms,
ROUND(AVG(user_io_wait_time) / 1000, 3) AS avg_io_ms,
SUM(disk_reads) AS disk_reads
FROM oceanbase.GV$OB_SQL_AUDIT
WHERE tenant_name = 'TENANT_A'
AND db_name = 'DB_A'
AND user_name = 'USER_A'
AND is_inner_sql = 0
AND is_executor_rpc = 0
AND request_time >= time_to_usec('2026-06-09 20:55:00')
AND request_time < time_to_usec('2026-06-09 20:56:00');
查询结果如下：
总请求数：约 224732 次
超过 50ms：3 次
最大耗时：93.761ms
平均耗时：约 1.47ms
说明：
这一分钟内整体请求量较大，但只有 3 条请求超过 50ms，整体平均响应时间正常。
2. 按客户端和 Observer 聚合定位慢请求来源
SELECT
user_client_ip,
client_ip,
svr_ip,
COUNT(*) AS cnt,
SUM(CASE WHEN elapsed_time / 1000 >= 50 THEN 1 ELSE 0 END) AS slow_50ms_cnt,
ROUND(MAX(elapsed_time) / 1000, 3) AS max_elapsed_ms,
ROUND(AVG(elapsed_time) / 1000, 3) AS avg_elapsed_ms,
ROUND(MAX(get_plan_time) / 1000, 3) AS max_get_plan_ms,
ROUND(AVG(get_plan_time) / 1000, 3) AS avg_get_plan_ms,
ROUND(AVG(execute_time) / 1000, 3) AS avg_execute_ms,
ROUND(AVG(queue_time) / 1000, 3) AS avg_queue_ms,
ROUND(AVG(user_io_wait_time) / 1000, 3) AS avg_io_ms
FROM oceanbase.GV$OB_SQL_AUDIT
WHERE tenant_name = 'TENANT_A'
AND db_name = 'DB_A'
AND user_name = 'USER_A'
AND is_inner_sql = 0
AND is_executor_rpc = 0
AND request_time >= time_to_usec('2026-06-09 20:55:00')
AND request_time < time_to_usec('2026-06-09 20:56:00')
GROUP BY user_client_ip, client_ip, svr_ip
ORDER BY max_elapsed_ms DESC
LIMIT 20;
定位结果：
慢请求集中在：
客户端：CLIENT_A
Observer：OBSERVER_A
最大响应时间：93.761ms
慢请求数：3 条
说明：
本次尖刺不是所有客户端、所有 Observer 普遍变慢，而是集中在 CLIENT_A -> OBSERVER_A 这条访问路径上的少量请求。
3. 查看慢请求明细，确认耗时阶段
SELECT
usec_to_time(request_time) AS request_time,
user_client_ip,
svr_ip,
sql_id,
trace_id,
is_hit_plan,
plan_id,
plan_type,
ROUND(elapsed_time / 1000, 3) AS elapsed_ms,
ROUND(get_plan_time / 1000, 3) AS get_plan_ms,
ROUND(execute_time / 1000, 3) AS execute_ms,
ROUND(queue_time / 1000, 3) AS queue_ms,
ROUND(user_io_wait_time / 1000, 3) AS user_io_ms
FROM oceanbase.GV$OB_SQL_AUDIT
WHERE tenant_name = 'TENANT_A'
AND db_name = 'DB_A'
AND user_name = 'USER_A'
AND is_inner_sql = 0
AND is_executor_rpc = 0
AND user_client_ip = 'CLIENT_A'
AND svr_ip = 'OBSERVER_A'
AND request_time >= time_to_usec('2026-06-09 20:55:50')
AND request_time < time_to_usec('2026-06-09 20:55:52')
ORDER BY elapsed_time DESC
LIMIT 30;
慢请求结果：
request_time elapsed_ms get_plan_ms execute_ms queue_ms user_io_ms
2026-06-09 20:55:51.059137 93.761 93.411 0.164 0.155 0
2026-06-09 20:55:51.058977 93.581 93.322 0.204 0.024 0
2026-06-09 20:55:51.058825 92.611 92.368 0.186 0.024 0
可以看到：
elapsed_time 基本全部消耗在 get_plan_time 阶段。
execute_time 只有 0.1~0.2ms。
queue_time 很低。
user_io_wait_time = 0。
disk_reads = 0。
因此可以初步排除：
1. 数据库实际执行慢
2. 租户资源排队
3. 磁盘 IO 慢
4. 大扫描
4. 对比同 SQL_ID 下的正常请求
同一个 SQL_ID 下，大部分请求正常，正常请求耗时如下：
正常请求 elapsed_ms 约 2.5~2.8ms
正常请求 get_plan_ms 约 2.1~2.4ms
execute_ms 约 0.1~0.2ms
说明：
同一个 SQL_ID，大部分请求正常。
只有 3 条请求的 get_plan_time 从正常 2ms 左右突然升高到 92~93ms。
另外，慢请求和正常请求的字段均为：
is_hit_plan = 0
plan_id = 0
plan_type = 0
因此暂时没有直接归因为普通 Plan Cache 未命中，因为在该 OBKV-HBase 请求场景下这些字段看起来可能是常态。
5. 按秒确认尖刺集中在单条链路
SELECT
user_client_ip,
svr_ip,
COUNT(*) AS cnt,
SUM(CASE WHEN elapsed_time / 1000 >= 50 THEN 1 ELSE 0 END) AS slow_50ms_cnt,
ROUND(MAX(elapsed_time) / 1000, 3) AS max_elapsed_ms,
ROUND(MAX(get_plan_time) / 1000, 3) AS max_get_plan_ms,
ROUND(AVG(get_plan_time) / 1000, 3) AS avg_get_plan_ms,
ROUND(AVG(execute_time) / 1000, 3) AS avg_execute_ms
FROM oceanbase.GV$OB_SQL_AUDIT
WHERE tenant_name = 'TENANT_A'
AND db_name = 'DB_A'
AND user_name = 'USER_A'
AND sql_id = 'SQL_ID_A'
AND request_time >= time_to_usec('2026-06-09 20:55:51')
AND request_time < time_to_usec('2026-06-09 20:55:52')
GROUP BY user_client_ip, svr_ip
ORDER BY max_elapsed_ms DESC;
结果：
user_client_ip svr_ip cnt slow_50ms_cnt max_elapsed_ms max_get_plan_ms avg_get_plan_ms avg_execute_ms
CLIENT_A OBSERVER_A 433 3 93.761 93.411 2.480 0.167
CLIENT_B OBSERVER_B 24 0 0.359 0.096 0.068 0.155
说明：
20:55:51 这一秒内，CLIENT_A -> OBSERVER_A 共 433 次请求，其中只有 3 条慢。
同一秒其他链路没有类似异常。
因此本次尖刺属于局部少量请求长尾，不是整体性能问题。
6. 通过 trace_id 查询 Observer 日志
慢请求 trace_id 脱敏如下：
TRACE_SLOW_1
TRACE_SLOW_2
TRACE_SLOW_3
在对应 Observer OBSERVER_A 上查询日志：
grep 'TRACE_SLOW_1' observer.log*
grep 'TRACE_SLOW_2' observer.log*
grep 'TRACE_SLOW_3' observer.log*
慢请求日志中仅看到如下相关日志：
[2026-06-09 20:55:51.152703] INFO [STORAGE.TRANS] get_cluster_version
(ob_weak_read_service.cpp:123)
[TRACE_SLOW_1]
[WRS] get_cluster_version(ret=0, tenant_id=TENANT_ID_A, version={...})
慢请求 SQL Audit：
request_time = 2026-06-09 20:55:51.059137
get_plan_ms = 93.411ms
elapsed_ms = 93.761ms
时间差：
20:55:51.152703 - 20:55:51.059137 ≈ 93.566ms
该时间差与 SQL Audit 中的 get_plan_time = 93.411ms 基本一致。
7. 用正常请求日志做对比
正常请求 trace_id 脱敏如下：
TRACE_NORMAL_1
对应 SQL Audit：
request_time = 2026-06-09 20:55:51.038301
elapsed_ms = 2.829ms
get_plan_ms = 2.373ms
Observer 日志：
[2026-06-09 20:55:51.040918] INFO [STORAGE.TRANS] get_cluster_version
(ob_weak_read_service.cpp:123)
[TRACE_NORMAL_1]
[WRS] get_cluster_version(ret=0, tenant_id=TENANT_ID_A, version={...})
时间差：
20:55:51.040918 - 20:55:51.038301 ≈ 2.617ms
这与正常请求的 get_plan_time = 2.373ms 基本一致。
对比结论：
正常请求：get_cluster_version 阶段约 2~3ms
异常请求：get_cluster_version 阶段约 93ms
当前现象是：
SQL Audit 中的 get_plan_time 与 observer.log 中 get_cluster_version 的时间差基本一致。
8. 检查一致性读相关情况
业务侧确认该类请求为强一致性读。
同时曾检查弱读相关参数：
SHOW PARAMETERS LIKE '%weak%';
SHOW PARAMETERS LIKE '%weak_read%';
结果显示：
weak_read_version_refresh_interval = 100ms
enable_monotonic_weak_read = False
max_stale_time_for_weak_consistency = 5s
后续曾尝试将：
weak_read_version_refresh_interval: 100ms -> 50ms
但该类问题没有明显改善。
因此目前不再将根因归结为弱读刷新间隔，而是希望确认：
强一致性 OBKV-HBase 读请求中，get_cluster_version 出现偶发 90ms+ 长尾是否符合预期？
【附件及日志】
【备注】
当前排查结论如下：
2026-06-09 20:55 左右，业务服务 SERVICE_A 触发慢查询告警，告警值约 96ms。通过 OceanBase SQL Audit 排查发现，告警窗口内业务请求约 22.47 万次，仅 3 条超过 50ms，最大耗时约 93.761ms，整体平均响应时间正常。
慢请求集中在 CLIENT_A -> OBSERVER_A 链路上，对应 SQL_ID 为 SQL_ID_A。进一步拆分发现，慢请求耗时几乎全部集中在 get_plan_time 阶段，get_plan_time 约 92~93ms，而 execute_time 仅 0.1~0.2ms，queue_time、IO wait、disk_reads 均无异常。
结合 Observer 日志，慢请求 trace_id 对应 ob_weak_read_service.cpp 中的 get_cluster_version 日志。request_time 到 get_cluster_version 日志的时间差约 93.5ms，与 SQL Audit 中 get_plan_time 基本一致；正常请求该阶段仅约 2~3ms。
业务侧确认该类请求为强一致性读，且将 weak_read_version_refresh_interval 从 100ms 调整为 50ms 后对该类尖刺无明显改善。因此目前希望社区协助确认：强一致 OBKV-HBase 读请求中，get_cluster_version 阶段偶发 90ms+ 长尾的可能原因，以及后续应该如何继续定位。
希望社区协助确认以下问题：
1. OBKV-HBase 强一致读场景下，SQL Audit 的 get_plan_time 是否会包含 get_cluster_version 阶段耗时？
2. 强一致读请求为什么会进入 ob_weak_read_service.cpp 的 get_cluster_version 逻辑？
3. get_cluster_version 偶发 90ms+ 长尾可能由哪些因素导致？例如 GTS、schema/location、租户内部锁、版本服务、线程调度等。
4. weak_read_version_refresh_interval 调整为 50ms 无明显改善后，下一步应重点排查哪些指标或日志？
5. OceanBase CE 4.4.2.1 是否存在类似 OBKV-HBase 请求 get_plan_time 偶发长尾的已知问题或修复版本？