背景：
本来该篇我起名《OB中队列等待导致业务体验效率变慢》，今天发现是我分析问题的时候分析偏了，问题根因还是锁等待。（自我反省中）
业务反馈某时间段sql效率有问题，这个问题还一直出现。
--业务系统体验较平时要慢（10:30-11:30）,发下有条如下简单update操作在OCP采集在慢SQL里了，帮查下系统原因，是不是整体负载有问题还是其它
--如下一个简单的update操作正常更新应该耗时300MS左右，执行计划如下应该是没问题（租户：xxxxx 库：xxxxx）
--但今天OCP采集到实际执行时间平均达到：6132.02MS，最大19238.79MS排查过程：
可以看到ocp上这段时间的qps/sql数量/以及等待都比较高，与业务确认这个量是正常的。
通过ocp的sql诊断找到业务说的这个update，发现采样历史的重试次数最少是两次，多的是四次。
检查gv$plan_cache_plan_stat该sql的历史执行情况，可以看到响应时间与执行时间有比较大的出入。
去gv$sql_audit找一条该sql的执行信息
MySQL [oceanbase]> select * from gv$sql_audit where sql_id='64A27C00B8392D2A3B741AB01633BDC1' limit 1\G
*************************** 1. row ***************************
SVR_IP: xx.xx.x1x.xx
SVR_PORT: 2882
REQUEST_ID: 1356854236
SQL_EXEC_ID: 1801169283
TRACE_ID: YB420AAC934F-000609929BB97E22-0-0
SID: 3234037378
CLIENT_IP: 1x.xx.xx2.xx
CLIENT_PORT: 25142
TENANT_ID: 1002
TENANT_NAME: xxxxxxx
EFFECTIVE_TENANT_ID: 1002
USER_ID: 1101710651032554
USER_NAME: xxxxxr
USER_GROUP: 0
USER_CLIENT_IP: xx.xx.xx6.xx
DB_ID: 1101710651032603
DB_NAME: xxxxxxxxx
SQL_ID: 64A27C00B8392D2A3B741AB01633BDC1
QUERY_SQL: UPDATE xxxxxxx SET xxxxxxe='2024-01-10 12:08:13.553',update_time='2024-01-10 12:08:13.553',xxxx=xxxxxx,xxxxx='xxxx'
WHERE (xxx_id = xxxxxx AND xxxx = 0 AND xxxxx = 15)
PLAN_ID: 177990
AFFECTED_ROWS: 1
RETURN_ROWS: 0
PARTITION_CNT: 1
RET_CODE: 0
QC_ID: 0
DFO_ID: 0
SQC_ID: 0
WORKER_ID: 0
EVENT: system internal wait
P1TEXT:
P1: 0
P2TEXT:
P2: 0
P3TEXT:
P3: 0
LEVEL: 0
WAIT_CLASS_ID: 100
WAIT_CLASS#: 0
WAIT_CLASS: OTHER
STATE: MAX_WAIT TIME ZERO
WAIT_TIME_MICRO: 0
TOTAL_WAIT_TIME_MICRO: 0
TOTAL_WAITS: 0
RPC_COUNT: 1
PLAN_TYPE: 1
IS_INNER_SQL: 0
IS_EXECUTOR_RPC: 0
IS_HIT_PLAN: 1
REQUEST_TIME: 1704859693809738
ELAPSED_TIME: 5048448
NET_TIME: 0
NET_WAIT_TIME: 0
QUEUE_TIME: 74
DECODE_TIME: 3
GET_PLAN_TIME: 395
EXECUTE_TIME: 3563
APPLICATION_WAIT_TIME: 0
CONCURRENCY_WAIT_TIME: 0
USER_IO_WAIT_TIME: 0
SCHEDULE_TIME: 0
ROW_CACHE_HIT: 0
BLOOM_FILTER_CACHE_HIT: 0
BLOCK_CACHE_HIT: 3
BLOCK_INDEX_CACHE_HIT: 3
DISK_READS: 0
RETRY_CNT: 2
TABLE_SCAN: 0
CONSISTENCY_LEVEL: 3
MEMSTORE_READ_ROW_COUNT: 2
SSSTORE_READ_ROW_COUNT: 3
REQUEST_MEMORY_USED: 2096128
EXPECTED_WORKER_COUNT: 0
USED_WORKER_COUNT: 0
SCHED_INFO: NULL
FUSE_ROW_CACHE_HIT: 0
PS_CLIENT_STMT_ID: -1
PS_INNER_STMT_ID: -1
TRANSACTION_HASH: 12033303829514409265
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 5163519357113747784
LOCK_FOR_READ_TIME: 0
WAIT_TRX_MIGRATE_TIME: 0
PARAMS_VALUE:可以看到ELAPSED TIME: 5048448，总响应时间到了5s，但是EXECUTE TIME: 3563，执行时间只有3ms，而且其他的wait以及队列时间都显示很短，唯一可疑的点在重试了2次，因为该sql不是绑定变量的形式，可以看到所有变量信息，通过query_sql(sql文本)以及TRACE_ID的维度在 gv$sql_audit视图做一个统计，确认排除了两个情况：
1.排除了是更新同一笔数据产生锁冲突造成的锁重试 ----这里开始判断就出错了
2.排除了批量场景导致ELAPSED TIME累加的情况
那么现在就有点遇到瓶颈了，根据TRACE_ID去看下server日志，看下详细信息。
这里就看到问题了，sql_audit里显示 QUEUE_TIME: 74只有74us，但是in_queue_time:3161135，日志里显示队列时间达到了3s，与原厂工程师咨询，sql_audit会有统计不准的情况。
token_cnt: //调度器分配的 Token 数，一个 Token 会转换为一个工作线程
actives://活跃工作线程数，一般和 Workers 相等，它们的差包含：租户工作线程缓存+带工作线程的大请求缓存
####上次分析到这里的时候我在几乎重合的时间看到队列等待的active线程满的日志，误以为是队列等到导致的重试和效率降低###
后续因为该租户线程使用率很低，虽然有好多sql的执行次数突刺，但是ocp监控上租户线程使用率峰值未超过8%，疑点重重。
今天又抓了一下这个业务语句
TRACE_ID: YB420AAC9350-000609980A7B61B9-0-0
QUERY_SQL: UPDATE ZZZZRRRRYYYY SET ENDTIME='2024-01-12 10:05:28.983',UPTIME='2024-01-12 10:05:28.983',IIIIIID=5555555555,XXXXXX='XXXXXX'
WHERE (CCCCCCC_id = 77777777777777777777 AND DDDDD = 0 AND EWRER = 22)
REQUEST_TIME: 1705025129014689
usec_to_time(t.REQUEST_TIME): 2024-01-12 10:05:29.014689
ELAPSED_TIME: 3450836
RETRY_CNT: 2
NET_TIME: 0
NET_WAIT_TIME: 0
QUEUE_TIME: 46
DECODE_TIME: 1
GET_PLAN_TIME: 396
EXECUTE_TIME: 3594
通过trace_id在找下server日志
看到被hash：9705346166372946539的事务阻塞了，查下这个事务
MySQL [oceanbase]> select query_Sql,usec_to_time(REQUEST_TIME) from gv$sql_audit where TRANSACTION_HASH=9705346166372946539 order by REQUEST_TIME
| SELECT xxxxxxxxxxxxxxxx | 2024-01-12 10:05:28.860367 |
| SELECT xxxxxxxxxxxxxxx | 2024-01-12 10:05:28.879299 |
| UPDATE ZZZZRRRRYYYY SET xxxxg=1,UPTIME='2024-01-12 10:05:28.956',IIIIIID=5555555555,XXXXXX='XXXXXX'
WHERE (CCCCCCC_id = 77777777777777777777 AND DDDDD = 0) | 2024-01-12 10:05:28.973385 |
| SELECT xxxxxxxxxxxxxxxxxxxxxxxxxxx | 2024-01-12 10:05:28.994819 |
| SELECT xxxxxxxxxxxxxxxxxxxxxx | 2024-01-12 10:05:29.003701 |
| SELECT xxxxxxxxxxxxxxxxxx | 2024-01-12 10:05:29.149893 |
| insert into ZZZZRRRRYYYY xxxxxxxxx x | 2024-01-12 10:05:29.168859 |
| commit | 2024-01-12 10:05:32.458785 |发现这个事务里对该表的update操作，看下条件该事务中的sql更新的数据包含效率下降的业务语句的数据，从时间点可以看到，该事务2024-01-12 10:05:28.973385发起，持有该行数据的行锁，2024-01-12 10:05:32.458785事务才commit释放锁，而效率下降的update是2024-01-12 10:05:29.014689发起，ELAPSED_TIME有3s，与该时间匹配，能确定是该事务阻塞了这个update。这个事务还有一个问题，最后一条insert之后等待了约3s才去commit，该业务逻辑和问题需要业务去整改了。
结论：
这个问题很羞愧，分析过程不严谨导致分析偏差耽误了不少时间，引以为戒。
行之所向，莫问远方。
