划线反馈

锁冲突导致业务交易报 read time out 超时问题

更新时间：2026-06-10 09:51

适用版本：V4.1.x、V4.2.x内容类型：Troubleshoot

问题现象

生产环境中业务交易，应用报 read time out 超时，如下图所示。

业务采用微服务架构，应用侧有交易 10s 超时断链设置，但该业务中 update sql 根据主键更新数据，t_upp_txn_main 表为主流水表，按理不会超过 10s。

应用提供的日志信息如下。

[2025-01-0912:44:48:968][INFO ][SW_CTX: [5d9ada4d64404fcbb1f639e84e89c32c.157.17363978889590183,0]][60010002][g01][s60360102-lt-65b7958dc7-w2cvg][10.158.130.220][1][http-nio-28888-exec-5][com.kayakwise.delivery.scbank.ScBankSQLLogger:][#sqlParams: params=TxnCreditBean[amount=1000.00,authType=AC05,bizKind=03301,bizStep=S900,bizType=D101,channelCode=S60360199,consumeTime=2693,createTime=Thu Jan 09 12:44:46 CST 2025,currency=CNY,deptCode=76012,deptId=69,globalBusiTrackNo=s603601997vzrw202501091244462633850,legalCode=8000,logTraceId=3492B66E59704AE49E92AE821CCC18C9,msgCode=cbps.142.001.01,msgDirection=S,msgNo=2025010900036008,operator=0003097,payeeAcctName=xxx,payeeAcctNo=0,payeeClearBankCode=313651071504,payeeClearBankName=xxxxx,payeeOpenBankCode=313xxx028,payeeOpenBankName=xxxxxxxx,payerAcctName=xxx,payerAcctNo=623xxx0000001xxx87,payerAcctType=AT07,payerClearBankCode=3136xxx748,payerClearBankName=xxxxx,payerOpenBankCode=313xxx748,payerOpenBankName=xxx分行,platBizKind=P3301,platBizType=P21101,pmcCode=CBPS,pmcDate=20250109,pmcNo=20250109124446273000017678001000,pmcStatus=SUCCESS,prodNo=JCZFCP2024052800000002,recvBankCode=3136xxx028,recvBankName=xxxxxx,retCode=000000,retMsg=成功,selfBank=0,sendBankCode=3136xxxx748,sendBankN... Ignore 274 characters]

涉及的更新语句 update sql。

update t_upp_txn_main set status = $s{status}, biz_step = $s{biz_step}, pmc_status = $s{pmc_status}, ret_code = $s{ret_code}, 
ret_msg = $s{ret_msg}, send_bank_code = $s{send_bank_code}, send_bank_name = $s{send_bank_name}, 
recv_bank_code = $s{recv_bank_code}, recv_bank_name = $s{recv_bank_name}, biz_type = $s{biz_type}, biz_kind = $s{biz_kind}, msg_code = $s{msg_code}, msg_no = $s{msg_no} 
where txn_no=$s{txn_no} and txn_date=$s{txn_date}]

-- 表结构
CREATE TABLE `t_upp_txn_main` (
  `txn_no` varchar(69) COLLATE utf8mb4_bin NOT NULL COMMENT 'xx流水号',
  `txn_date` varchar(8) COLLATE utf8mb4_bin NOT NULL COMMENT 'xxxx日期',
  `txn_time` varchar(9) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'xxxxx时点',
  `legal_code` varchar(4) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'xx代码',
  `dept_id` bigint(20) DEFAULT NULL COMMENT 'xx自增编号',
  `dept_code` varchar(6) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'xx编号',
  ......
  ......
  `spare4` varchar(512) COLLATE utf8mb4_bin DEFAULT NULL COMMENT '备用字段四',
  `spare5` varchar(512) COLLATE utf8mb4_bin DEFAULT NULL COMMENT '备用字段五',
  PRIMARY KEY (`txn_no`, `txn_date`),
  UNIQUE KEY `uk_t_upp_txn_main_channel_code` (`txn_date`, `trans_no`, `trans_date`, `channel_code`) BLOCK_SIZE 16384 LOCAL,
  KEY `idx_t_upp_txn_main_dept_id` (`dept_code`) BLOCK_SIZE 16384 LOCAL,
  KEY `idx_t_upp_txn_main_query_upp_txn_recv` (`pmc_code`, `msg_direction`, `txn_date`, `update_time`) BLOCK_SIZE 16384 LOCAL
) DEFAULT CHARSET = utf8mb4 COLLATE = utf8mb4_bin ROW_FORMAT = DYNAMIC COMPRESSION = 'zstd_1.3.8' REPLICA_NUM = 3 BLOCK_SIZE = 16384 USE_BLOOM_FILTER = FALSE TABLET_SIZE = 134217728 PCTFREE = 0 COMMENT = 'xxxxx主流水表'
 partition by range columns(`txn_date`)
