背景:
作为dba在日常工作中肯定经常遇到两个场景
- 业务找过来说表上有锁,阻塞业务了,帮杀下,或者看下
- 业务反馈有个程序平时几秒就完了,结果出现跑了好几分钟的情况
其实第二种场景排除执行计划突变和数据量突变的情况,大部分也是锁导致的。
那么这两个问题都是怎么排查锁,只不过是当前的锁,和历史的锁。
那么我用一个实验来展示这两个场景怎么分析。
先介绍下我使用的环境版本为
observer (OceanBase 4.3.0.1) REVISION: 101000062024032200-b59432e535c48e8b8828190c803b6c7736413ff9 BUILD_BRANCH: HEAD BUILD_TIME: Mar 22 2024 00:52:21 BUILD_FLAGS: RelWithDebInfo BUILD_INFO: |
实验场景:
1.第一个场景:当前正在锁的表
我们先开启一个事务,然后更新一行数据,但是不提交。
然后我们模仿程序,通过java代码去调用sql,更新同一条数据。
我们可以看到程序现在是卡死的状态。这时候我们就可以去库里去查下了。
MySQL [oceanbase]> select * from __all_virtual_processlist where TENANT='htap' and user_client_ip<>'127.0.0.1';
+------------+------+--------+--------------------+------+---------+--------+------+-------+------+--------------+----------+----------+---------------------+---------------+----------------+-----------+----------+-----------+------------+----------+-------------+------------+-----------+------------+--------+--------+-------------+-----------+---------+-----------+---------------------+-------+-------------------+-----------------------+--------+--------+----------+----------+-----------+------------------+------------+--------------+
| id | user | tenant | host | db | command | sql_id | time | state | info | svr_ip | svr_port | sql_port | proxy_sessid | master_sessid | user_client_ip | user_host | trans_id | thread_id | ssl_cipher | trace_id | trans_state | total_time | retry_cnt | retry_info | action | module | client_info | sql_trace | plan_id | tenant_id | effective_tenant_id | level | sample_percentage | record_policy | lb_vid | lb_vip | lb_vport | in_bytes | out_bytes | user_client_port | proxy_user | service_name |
+------------+------+--------+--------------------+------+---------+--------+------+-------+------+--------------+----------+----------+---------------------+---------------+----------------+-----------+----------+-----------+------------+----------+-------------+------------+-----------+------------+--------+--------+-------------+-----------+---------+-----------+---------------------+-------+-------------------+-----------------------+--------+--------+----------+----------+-----------+------------------+------------+--------------+
| 3221643380 | SYS | htap | 134.90.8.212:39832 | SYS | Sleep | | 24 | SLEEP | NULL | 134.90.8.212 | 2882 | 2881 | 9681060055801331737 | NULL | 134.90.8.212 | % | 3917058 | 0 | NULL | NULL | ACTIVE | 24 | 0 | 0 | | | | 1 | 3036 | 1002 | 1002 | 1 | 10 | SAMPLE_AND_SLOW_QUERY | NULL | NULL | NULL | 663 | 13527 | 59424 | NULL | NULL |
| 3221704604 | SYS | htap | 134.90.8.212:43442 | SYS | Sleep | | 5 | SLEEP | NULL | 134.90.8.212 | 2882 | 2881 | 9681060055801331738 | NULL | 134.90.8.9 | % | 0 | 0 | NULL | NULL | | 5 | 6 | -6005 | | | | 1 | 3037 | 1002 | 1002 | 1 | 10 | SAMPLE_AND_SLOW_QUERY | NULL | NULL | NULL | 1078 | 11179 | 42302 | NULL | NULL |
| 3222051655 | SYS | htap | 134.90.8.212:38844 | SYS | Sleep | | 969 | SLEEP | NULL | 134.90.8.216 | 2882 | 2881 | 9681060055801331737 | NULL | 134.90.8.212 | % | 0 | 0 | NULL | NULL | | 969 | 0 | 0 | | | | 1 | 322 | 1002 | 1002 | 1 | 10 | SAMPLE_AND_SLOW_QUERY | NULL | NULL | NULL | 638 | 8569 | 59424 | NULL | NULL |
+------------+------+--------+--------------------+------+---------+--------+------+-------+------+--------------+----------+----------+---------------------+---------------+----------------+-----------+----------+-----------+------------+----------+-------------+------------+-----------+------------+--------+--------+-------------+-----------+---------+-----------+---------------------+-------+-------------------+-----------------------+--------+--------+----------+----------+-----------+------------------+------------+--------------+
3 rows in set (0.02 sec)
其实通过__all_virtual_processlist我们就可以看到持有锁的会话,以及被锁的会话,可以看到第二个session的retry_info有6005获取锁失败的报错,那他就是被阻塞的会话,第一个active的就是持有锁,阻塞别人的会话,只要第一个会话回滚或者提交,释放掉锁,第二个会话就可以获取到锁,因为我这是测试环境会话比较少比较好看,那么实际生产可能不那么好看,那么就再介绍下别的方式。
小场景(1)业务反馈有积压,程序跑不动卡住了,但是不确定是卡在哪些表上了
那么可以通过以下的sql查询持有锁的所有会话,以及表名。我们可以拿着这些表找业务确认他们的程序涉及哪几个表,对应的处理下就可以了。(ps:如果涉及杀会话的话,要确认好持有锁的会话杀掉会不会影响业务),下面sql可以理解为查询持有锁的会话和表。
MySQL [oceanbase]> select a.tenant_id,a.svr_ip,a.ls_id,a.table_id,c.table_id table_actual_id,c.table_name,a.tablet_id,a.session_id,a.ctx_create_time
-> from __all_virtual_trans_lock_stat a
-> left join __all_virtual_tablet_to_ls b on b.tablet_id=a.tablet_id
-> left join __all_virtual_table c on b.table_id=c.table_id;
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
| tenant_id | svr_ip | ls_id | table_id | table_actual_id | table_name | tablet_id | session_id | ctx_create_time |
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
| 1002 | 169.78.3.112 | 1001 | 0 | 500008 | ZRY2 | 200010 | 3221643380 | 2024-04-12 10:32:52.880125 |
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
1 row in set (0.09 sec)
小场景(2)业务反馈涉及某个表的程序卡住了
那么我们就针对这个表查下有没有锁就可以了,查询语句如下。该sql是根据表名查询持有锁的会话。
MySQL [oceanbase]> select * from (select a.tenant_id,a.svr_ip,a.ls_id,a.table_id,c.table_id table_actual_id,c.table_name,a.tablet_id,a.session_id,a.ctx_create_time
-> from __all_virtual_trans_lock_stat a
-> left join __all_virtual_tablet_to_ls b on b.tablet_id=a.tablet_id
-> left join __all_virtual_table c on b.table_id=c.table_id) t where t.table_name like '%ZRY2%';
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
| tenant_id | svr_ip | ls_id | table_id | table_actual_id | table_name | tablet_id | session_id | ctx_create_time |
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
| 1002 | 169.78.3.112 | 1001 | 0 | 500008 | ZRY2 | 200010 | 3221643380 | 2024-04-12 10:32:52.880125 |
+-----------+--------------+-------+----------+-----------------+------------+-----------+------------+----------------------------+
1 row in set (0.05 sec)
小场景(3)有时候可能多个程序逻辑会相互冲突,某个业务发现自己的程序被卡住了,但是他的业务逻辑可以手动调整,那他可能想先终止该会话先去走其他流程。
那么如下sql可以查询到被锁,或者说等待持有锁的会话。
MySQL [oceanbase]> select a.tenant_id,a.svr_ip,c.table_id table_actual_id,c.table_name,a.tablet_id,a.session_id,a.block_session_id,a.trans_id,a.holder_trans_id,a.lock_mode,a.`type`
-> from __all_virtual_lock_wait_stat a
-> left join __all_virtual_tablet_to_ls b on b.tablet_id=a.tablet_id
-> left join __all_virtual_table c on b.table_id=c.table_id;
+-----------+--------------+-----------------+------------+-----------+------------+------------------+----------+-----------------+-----------+------+
| tenant_id | svr_ip | table_actual_id | table_name | tablet_id | session_id | block_session_id | trans_id | holder_trans_id | lock_mode | type |
+-----------+--------------+-----------------+------------+-----------+------------+------------------+----------+-----------------+-----------+------+
| 1002 | 169.78.3.112 | 500008 | ZRY2 | 200010 | 3221704604 | 3221704604 | 3917301 | 3917058 | X | 1 |
+-----------+--------------+-----------------+------------+-----------+------------+------------------+----------+-----------------+-----------+------+
1 row in set (0.02 sec)
2.第二个场景:历史被锁的信息
dba经常遇到该场景,就是业务反馈有个程序平时几秒就完了,结果出现跑了好几分钟的情况,然后让帮查查怎么回事,一般我们确认是锁冲突导致的,那么会建议他们修改业务逻辑,但是有时候业务也不清楚更另外的哪个业务冲突了,那么我们如果能找到当时锁住他的业务模型,那么就方便业务去定位修改了。
那么我们先把刚才实验的第一个update提交一下。
可以看到java程序也就获取到锁,执行结束了,因为java程序是我直接从官网案例里拿过来改了下sql,getString报错不影响我的目的。
可以确认下数据,java程序是修改成功了。
首先在生产等环境sqlaudit是刷的比较快的,很多时候要分析的话,要保留相应的aqlaudit,那么可以等场景复现时关闭下audit,保留下信息。
MySQL [oceanbase]> alter system set enable_sql_audit='False';
Query OK, 0 rows affected (0.07 sec)
然后我们可以通过业务提供或者业务日志里的sql语句去查下sql_audit信息。
MySQL [oceanbase]> select * from gv$ob_sql_audit where query_sql='update zry2 set b=\'javacs\' where a=985 and c=164;' \G
*************************** 1. row ***************************
SVR_IP: 169.78.3.112
SVR_PORT: 2882
REQUEST_ID: 12119440
SQL_EXEC_ID: 52294148
TRACE_ID: YB42865A08D4-0006157C0336EBEA-0-0
SID: 3221704604
CLIENT_IP: 169.78.3.112
CLIENT_PORT: 43442
TENANT_ID: 1002
TENANT_NAME: htap
EFFECTIVE_TENANT_ID: 1002
USER_ID: 200003
USER_NAME: SYS
USER_GROUP: 0
USER_CLIENT_IP: 169.78.16.6
DB_ID: 201006
DB_NAME: SYS
SQL_ID: 3E393CA2244E2C49F354EA1DE7874597
QUERY_SQL: update zry2 set b='javacs' where a=985 and c=164;
PLAN_ID: 3037
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:
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: 2
PLAN_TYPE: 1
IS_INNER_SQL: 0
IS_EXECUTOR_RPC: 0
IS_HIT_PLAN: 1
REQUEST_TIME: 1712889179734177
ELAPSED_TIME: 94830642
NET_TIME: 0
NET_WAIT_TIME: 4
QUEUE_TIME: 2467
DECODE_TIME: 3
GET_PLAN_TIME: 1698
EXECUTE_TIME: 160381
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: 243
DISK_READS: 0
RETRY_CNT: 30
TABLE_SCAN: 1
CONSISTENCY_LEVEL: 3
MEMSTORE_READ_ROW_COUNT: 2
SSSTORE_READ_ROW_COUNT: 3
DATA_BLOCK_READ_CNT: 0
DATA_BLOCK_CACHE_HIT: 212
INDEX_BLOCK_READ_CNT: 0
INDEX_BLOCK_CACHE_HIT: 31
BLOCKSCAN_BLOCK_CNT: 422
BLOCKSCAN_ROW_CNT: 999999
PUSHDOWN_STORAGE_FILTER_ROW_CNT: 0
REQUEST_MEMORY_USED: 1614992
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
TX_ID: 3917415
SNAPSHOT_VERSION: 1712889274559945492
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 5849233527757913110
LOCK_FOR_READ_TIME: 0
PARAMS_VALUE:
RULE_NAME:
PARTITION_HIT: 1
TX_INTERNAL_ROUTING: 0
TX_STATE_VERSION: 0
FLT_TRACE_ID:
PL_TRACE_ID: NULL
PLSQL_EXEC_TIME: 0
TOTAL_MEMSTORE_READ_ROW_COUNT: 0
TOTAL_SSSTORE_READ_ROW_COUNT: 0
1 row in set (0.82 sec)
可以看到 ELAPSED_TIME: 94830642,总响应时间到了90多秒,但是其实EXECUTE_TIME: 160381,执行时间才160ms,其他的时间消耗也比较低,RETRY_CNT: 30,重试了30次,那么基本就是锁冲突导致了,我们通过TRACE_ID: YB42865A08D4-0006157C0336EBEA-0-0 去SVR_IP: 169.78.3.112节点的日志里搜索下。
xxxxxxxxxroot:/home/admin/oceanbase/log # grep YB42865A08D4-0006157C0336EBEA-0-0 observer.log|more
[2024-04-12 10:32:59.739289] WDIAG [STORAGE.TRANS] mvcc_write (ob_mvcc_row.cpp:1023) [9181][T1002_L0_G0][T1002][YB42865A08D4-0006157C0336EBEA-0-0] [lt=21][e
rrcode=-6005] mvcc write conflict(ret=-6005, ctx={ObIMvccCtx={alloc_type=0 ctx_descriptor=0 min_table_version=1712482298355992 max_table_version=17124822983
55992 trans_version={val:4611686018427387903, v:0} commit_version={val:0, v:0} lock_wait_start_ts=0 replay_compact_version={val:0, v:0}} end_code=0 tx_statu
s=0 is_readonly=false ref=1 trans_id={txid:3917083} ls_id=1001 row_callback[alloc:0, free:0, unsubmit:0] redo[fill:0,sync_succ:0, sync_fail:0] main_list_len
=1 pending_log_size=0 callback_list:{cnt=1 need_merge=0 stat:[tx_end=0, rollback_to=0, fast_commit=0, remove_memtable=0] detail:[(log_epoch,length,logged,sy
nced,appended,removed,unlog_removed,branch_removed)|0:(1,1,0,0,1,0,0,0)|]}}, node=this=0x7fe662a11a10 trans_version={val:4611686018427387903, v:0} scn={val:
4611686018427387903, v:0} tx_id={txid:3917083} prev=(nil) next=(nil) modify_count=4294967295 acc_checksum=0 version=1712887388091454 type=0 flag=0 snapshot_
barrier=0 snapshot_barrier_flag=0 mtd={dml_flag:2, buf_len:49} seq_no={branch:0, seq:3}, res={can_insert:false, need_insert:false, is_new_locked:false, is_m
vcc_undo:false, lock_state:{is_locked:true, trans_version:{val:0, v:0}, lock_trans_id:{txid:3917058}, lock_data_sequence:{branch:0, seq:15984}, lock_dml_fla
g:2, is_delayed_cleanout:false, mvcc_row:0x7fe662a040a8, trans_scn:{val:4611686018427387903, v:0}}, is_checked:false, tx_node:NULL}, *this={this=0x7fe662a04
0a8 latch_=unlocked flag=11 first_dml=UPDATE last_dml=UPDATE update_since_compact=2 list_head=0x7fe662a11978 latest_compact_node=(nil) max_trans_version={va
l:1712887883522203616, v:0} max_trans_id=3912943 max_elr_trans_version={val:1712887883522203616, v:0} max_elr_trans_id=3912943 latest_compact_ts=0 last_comp
act_cnt=0 total_trans_node_cnt=3 max_modify_scn={val:1712887883522203616, v:0} min_modify_scn={val:1712887883518676835, v:0}})
[2024-04-12 10:32:59.739372] INFO [STORAGE.TRANS] on_wlock_retry (ob_memtable_context.cpp:300) [9181][T1002_L0_G0][T1002][YB42865A08D4-0006157C0336EBEA-0-0
] [lt=78] mvcc_write conflict(key={"BIGINT UNSIGNED":33}, tx_id={txid:3917083}, conflict_tx_id={txid:3917058}, this={ObIMvccCtx={alloc_type=0 ctx_descriptor
=0 min_table_version=1712482298355992 max_table_version=1712482298355992 trans_version={val:4611686018427387903, v:0} commit_version={val:0, v:0} lock_wait_
start_ts=0 replay_compact_version={val:0, v:0}} end_code=0 tx_status=0 is_readonly=false ref=1 trans_id={txid:3917083} ls_id=1001 row_callback[alloc:0, free
:0, unsubmit:0] redo[fill:0,sync_succ:0, sync_fail:0] main_list_len=1 pending_log_size=0 callback_list:{cnt=1 need_merge=0 stat:[tx_end=0, rollback_to=0, fa
st_commit=0, remove_memtable=0] detail:[(log_epoch,length,logged,synced,appended,removed,unlog_removed,branch_removed)|0:(1,1,0,0,1,0,0,0)|]}})
[2024-04-12 10:32:59.739404] WDIAG [STORAGE] update_row (ob_tablet.cpp:3796) [9181][T1002_L0_G0][T1002][YB42865A08D4-0006157C0336EBEA-0-0] [lt=24][errcode=-
6005] failed to set memtable, (ret=-6005)
其实日志里很明显看到6005获取锁失败的信息,以及持有锁的lock_trans_id:{txid:3917058},那么根据这个txid就可以找到当时锁住该业务的另个业务模型。ps:在3.2.4版本中可以从日志中获取到持有锁的trans_hash的值,通过该值也可以获取该事务的业务模型。
MySQL [oceanbase]> select * from gv$ob_sql_audit where tx_id=3917058 \G
*************************** 1. row ***************************
SVR_IP: 169.78.3.112
SVR_PORT: 2882
REQUEST_ID: 12116788
SQL_EXEC_ID: 52281688
TRACE_ID: YB42865A08D4-0006157C0336EBE3-0-0
SID: 3221643380
CLIENT_IP: 169.78.3.112
CLIENT_PORT: 39832
TENANT_ID: 1002
TENANT_NAME: htap
EFFECTIVE_TENANT_ID: 1002
USER_ID: 200003
USER_NAME: SYS
USER_GROUP: 0
USER_CLIENT_IP: 169.78.3.112
DB_ID: 201006
DB_NAME: SYS
SQL_ID: 8D589AFA4DFAEEED85FFF5AA78E5FF6A
QUERY_SQL: begin
PLAN_ID: 0
AFFECTED_ROWS: 0
RETURN_ROWS: 0
PARTITION_CNT: 0
RET_CODE: 0
QC_ID: 0
DFO_ID: 0
SQC_ID: 0
WORKER_ID: 0
EVENT:
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: 0
PLAN_TYPE: 0
IS_INNER_SQL: 0
IS_EXECUTOR_RPC: 0
IS_HIT_PLAN: 0
REQUEST_TIME: 1712889172875953
ELAPSED_TIME: 200
NET_TIME: 0
NET_WAIT_TIME: 8
QUEUE_TIME: 37
DECODE_TIME: 1
GET_PLAN_TIME: 66
EXECUTE_TIME: 53
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: 0
DISK_READS: 0
RETRY_CNT: 0
TABLE_SCAN: 0
CONSISTENCY_LEVEL: -1
MEMSTORE_READ_ROW_COUNT: 0
SSSTORE_READ_ROW_COUNT: 0
DATA_BLOCK_READ_CNT: 0
DATA_BLOCK_CACHE_HIT: 0
INDEX_BLOCK_READ_CNT: 0
INDEX_BLOCK_CACHE_HIT: 0
BLOCKSCAN_BLOCK_CNT: 0
BLOCKSCAN_ROW_CNT: 0
PUSHDOWN_STORAGE_FILTER_ROW_CNT: 0
REQUEST_MEMORY_USED: 65536
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
TX_ID: 3917058
SNAPSHOT_VERSION: 0
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 0
LOCK_FOR_READ_TIME: 0
PARAMS_VALUE:
RULE_NAME:
PARTITION_HIT: 1
TX_INTERNAL_ROUTING: 1
TX_STATE_VERSION: 1
FLT_TRACE_ID: 000615dd-16b0-59f2-f7a7-1215e6062770
PL_TRACE_ID: NULL
PLSQL_EXEC_TIME: 0
TOTAL_MEMSTORE_READ_ROW_COUNT: 0
TOTAL_SSSTORE_READ_ROW_COUNT: 0
*************************** 2. row ***************************
SVR_IP: 169.78.3.112
SVR_PORT: 2882
REQUEST_ID: 12116789
SQL_EXEC_ID: 52281689
TRACE_ID: YB42865A08D4-0006157C0336EBE4-0-0
SID: 3221643380
CLIENT_IP: 169.78.3.112
CLIENT_PORT: 39832
TENANT_ID: 1002
TENANT_NAME: htap
EFFECTIVE_TENANT_ID: 1002
USER_ID: 200003
USER_NAME: SYS
USER_GROUP: 0
USER_CLIENT_IP: 169.78.3.112
DB_ID: 201006
DB_NAME: SYS
SQL_ID: 328A68949A9F6E066CEA786B79D83BE9
QUERY_SQL: update zry2 set b='cs' where a=985 and c=164
PLAN_ID: 3036
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:
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: 0
PLAN_TYPE: 1
IS_INNER_SQL: 0
IS_EXECUTOR_RPC: 0
IS_HIT_PLAN: 1
REQUEST_TIME: 1712889172876387
ELAPSED_TIME: 4429
NET_TIME: 0
NET_WAIT_TIME: 3
QUEUE_TIME: 145
DECODE_TIME: 0
GET_PLAN_TIME: 71
EXECUTE_TIME: 4196
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: 243
DISK_READS: 0
RETRY_CNT: 0
TABLE_SCAN: 1
CONSISTENCY_LEVEL: 3
MEMSTORE_READ_ROW_COUNT: 2
SSSTORE_READ_ROW_COUNT: 3
DATA_BLOCK_READ_CNT: 0
DATA_BLOCK_CACHE_HIT: 212
INDEX_BLOCK_READ_CNT: 0
INDEX_BLOCK_CACHE_HIT: 31
BLOCKSCAN_BLOCK_CNT: 422
BLOCKSCAN_ROW_CNT: 999999
PUSHDOWN_STORAGE_FILTER_ROW_CNT: 0
REQUEST_MEMORY_USED: 1369040
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
TX_ID: 3917058
SNAPSHOT_VERSION: 1712889172484169270
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 5849233527757913110
LOCK_FOR_READ_TIME: 0
PARAMS_VALUE:
RULE_NAME:
PARTITION_HIT: 1
TX_INTERNAL_ROUTING: 1
TX_STATE_VERSION: 2
FLT_TRACE_ID: 000615dd-16b0-59f2-f7a7-1215e6062770
PL_TRACE_ID: NULL
PLSQL_EXEC_TIME: 0
TOTAL_MEMSTORE_READ_ROW_COUNT: 0
TOTAL_SSSTORE_READ_ROW_COUNT: 0
*************************** 3. row ***************************
SVR_IP: 169.78.3.112
SVR_PORT: 2882
REQUEST_ID: 12119439
SQL_EXEC_ID: 52294147
TRACE_ID: YB42865A08D4-0006157C0336EBEB-0-0
SID: 3221643380
CLIENT_IP: 169.78.3.112
CLIENT_PORT: 39832
TENANT_ID: 1002
TENANT_NAME: htap
EFFECTIVE_TENANT_ID: 1002
USER_ID: 200003
USER_NAME: SYS
USER_GROUP: 0
USER_CLIENT_IP: 169.78.3.112
DB_ID: 201006
DB_NAME: SYS
SQL_ID: FFFCA4D67EA0A788813031B8BBC3B329
QUERY_SQL: commit
PLAN_ID: 0
AFFECTED_ROWS: 0
RETURN_ROWS: 0
PARTITION_CNT: 0
RET_CODE: 0
QC_ID: 0
DFO_ID: 0
SQC_ID: 0
WORKER_ID: 0
EVENT:
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: 4
PLAN_TYPE: 0
IS_INNER_SQL: 0
IS_EXECUTOR_RPC: 0
IS_HIT_PLAN: 0
REQUEST_TIME: 1712889274559727
ELAPSED_TIME: 546
NET_TIME: 0
NET_WAIT_TIME: 5
QUEUE_TIME: 75
DECODE_TIME: 1
GET_PLAN_TIME: 94
EXECUTE_TIME: 344
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: 0
DISK_READS: 0
RETRY_CNT: 0
TABLE_SCAN: 0
CONSISTENCY_LEVEL: -1
MEMSTORE_READ_ROW_COUNT: 0
SSSTORE_READ_ROW_COUNT: 0
DATA_BLOCK_READ_CNT: 0
DATA_BLOCK_CACHE_HIT: 0
INDEX_BLOCK_READ_CNT: 0
INDEX_BLOCK_CACHE_HIT: 0
BLOCKSCAN_BLOCK_CNT: 0
BLOCKSCAN_ROW_CNT: 0
PUSHDOWN_STORAGE_FILTER_ROW_CNT: 0
REQUEST_MEMORY_USED: 65536
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
TX_ID: 3917058
SNAPSHOT_VERSION: 0
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 0
LOCK_FOR_READ_TIME: 0
PARAMS_VALUE:
RULE_NAME:
PARTITION_HIT: 1
TX_INTERNAL_ROUTING: 0
TX_STATE_VERSION: 2
FLT_TRACE_ID: 000615dd-16b0-59f2-f7a7-1215e6062770
PL_TRACE_ID: NULL
PLSQL_EXEC_TIME: 0
TOTAL_MEMSTORE_READ_ROW_COUNT: 0
TOTAL_SSSTORE_READ_ROW_COUNT: 0
3 rows in set (0.58 sec)
当然我这个实验中的实验模型比较简单,就是开启事务执行update然后commit,生产中的业务模型可能会涉及成百上千条sql,那么可以根据表名和时间缩小查询的范围,提供给业务有力并关键的信息和证据就可以。
总结:
因为4.x采用了日志流,所以在想确认表上的锁的时候要多关联一张表了,但是思路都是一样的,并没有什么不同,古人云:授人与鱼不如授人与渔。希望可以帮助大家学习与理解。
行之所向,莫问远方。