概念描述
ORACLE 有更新重启动，但不会发生在锁等待过程中。OB在锁等待过程中，会每间隔10秒，进行回滚，重新执行（每次重试2次）。
测试验证
1、创建测试表
obclient [TEST]> create table tlock (id number primary key,c1 varchar2(100),c2 varchar2(100));
Query OK, 0 rows affected (0.525 sec)
obclient [TEST]> insert into tlock select rownum id,'test'||rownum,'test'||rownum from dual connect by rownum<100000;
Query OK, 99999 rows affected (0.928 sec)
Records: 99999 Duplicates: 0 Warnings: 0
obclient [TEST]> commit;
Query OK, 0 rows affected (0.178 sec)
2、修改参数
每个session调整timeout变量
set ob_trx_lock_timeout=7200000000;
set ob_trx_idle_timeout=7200000000;
set ob_trx_timeout=7200000000;
set ob_query_timeout=7200000000;
3、模拟、观察锁等待
session 1 先更新不提交
obclient [TEST]> update tlock set c1=c2 where c1='test99999';
Query OK, 1 row affected (0.049 sec)
Rows matched: 1 Changed: 1 Warnings: 0
session 2 update等待,等待一段时间后，session 1提交，session 2执行成功
--开启trace log，调整ob_log_level=debug,观察锁等待输出
obclient [TEST]> set ob_enable_trace_log=on;
Query OK, 0 rows affected (0.001 sec)
obclient [TEST]> set ob_log_level=debug;
Query OK, 0 rows affected (0.001 sec)
obclient [TEST]> rollback;
Query OK, 0 rows affected (0.001 sec)
obclient [TEST]> update tlock set c1=c2 where c1='test99999';
Query OK, 1 row affected (47.225 sec)
Rows matched: 1 Changed: 1 Warnings: 0
obclient [TEST]> show trace;
+-----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+
| TITLE | KEYVALUE | TIME |
+-----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+
| process begin | addr:{ip:"192.168.10.71", port:55768}, in_queue_time:47175213, receive_ts:1692583838514886, enqueue_ts:1692583885690093, trace_id:YB420AE6B77C-0006032E174508DC-0-0 | 0 |
| parse begin | stmt:"update tlock set c1=c2 where c1='test99999'", stmt_len:43 | 39 |
| execution begin | arg1:false, end_trans_cb:false, plan_id:71590 | 65 |
| do open plan begin | NULL | 1 |
| sql start stmt begin | NULL | 4 |
| sql start participant begin | NULL | 165 |
| table scan begin | NULL | 132 |
| table scan end | NULL | 150 |
| start_close_plan begin | NULL | 48945 |
| start_end_participant begin | NULL | 10 |
| start_auto_end_plan begin | NULL | 14 |
| NULL | PHY_UPDATE | NULL |
| TLOCK | PHY_TABLE_SCAN | NULL |
+-----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+
13 rows in set (0.013 sec)
obclient [TEST]> select * from v$sql_audit where trace_id='YB420AE6B77C-0006032E174508DC-0-0'\G
*************************** 1. row ***************************
SVR_IP: 192.168.10.124
SVR_PORT: 2882
REQUEST_ID: 4366114
SQL_EXEC_ID: 12542696
TRACE_ID: YB420AE6B77C-0006032E174508DC-0-0
SID: 3223042647
CLIENT_IP: 192.168.10.71
CLIENT_PORT: 55768
TENANT_ID: 1005
EFFECTIVE_TENANT_ID: 1005
TENANT_NAME: tbcsf
USER_ID: 1105009185915912
USER_NAME: TEST
USER_GROUP: 0
USER_CLIENT_IP: 192.168.10.11
DB_ID: 1105009185915962
DB_NAME: TEST
SQL_ID: 7DFFD37D22A261B3A556FF6D879BD177
QUERY_SQL: update tlock set c1=c2 where c1='test99999'
PLAN_ID: 71590
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: NULL
P1: 0
P2TEXT: NULL
P2: 0
P3TEXT: NULL
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: 1692583838514886
ELAPSED_TIME: 47224758
NET_TIME: 0
NET_WAIT_TIME: 1
QUEUE_TIME: 279
DECODE_TIME: 10
GET_PLAN_TIME: 899
EXECUTE_TIME: 542154 <<<<没有等待时的执行时长为46毫秒，重试10次，执行时间为原来的10倍
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
BLOCK_INDEX_CACHE_HIT: 0
DISK_READS: 0
RETRY_CNT: 10 <<<<重试10次
TABLE_SCAN: 1
CONSISTENCY_LEVEL: 3
MEMSTORE_READ_ROW_COUNT: 100000 <<<<重试10次,这个指标并没有增长，比较奇怪,通过debug日志看，在有锁等待时，实际SQL消耗应为MEMSTORE_READ_ROW_COUNT*RETRY_CNT
SSSTORE_READ_ROW_COUNT: 0
REQUEST_MEMORY_USED: 2096128
EXPECTED_WORKER_COUNT: 0
USED_WORKER_COUNT: 0
SCHED_INFO: NULL
PS_CLIENT_STMT_ID: -1
PS_INNER_STMT_ID: -1
TRANSACTION_HASH: 15259655584073690548
REQUEST_TYPE: 2
IS_BATCHED_MULTI_STMT: 0
OB_TRACE_INFO: NULL
PLAN_HASH: 5400499873144794138
PARAMS_VALUE: NULL
1 row in set (28.957 sec)
4、 从debug trace log中观察锁等待过程
可以看到差不多每隔10秒会回滚掉，重试2次（每次回滚会生成2条memtable handle rollback to successfuly日志）,重试一次约50毫秒，差不多就是没有等待时的单次执行时长。
[admin@ob6 log]$ cat observer.log.20230821101725140|grep YB420AE6B77C-0006032E174508DC-0-0|grep "memtable handle rollback to successfuly"
--第1次回滚重试，重试2次
[2023-08-21 10:10:38.565029] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] memtable handle rollback to successfuly(seq_no=1692583838514551, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583838427948 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583838514551 abs_expired_time=1692585038414886 stmt_timeout=1199900335 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:38.565057] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=6] [dc=0] memtable handle rollback to successfuly(seq_no=1692583838514551, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583838427948 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583838514551 abs_expired_time=1692585038414886 stmt_timeout=1199900335 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:38.614721] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=1] [dc=0] memtable handle rollback to successfuly(seq_no=1692583838565008, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583838528112 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583838565008 abs_expired_time=1692585038414886 stmt_timeout=1199849878 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:38.614749] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=7] [dc=0] memtable handle rollback to successfuly(seq_no=1692583838565008, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583838528112 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583838565008 abs_expired_time=1692585038414886 stmt_timeout=1199849878 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
--第2次回滚重试，重试2次
[2023-08-21 10:10:45.727142] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=8] [dc=0] memtable handle rollback to successfuly(seq_no=1692583845678348, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583845635340 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583845679088 abs_expired_time=1692585038414886 stmt_timeout=1192735798 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:45.727189] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=8] [dc=0] memtable handle rollback to successfuly(seq_no=1692583845678348, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583845635340 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583845679088 abs_expired_time=1692585038414886 stmt_timeout=1192735798 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:45.772545] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] memtable handle rollback to successfuly(seq_no=1692583845726782, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583845635340 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583845726518 abs_expired_time=1692585038414886 stmt_timeout=1192688368 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:45.772567] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=7] [dc=0] memtable handle rollback to successfuly(seq_no=1692583845726782, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583845635340 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583845726518 abs_expired_time=1692585038414886 stmt_timeout=1192688368 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
--第3次回滚重试，重试2次
[2023-08-21 10:10:55.733436] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] memtable handle rollback to successfuly(seq_no=1692583855680378, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583855645590 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583855680378 abs_expired_time=1692585038414886 stmt_timeout=1182734508 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:55.733464] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=6] [dc=0] memtable handle rollback to successfuly(seq_no=1692583855680378, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583855645590 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583855680378 abs_expired_time=1692585038414886 stmt_timeout=1182734508 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:55.783188] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=6] [dc=0] memtable handle rollback to successfuly(seq_no=1692583855732923, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583855645590 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583855732923 abs_expired_time=1692585038414886 stmt_timeout=1182681963 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:10:55.783221] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=9] [dc=0] memtable handle rollback to successfuly(seq_no=1692583855732923, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583855645590 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583855732923 abs_expired_time=1692585038414886 stmt_timeout=1182681963 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
--第4次回滚重试，重试2次
[2023-08-21 10:11:05.738166] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0] memtable handle rollback to successfuly(seq_no=1692583865688305, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583865655499 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583865688656 abs_expired_time=1692585038414886 stmt_timeout=1172726230 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:11:05.738195] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=5] [dc=0] memtable handle rollback to successfuly(seq_no=1692583865688305, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583865655499 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583865688656 abs_expired_time=1692585038414886 stmt_timeout=1172726230 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:11:05.785935] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=1] [dc=0] memtable handle rollback to successfuly(seq_no=1692583865737887, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583865655499 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583865738146 abs_expired_time=1692585038414886 stmt_timeout=1172676740 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:11:05.785960] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=5] [dc=0] memtable handle rollback to successfuly(seq_no=1692583865737887, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583865655499 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583865738146 abs_expired_time=1692585038414886 stmt_timeout=1172676740 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)[2023-08-21 10:11:15.747275] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=4] [dc=0] memtable handle rollback to successfuly(seq_no=1692583875696861, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583875665543 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583875697242 abs_expired_time=1692585038414886 stmt_timeout=1162717644 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
--第5次回滚重试，重试2次
[2023-08-21 10:11:15.747309] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=7] [dc=0] memtable handle rollback to successfuly(seq_no=1692583875696861, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583875665543 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583875697242 abs_expired_time=1692585038414886 stmt_timeout=1162717644 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:11:15.797275] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] memtable handle rollback to successfuly(seq_no=1692583875746310, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583875665543 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583875746742 abs_expired_time=1692585038414886 stmt_timeout=1162668144 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
[2023-08-21 10:11:15.797309] INFO [STORAGE.TRANS] ob_memtable_context.cpp:1469 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=8] [dc=0] memtable handle rollback to successfuly(seq_no=1692583875746310, is_replay=false, need_write_log=false, max_durable_log_ts=0, *this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583875665543 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583875746742 abs_expired_time=1692585038414886 stmt_timeout=1162668144 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=1692583838563965 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, has_calc_checksum=false, checksum=0, checksum_log_ts=0)
每次重试时的get next row failed日志（ret -6005)
[admin@ob6 log]$ cat observer.log|grep YB420AE6B77C-0006032E174508DC-0-0|grep "get next row failed"
[2023-08-21 10:10:38.564979] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:10:38.614676] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:10:45.727064] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:10:45.772504] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=1] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:10:55.733385] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:10:55.783119] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:11:05.738115] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:11:05.785893] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:11:15.747214] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[2023-08-21 10:11:15.797221] WDIAG [SQL.ENG] ob_operator.cpp:782 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] inner get next row failed(ret=-6005, type=25, op="PHY_UPDATE")
[admin@ob6 log]$
lock_for_write conflict日志记录
[admin@ob6 log]$ cat observer.log|grep YB420AE6B77C-0006032E174508DC-0-0|grep "lock_for_write conflict"|wc -l
5
admin@ob6 log]$ cat observer.log.20230821101725140|grep YB420AE6B77C-0006032E174508DC-0-0|grep "lock_for_write conflict"
[2023-08-21 10:10:38.564722] WDIAG [STORAGE.TRANS] ob_memtable_context.cpp:352 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=7] [dc=0][errcode=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583838427948 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583838514551 abs_expired_time=1692585038414886 stmt_timeout=1199900335 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=2 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, key=table_id=1105009186204158 rowkey_object=[{"NUMBER":"99999"}] , conflict_ctx="alloc_type=0 ctx_descriptor=7483384 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583832822598 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583832875486 abs_expired_time=1692585032775247 stmt_timeout=1199899761 abs_lock_wait_timeout=1692585032775247 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:17325829981666003259, inc:1274109, addr:"192.168.10.124:2882", t:1692583832874433} trans_mem_total_size=79 checksum_log_ts=0")
[2023-08-21 10:10:45.726794] WDIAG [STORAGE.TRANS] ob_memtable_context.cpp:352 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=8] [dc=0][errcode=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583845635340 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583845679088 abs_expired_time=1692585038414886 stmt_timeout=1192735798 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=2 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, key=table_id=1105009186204158 rowkey_object=[{"NUMBER":"99999"}] , conflict_ctx="alloc_type=0 ctx_descriptor=7483384 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583832822598 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583832875486 abs_expired_time=1692585032775247 stmt_timeout=1199899761 abs_lock_wait_timeout=1692585032775247 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:17325829981666003259, inc:1274109, addr:"192.168.10.124:2882", t:1692583832874433} trans_mem_total_size=79 checksum_log_ts=0")
[2023-08-21 10:10:55.733114] WDIAG [STORAGE.TRANS] ob_memtable_context.cpp:352 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=7] [dc=0][errcode=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583855645590 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583855680378 abs_expired_time=1692585038414886 stmt_timeout=1182734508 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=2 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, key=table_id=1105009186204158 rowkey_object=[{"NUMBER":"99999"}] , conflict_ctx="alloc_type=0 ctx_descriptor=7483384 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583832822598 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583832875486 abs_expired_time=1692585032775247 stmt_timeout=1199899761 abs_lock_wait_timeout=1692585032775247 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:17325829981666003259, inc:1274109, addr:"192.168.10.124:2882", t:1692583832874433} trans_mem_total_size=79 checksum_log_ts=0")
[2023-08-21 10:11:05.737844] WDIAG [STORAGE.TRANS] ob_memtable_context.cpp:352 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=6] [dc=0][errcode=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583865655499 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583865688656 abs_expired_time=1692585038414886 stmt_timeout=1172726230 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=2 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, key=table_id=1105009186204158 rowkey_object=[{"NUMBER":"99999"}] , conflict_ctx="alloc_type=0 ctx_descriptor=7483384 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583832822598 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583832875486 abs_expired_time=1692585032775247 stmt_timeout=1199899761 abs_lock_wait_timeout=1692585032775247 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:17325829981666003259, inc:1274109, addr:"192.168.10.124:2882", t:1692583832874433} trans_mem_total_size=79 checksum_log_ts=0")
[2023-08-21 10:11:15.746923] WDIAG [STORAGE.TRANS] ob_memtable_context.cpp:352 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=8] [dc=0][errcode=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=7483381 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583875665543 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583875697242 abs_expired_time=1692585038414886 stmt_timeout=1162717644 abs_lock_wait_timeout=1692585038414886 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=2 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:15259655584073690548, inc:1274119, addr:"192.168.10.124:2882", t:1692583838514551} trans_mem_total_size=0 checksum_log_ts=0, key=table_id=1105009186204158 rowkey_object=[{"NUMBER":"99999"}] , conflict_ctx="alloc_type=0 ctx_descriptor=7483384 min_table_version=1692581639025576 max_table_version=1692581639025576 is_safe_read=false read_snapshot=1692583832822598 start_version=-1 trans_version=9223372036854775807 commit_version=0 stmt_start_time=1692583832875486 abs_expired_time=1692585032775247 stmt_timeout=1199899761 abs_lock_wait_timeout=1692585032775247 row_purge_version=0 lock_wait_start_ts=0 trx_lock_timeout=600000000 end_code=0 is_readonly=false ref=0 pkey={tid:1105009186204158, partition_id:0, part_cnt:0} trans_id={hash:17325829981666003259, inc:1274109, addr:"192.168.10.124:2882", t:1692583832874433} trans_mem_total_size=79 checksum_log_ts=0")
lock_for_write conflict日志记录，冲突的行
[admin@ob6 log]$ cat observer.log|grep YB420AE6B77C-0006032E174508DC-0-0|grep "ob_table_update_op"
[2023-08-21 10:10:38.564583] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:38.564972] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:38.564974] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:10:38.614318] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:38.614669] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:38.614672] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:10:45.726590] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:45.727056] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:45.727059] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:10:45.772178] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:45.772498] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:45.772501] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964436][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:10:55.732950] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:55.733378] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:55.733381] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:10:55.782709] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:10:55.783111] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:10:55.783114] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964564][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:11:05.737706] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:11:05.738106] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:11:05.738109] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:11:05.785547] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:11:05.785886] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:11:05.785889] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964372][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:11:15.746753] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:11:15.747206] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:11:15.747209] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:11:15.796787] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[2023-08-21 10:11:15.797213] WDIAG [SQL.ENG] ob_table_update_op.cpp:447 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0][errcode=-6005] execute all update das task failed(ret=-6005)
[2023-08-21 10:11:15.797216] WDIAG [SQL.ENG] ob_table_update_op.cpp:219 [2964390][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=2] [dc=0][errcode=-6005] do update rows post process failed(ret=-6005)
[2023-08-21 10:11:25.739438] TRACE [SQL.ENG] ob_table_update_op.cpp:490 [2964539][0][YB420AE6B77C-0006032E174508DC-0-0] [lt=3] [dc=0] child output row(row=[{expr:0x7f3e8f98c0d0, {"NUMBER":"99999"}}, {expr:0x7f3e8f98c178, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c220, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}, {expr:0x7f3e8f98c610, {"VARCHAR2":"test99999", collation:"utf8mb4_bin", coercibility:"IMPLICIT"}}])
[admin@ob6 log]$
5、通过OS LOAD,CPU消耗验证(回滚，重新执行会消耗CPU)
obclient [SYS]> create table tlock (id number primary key,c1 varchar2(100),c2 varchar2(100));
Query OK, 0 rows affected (0.116 sec)
obclient [SYS]> insert into tlock select rownum id,'test'||rownum,'test'||rownum from dual connect by rownum<1000000;
Query OK, 999999 rows affected (13.431 sec)
Records: 999999 Duplicates: 0 Warnings: 0
obclient [SYS]> commit;
Query OK, 0 rows affected (1.807 sec)
---session更新后不提交
obclient [SYS]> update tlock set c1=c2 where c1='test999999';
Query OK, 1 row affected (0.917 sec)
Rows matched: 1 Changed: 1 Warnings: 0
--创建100 session 并发行执行
update tlock set c1=c2
vmstat 间隔2秒输出，每隔10秒等待行锁的update会回滚，重新执行，消耗大量CPU,running队列高。
[root@ob4 ~]# vmstat 2
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 0 0 487721088 2135428 8422316 0 0 0 26 1 0 2 2 96 0 0
3 0 0 487721344 2135428 8422452 0 0 0 32 80123 159426 1 2 97 0 0
0 0 0 487721472 2135428 8422564 0 0 0 0 80469 160559 1 2 97 0 0
31 0 0 487720032 2135432 8422800 0 0 0 32 82069 163241 1 2 97 0 0
0 0 0 487719936 2135432 8422912 0 0 0 18 83215 162430 1 2 97 0 0
0 0 0 487726880 2135432 8423024 0 0 0 14 82531 162957 1 2 97 0 0
0 0 0 487724928 2135440 8423148 0 0 0 28 82577 162629 1 2 97 0 0
0 0 0 487724576 2135440 8423276 0 0 0 0 81690 161798 1 2 97 0 0
。。。。。
136 0 0 477655392 2135532 8454848 0 0 8 2474 132738 123680 49 2 49 0 0 vmstat 间隔2秒输出，每隔10秒等待行锁的update会回滚，重新执行，消耗大量CPU,running队列高。
5 0 0 477393440 2135532 8456000 0 0 8 3954 115638 176762 12 2 86 0 0
2 0 0 477133856 2135532 8456120 0 0 8 4098 99355 175149 3 2 96 0 0
1 0 0 476948000 2135532 8456280 0 0 8 2698 98687 172256 2 2 95 0 0
2 0 0 476934592 2135532 8456432 0 0 8 4098 97221 170132 2 2 96 0 0
255 0 0 476730560 2135532 8457532 0 0 8 686 183546 120589 49 2 49 0 0
4 0 0 476519072 2135532 8458508 0 0 8 3274 120631 164193 23 2 75 0 0
3 0 0 476253376 2135532 8458764 0 0 8 3920 107209 174014 3 2 95 0 0
1 0 0 476001536 2135532 8458912 0 0 8 3824 94007 168229 2 2 95 0 0
3 0 0 475746880 2135536 8459080 0 0 8 4126 92803 168510 2 2 96 0 0
198 0 0 475454400 2135540 8460108 0 0 8 2512 184655 119846 49 2 49 0 0
5 0 0 475233440 2135540 8461288 0 0 8 3240 121281 165517 24 2 74 0 0
9 0 0 474973504 2135544 8461532 0 0 8 3876 102975 174554 2 2 96 0 0
2 0 0 474861184 2135548 8461676 0 0 8 1596 91119 167298 3 2 96 0 0
3 0 0 474836416 2135548 8461892 0 0 8 54 91645 165799 3 2 95 0 0
93 0 0 474637248 2135548 8463264 0 0 8 2540 131873 124829 49 2 49 0 0
5 0 0 474496608 2135548 8464160 0 0 8 3914 114206 175422 11 2 87 0 0
3 0 0 474361184 2135552 8464404 0 0 8 4118 95174 171444 3 2 96 0 0
1 0 0 474220832 2135552 8464536 0 0 8 4068 93940 173688 3 2 95 0 0
2 0 0 473990336 2135552 8464692 0 0 8 7844 95377 168866 2 2 96 0 0
160 0 0 473695936 2135552 8465800 0 0 8 2544 141319 120969 49 2 49 0 0
3 0 0 473441152 2135552 8466860 0 0 8 3688 113171 175622 10 2 88 0 0
5 0 0 473290304 2135556 8467112 0 0 8 2364 100330 170518 2 2 96 0 0
3 0 0 473277376 2135556 8467256 0 0 8 8 88945 165278 2 2 96 0 0
5 0 0 473151040 2135556 8467484 0 0 8 3654 95173 170956 3 2 95 0 0
54 0 0 472931680 2135560 8468272 0 0 8 2534 149181 125581 48 2 50 0 0
2 0 0 472790656 2135560 8469636 0 0 8 3934 111565 176973 8 2 90 0 0
5 0 0 472667296 2135560 8469872 0 0 8 3826 94133 169751 3 2 95 0 0
2 0 0 472461696 2135560 8470008 0 0 4 3390 94141 169389 2 2 96 0 0
知识总结
ob在有锁等待时，每隔10秒会回滚掉SQL的更新，并重试2次，如果大量锁等待，并且等时间比较长时，这个内部回滚重试会消耗大量资源,(尤其SQL本身较慢时，每次重试消耗更多资源)
参考文档
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。