(partition `t_upp_txn_main_part202109` values less than ('20210930'),
partition `t_upp_txn_main_part202110` values less than ('20211031'),
......
......
partition `t_upp_txn_main_part202707` values less than ('20270731'),
partition `t_upp_txn_main_part202708` values less than ('20270831')
)

问题排查分析

根据业务报错时间点和关键词，搜索 OBProxy 日志：该 SQL 执行成功，并没有报错，执行耗时：8197379us。

[root@xxxxx log]# grep '20250109124446273000017678001000' obproxy_digest.log 
2025-01-09 12:44:57.166570,scb_prod_ob70_obp,,,,scb_prod_ob70:s_6036_upp:supp_trans_db,OB_MYSQL,t_upp_txn_main,t_upp_txn_main,COM_QUERY,UPDATE,success,,update t_upp_txn_main set status = 'SUCCESS'%2C biz_step = 'S900'%2C pmc_status = 'SUCCESS'%2C ret_code = '000000'%2C ret_msg = '成功'%2C send_bank_code = '3136xxx748'%2C send_bank_name = 'xxxxxx'%2C recv_bank_code = '3136xxx8'%2C recv_bank_name = 'xxxxxxxxxxx'%2C biz_type = 'D101'%2C biz_kind = '03301'%2C msg_code = 'xxx.1xx.0xx.0xxx'%2C msg_no = '2025010900036008' where txn_no='20250109124446273000017678001000' and txn_date='20250109',8197379us,0us,0us,8197379us,Y0-xxxxxx,YBxxxxx-xxxxx-xxxxx-xxxxx,10.xxx.xxx.19:60338,,0,10.xxx.xxx.108:2881
[root@xxxxx log]# 
[root@xxxxx log]# grep '20250109124446273000017678001000' obproxy_slow.log           
2025-01-09 12:44:57.166581,scb_prod_ob70_obp,,,,scb_prod_ob70:s_6036_upp:supp_trans_db,OB_MYSQL,t_upp_txn_main,t_upp_txn_main,COM_QUERY,UPDATE,success,,update t_upp_txn_main set status = 'SUCCESS'%2C biz_step = 'S900'%2C pmc_status = 'SUCCESS'%2C ret_code = '000000'%2C ret_msg = '成功'%2C send_bank_code = '3136xxx48'%2C send_bank_name = 'xxxxx'%2C recv_bank_code = '313xxx0028'%2C recv_bank_name = 'xxxxxxxxxxx'%2C biz_type = 'D101'%2C biz_kind = '03301'%2C msg_code = 'xxx.1xx.0xx.0xxx'%2C msg_no = '2025010900036008' where txn_no='20250109124446273000017678001000' and txn_date='20250109',8197379us,0us,0us,8197379us,Y0-xxxxx,YBxxxxx-xxxxx-xxxx-xxxx,10.xxx.xxx.19:60338,,0,10.xxx.xxx.108:2881
[root@xxxxx log]# 
[root@xxxxx log]# grep 'Y0-xxxxx' obproxy.log.20250109162625 
[2025-01-09 12:44:57.166500] WDIAG [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:11068) [1081385][Y0-xxxxx] [lt=0] [dc=0] Slow Query: ((client_ip={xxx.xxx.xxxx.xxxx:60338}, server_ip={xxx.xxx.xxxx.xxxx:2881}, obproxy_client_port={xxx.xxx.xxxx.xxxx:29588}, server_trace_id=YBxxxxx-xxxxx-xxxxx-xxxxx, route_type=ROUTE_TYPE_LEADER, user_name=supp, tenant_name=s_6036_upp, cluster_name=scb_prod_ob70, logic_database_name=, logic_tenant_name=, ob_proxy_protocol=2, cs_id=594838, proxy_sessid=740558744064347503, ss_id=1102759, server_sessid=3221924144, sm_id=2731391, cmd_size_stats={client_request_bytes:489, server_request_bytes:524, server_response_bytes:53, client_response_bytes:53}, cmd_time_stats={client_transaction_idle_time_us=0, client_request_read_time_us=0, client_request_analyze_time_us=0, cluster_resource_create_time_us=0, pl_lookup_time_us=0, pl_process_time_us=0, bl_lookup_time_us=0, bl_process_time_us=0, congestion_control_time_us=0, congestion_process_time_us=0, do_observer_open_time_us=0, server_connect_time_us=0, server_sync_session_variable_time_us=0, server_send_saved_login_time_us=0, server_send_use_database_time_us=0, server_send_session_variable_time_us=0, server_send_session_user_variable_time_us=0, server_send_all_session_variable_time_us=0, server_send_start_trans_time_us=0, server_send_xa_start_time_us=0, server_send_init_sql_time_us=0, build_server_request_time_us=0, plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=0, server_request_write_time_us=0, server_process_request_time_us=8197379, server_response_read_time_us=0, plugin_decompress_response_time_us=0, server_response_analyze_time_us=0, ok_packet_trim_time_us=0, client_response_write_time_us=0, request_total_time_us=8197379}, sql=update t_upp_txn_main set status = 'SUCCESS', biz_step = 'S900', pmc_status = 'SUCCESS', ret_code = '000000', ret_msg = '成功', send_bank_code = '3136xxx748', send_bank_name = 'xxxx分行', recv_bank_code = '313xxx0028', recv_bank_name = 'xxxxxxxxxxx', biz_type = 'D101', biz_kind = '03301', msg_code = 'xxx.1xx.0xx.0xxx', msg_no = '2025010900036008' where txn_no='20250109124446273000017678001000' and txn_date='20250109', trans_internal_routing_state=not in trans)

查看 ocp-topsql，该 SQL 执行共 10 次，平均每次执行耗时 10s 左右，存在 51 次重试。

根据 ocp-sql 该 sql_id，搜索 sql_audit，发现确实每次 SQL 执行存在很多重试。

select /*+ parallel(10) query_timeout(60000000)*/usec_to_time(request_time) ,svr_ip,trace_id,tx_id,sid,query_sql,plan_id,ret_code,elapsed_time,IS_HIT_PLAN,QUEUE_TIME,GET_PLAN_TIME,EXECUTE_TIME,RETRY_CNT,client_ip,user_client_ip,tenant_id,tenant_name,user_name,db_name,sql_id,PLAN_HASH from gv$ob_sql_audit a where 1=1 and sql_id='94451D775E1511C36EACB53BAADFA39E' order by request_time;

从 sql_audit 数据中，可以作证应用报错的该时间点 12:44:48 这个 SQL，执行成功 ret_code=0，执行耗时 elapsed_time=8s，重试次数 retry_cnt=3。

根据 sql_audit 信息 plan_id=61764，查看该 SQL 的物理执行计划，如下执行计划没问题，根据主键扫描。

select * from gv$ob_plan_cache_plan_explain where tenant_id=1008 and plan_id=61764 and svr_ip='10.xx.xx.108' and svr_port='2882';
1008	10.xx.xx.108	2882	61764	0	0	PHY_UPDATE	NULL	1	43	NULL
1008	10.xx.xx.108	2882	61764	1	1	 PHY_TABLE_SCAN	t_upp_txn_main	1	11	table_rows:1392052, physical_range_rows:1, logical_range_rows:1, index_back_rows:0, output_rows:1, avaiable_index_name[uk_t_upp_txn_main_channel_code,idx_t_upp_txn_main_dept_id,idx_t_upp_txn_main_query_upp_txn_recv,t_upp_txn_main], pruned_index_name[uk_t_upp_txn_main_channel_code,idx_t_upp_txn_main_dept_id,idx_t_upp_txn_main_query_upp_txn_recv]

由于该 SQL 执行计划正常，但存在很多重试，怀疑跟锁冲突有关。

通过 sql_audit 信息，根据 trace_id=YB420A3CFE6C-00061E63541D8B36-0-0 到 svr_ip=10.xxx.xxx.108 节点搜索 OBServer 日志，如下：确实存在多版本写冲突：[errcode=-6005] mvcc write conflict 冲突对应的事务： conflict_tx_id={txid:1175290189}。

根据锁冲突的事务 txid:1175290189，搜索 sql_audit 信息，找到该锁冲突事务 SQL 执行情况，如下。

select /*+ parallel(10) query_timeout(60000000)*/usec_to_time(request_time) ,svr_ip,tx_id,sid,sql_id,query_sql,elapsed_time,retry_cnt,IS_HIT_PLAN,plan_id,rpc_count,trace_id,PLAN_HASH,ret_code,QUEUE_TIME,GET_PLAN_TIME,EXECUTE_TIME,client_ip,user_client_ip,tenant_id,tenant_name,user_name,db_name from gv$ob_sql_audit a where tx_id='1175290189' order by request_time;

从以上结果可以看到，该冲突事务中第一条 SQL 正是和 update sql 都是同步一笔数据进行更新操作。

该冲突事务中，第二条 update sql 更新交易子流水表数据，执行耗时 10s，无 where 条件全表更新。

update t_upp_txn_sub set pmc_cost = 0 ,payload = '{\"endToEndNo\":\"s603601997vzrw202501091244462633850\",\"bizChannelCode\":\"01\"}'

通过以上分析，总结整个业务执行时序情况，如下。
- 2025-01-09 12:44:46.778489，事务 txid=1175290189，更新该笔数据状态为处理中 status='PROCESSING'，然后执行一个 update 全表更新 sub 表无 wherre 条件导致执行耗时 10s，最后 12:44:57 才 commit。
- 2025-01-09 12:44:48.969597，事务 txid=1175290313，更新该笔数据状态为成功 status = 'SUCCESS'，产生锁等待，不断重试。
两个事务都对同一笔流水数据进行更新，产生了行锁，由于第一个事务中对 sub 子表全表更新耗时 10s，冲突事务提交后，被阻塞的事务才成功，因此导致被阻塞事务的 update sql 多次重试，业务交易 10s 超时限制后被中断。