无论是在内部测试环境，还是线上运行的 OceanBase 集群，均有可能会遇到一些常见的事务报错，大体分为两大类，一类是事务执行过程中对客户端展示的错误，另一类是通过日志或内存表查询发现的环境异常。本文主要对这两大类错误进行了汇总，并总结常见的排查手段。
适用版本
OceanBase 数据库所有版本
事务问题的排查思路
对于事务常见的问题，排查手段主要包括查询事务状态表
__all_virtual_trans_stat
与搜索
observer.log
日志。
observer.log.20200618102440:[2020-06-18 10:24:38.213870] WARN [STORAGE.TRANS] set (ob_memtable.cpp:354) [509976][2170][Y404645869E7-0005A852503E9F53] [lt=10] [dc=0]
-
通过
trans_id
日志来搜索和事务本身有关的全部日志。
-
例如
trans_id:{hash:16713812224872761916, inc:334222, addr:{ip:“xxx.xxx.xx.xxx”, port:xxxx}, t:1588070679938314}
中，
hash
表示事务 ID 的散列值，该散列值唯一，因此可以作为事务的唯一 ID 搜索日志，
addr
表示开启事务的 IP 地址，
t
表示事务的开始时间。
字数限制，下接评论区——————
事务问题的错误码
一般情况下，OceanBase 数据库会通过 Error Packet 判断报错的 SQL，而 SQL 报错在日志中表现形式如下所示。
observer.log.20200727141140:[2020-07-27 14:11:39.217574] INFO [SERVER] obmp_base.cpp:1189 [68642][2036][YCB200BA65045-0005AB63DE657563] [lt=7] [dc=0] sending error packet(err=-4038, bt="0xb87c095 0x748e365 0x80358b4 0x74aaa46 0x802efac 0x802abff 0xb9c269d 0x809cfaa 0x809c64c 0x80984c1 0x8097819 0x30ee977 0x30ee81c 0x2b9ba7d 0xb67f8f3 0xb67d664 0xb67c7ee", extra_err_info=NULL)
可以通过对应的
TRACE_ID
找到对应事务与报错原因。
出现上述四类报错时，说明出现了事务回滚的问题。事务回滚不一定是异常，在当前 OceanBase 数据库的实现中，事务超时、参与者切主都会引起事务回滚，因此在这些情况下，事务回滚可以视为正常现象。
排查事务回滚问题的步骤如下：
- 通过对应的内部错误码到开启事务的 OBServer 上搜索相关的日志。 对于客户端直连的情况，直连的 IP 地址就是开启事务的 OBServer 的 IP 地址。 对于非直连的情况，需要根据 OBProxy 的日志来确定事务开启的机器。这种情况下，根据查询结果中的
server_trace_id
与 server_ip
到对应的 OBServer 上搜索 observer.log
日志。
[2020-06-16 03:30:01.224301] WARN [PROXY.SM] print_mysql_complete_log (ob_mysql_sm.cpp:3026) [105108][Y0-7F5E9AC56310] [lt=30] [dc=0]
finishing mysql tunnel((sm_id=799, cs_id=3244036, proxy_sessid=7230649605627118303,
ss_id=5594, server_sessid=3222037518, client_ip={100.88.109.129:56253},
server_ip={xxx.xxx.xx.xxx:xxxx}, server_trace_id=Y404645869E7-0005A852503E9F53,
proxy_user_name=test@xyoracle#ob96.hudson, database_name=TEST,
is_flow_controlled=false, cpu_flow_control_count=0, memory_flow_control_count=0,
sql=SELECT d_tax, d_next_o_id FROM bmsql_district
WHERE d_w_id = 706 AND d_id = 10 FOR UPDATE, sql_cmd="Query",
result={is_trans_completed:false, is_resp_completed:true,
ending_type:2, is_partition_hit:false, has_new_sys_var:false,
has_proxy_idc_name_user_var:false, is_server_db_reset:false, reserved_len:0,
connection_id:0, scramble_buf:"", is_resultset_resp:false,
server_capabilities_lower_.capability:0, ok_packet_action_type:2,
last_ok_pkt_len:86, rewritten_last_ok_pkt_len:0, error_pkt:field_count:255,
errcode:1205, sqlstate:"HY000", message:"Lock wait timeout exceeded;
try restarting transaction"})
- 从相关日志中，找到事务的
trans_id
，并通过 trans_id
搜索相关的事务日志。
grep "transaction killed success" *
- 要找触发事务被强制停止的原因，可以尝试搜索下面两类日志：
grep "participant leader revoke" *
- 如果
trans_expired_time
小于等于事务回滚的时间点，说明是因为事务超时导致的回滚。
grep "trans_expired_time" *
执行超时类
常见的事务执行超时类的错误码有以下两个。
对于语句超时的情况，首先要确定当前租户下
ob_query_timeout
变量设置，然后根据
trace_id
搜索
observer.log
日志，找到当前语句的
cur_query_start_time
，如果超时时间点减去
cur_query_start_time
的值等于
ob_query_timeout
，说明是符合预期的，否则请联系 OceanBase 技术支持。
对于事务超时的情况，首先要确定，当前事务的 SQL 数目，是否出现重试，当前租户队列是否有堆积等情况。 可以通过搜索
dump tenant
关键字来查询当前租户队列是否存在堆积。有关
observer.log
日志的
dump tenant
相关的信息，请参见
observer.log 中 dump tenant 介绍。
语句执行失败重试也会导致事务超时，相关的错误码有以下三个。
等待锁超时类
常见的等待锁超时类的错误码有以下两个。
出现等锁超时的问题，首先会出现语句超时的情况。因此排查此类问题，首先需要按照上一节提到的语句超时排查方法排查语句超时时间设置是否合理。如果语句超时时间设置合理，则需要排查所等的事务是否存在长时间不结束的情况。
- 对于
Shared lock conflict
报错的请求，读请求正在等待另一个事务的提交。可以搜索下面的日志，查询未结束的事务。 其中 conflict_ctx
表示持有行锁的事务上下文信息，rowkey_object
表示是冲突的行。
grep "lock_for_read fail" *
observer.log:[2020-06-19 19:36:00.681313] WARN [STORAGE.TRANS] lock_for_read
(ob_mvcc_row.cpp:1120) [39644][3862][Y72F564587653-0005A86771DBF02A] [lt=22] [dc=0]
lock_for_read fail((ret=-6004, ctx=alloc_type=0 ctx_descriptor=7941866
...
pkey={tid:1102810162659511, partition_id:0, part_cnt:0}
trans_id={hash:10466628054523668402, inc:4098058, addr:"100.88.118.83:29429",
t:1592566558782644} data_relocated=0 relocate_cnt=0 truncate_cnt=0
trans_mem_total_size=0 callback_alloc_count=0 callback_free_count=0
callback_mem_used=0 checksum_log_id=0, *key=table_id=1102810162659511
rowkey_object=[{"BIGINT":1003},{"BIGINT":1102810162709409},{"BIGINT":519},
{"VARCHAR":"100.88.118.83", collation:"utf8mb4_general_ci"},{"BIGINT":29429}] ,
conflict_id=3155625, conflict_ctx="alloc_type=0 ctx_descriptor=3155625
trans_start_time=1592541786500368 min_table_version=640 max_table_version=640
...
stmt_timeout=1897924
abs_lock_wait_timeout=1592541788399623 row_purge_version=0
lock_wait_start_ts=0 trx_lock_timeout=-1 end_code=0
is_readonly=false ref=0 pkey={tid:1102810162659511, partition_id:0, part_cnt:0}
trans_id={hash:13185011132747685805, inc:1187948, addr:"100.88.118.83:29429",
t:1592541786499600} data_relocated=0
...)
grep "dunp tenant" observer.log
- 处于提交阶段的事务。
- 通过查询事务虚拟表
__all_virtual_trans_stat
，如果 state
不为 0
或者 part_trans_action
为 3
，说明处于提交阶段。 - 处于提交阶段的事务可以通过以下步骤排查：
- 通过
trans_id
查询 __all_virtual_trans_stat
，找到所有参与者上下文，其中 state
值最小的那个参与者，即长时间未提交的参与者。 - 找到长时间未提交的参与者所在的位置，通过
trans_id
搜索相关的上下文日志。 - 例如，参与者的事务日志如下图所示：
![事务问题排查指南]()
关注红框中的标记字段，取值如下表所示：- 字段信息
- 说明
- 对应的问题
- is_gts_waiting:true
- 提交日志过程中，在等最新的 GTS。
- GTS 刷新出现了问题。
- is_submig_log_pending_count:0is_submit_log_count:1
- 事务日志提交到 clog 后，clog 一直没有回调，说明滑动窗口超时。
- 可能有多数派的副本出现问题了。问题原因可能是磁盘满、网络故障或者内存超限。
- is_submig_log_pending_count:1is_submit_log_count:1
- 事务日志提交任务在异步提交队列中，等待后台异步提交。
- 同样可能是有滑动窗口超时的情况，或者是滑动窗口滑动速度过低。
grep "$dummy_id" election.log
- 对于第二类与第三类异常，可以查询
_all_virtual_clog_stat
表，查看该分区是否无主，或者多数派副本的 is_in_sync
是否为 0。
会话连接断开问题
会话连接断开有两种情况：
- 超过了
ob_trx_idle_timeout
设定的阈值。 - 有关
ob_trx_idle_timeout
的详细信息，请参见《OceanBase 数据库 参考指南》中的 系统变量 参考。 - Session 无法处理现在的异常。
会话断开问题的排查方法如下：
- 搜索
session is kill
关键字找到报错的 session_id
。
$ grep 'session is kill' observer.log.2*
observer.log.20200908141837:[2020-09-08 14:14:50.416162] WARN [SQL.SESSION] set_session_state (ob_basic_session_info.cpp:4084) [4830][0][Y0-0000000000000000] [lt=9] [dc=0] session is killed(ret=-5066, sessid_=3222146964, proxy_sessid_=0, version_=0, state=4)
observer.log.20200908141837:[2020-09-08 14:14:50.416418] WARN [SQL.SESSION] set_session_state (ob_basic_session_info.cpp:4084) [4832][0][Y0-0000000000000000] [lt=8] [dc=0] session is killed(ret=-5066, sessid_=3222146965, proxy_sessid_=0, version_=0, state=4)
observer.log.20200908144919:[2020-09-08 14:46:30.425385] WARN [SQL.SESSION] set_session_state (ob_basic_session_info.cpp:4084) [4825][0][Y0-0000000000000000] [lt=10] [dc=0] session is killed(ret=-5066, sessid_=3222154297, proxy_sessid_=0, version_=0, state=4)
- 通过
session_id
找到对应的报错进行分析。
