OceanBase 数据库事务问题排查指南

无论是在内部测试环境，还是线上运行的 OceanBase 集群，均有可能会遇到一些常见的事务报错，大体分为两大类，一类是事务执行过程中对客户端展示的错误，另一类是通过日志或内存表查询发现的环境异常。本文主要对这两大类错误进行了汇总，并总结常见的排查手段。

适用版本

OceanBase 数据库所有版本

事务问题的排查思路

对于事务常见的问题，排查手段主要包括查询事务状态表 __all_virtual_trans_stat 与搜索 observer.log 日志。

• 事务状态表 __all_virtual_trans_stat 可以查询到当前还未结束的事务上下文状态。 各主要表列的说明如下表所示。

  列名	说明
  svr_ip	表示创建该事务上下文的 OBServer 的 IP 地址。
  session_id	表示该事务上下文所属会话的唯一 ID。
  proxy_id	表示客户端 OBProxy/Java Client 对应的 IP 地址与端口号。
  trans_id	表示该事务的唯一 ID。
  is_existing	表示当前事务上下文是否正在退出。
  partition	表示当前事务上下文在哪个分区上创建。
  participants	当前事务的参与者列表。
  ctx_create_time	事务上下文的创建时间。
  ref	表示事务上下文当前的引用计数。
  sql_no	表示当前事务上下文上最后一次执行的 SQL 的 sql_no。
  state	表示事务上下文当前的状态。 可能的状态有 INIT、PREPARE、COMMIT、ABORT 与 CLEAR。
  part_trans_action	表示该事务上下文上最后执行的动作。 可能的状态有 START_TASK、END_TASK、COMMIT。
  lock_for_read_entry_count	表示该事务在表扫描过程中遇到锁冲突重试的次数。

  说明

  __all_virtual_trans_stat 展示的是整个集群中未结束事务的参与者上下文信息，包括主集群和备集群。对于使用者来说，需要通过收集当前事务的所有参与者信息，从中构造出当前整个事务的执行状态。

• 排查 observer.log 日志的方法可以分为两个维度。

  • 通过 trace_id 搜索对应时间段内的 observer.log 日志，trace 日志展示的是一条语句执行路径上的全部日志。

    例如通过 trace_id=Y404645869E7-0005A852503E9F53 搜索 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 数据库的实现中，事务超时、参与者切主都会引起事务回滚，因此在这些情况下，事务回滚可以视为正常现象。

排查事务回滚问题的步骤如下：

1. 通过对应的内部错误码到开启事务的 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={xxx.xxx.xxx.xxx: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"})
   

2. 从相关日志中，找到事务的 trans_id，并通过 trans_id 搜索相关的事务日志。

   grep "transaction killed success" *
   

3. 要找触发事务被强制停止的原因，可以尝试搜索下面两类日志。

   • 如果存在 leader revoke 信息，说明是因为切主导致的事务被回滚。 有关切主问题的排查方法，请参见 OceanBase 数据库切主强制停止正在进行的事务的原因及规避方法。

     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:"xxx.xxx.xxx.xxx: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":"xxx.xxx.xxx.xxx", 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:"xxx.xxx.xxx.xxx:29429", 
  t:1592541786499600} data_relocated=0 
  ...)
  

• 对于 Lock wait timeout exceeded，说明事务在等待行锁。有关 OceanBase 数据库排查行锁的方法，请参见 OceanBase 数据库中的行锁问题排查工具介绍。 可以搜索下面的日志，搜索 dump tenant 关键字，其中 conflict_ctx 表示持有行锁的事务。

  grep "dump tenant" observer.log
  

其它类

其它类错误码有以下六个。

• 对于错误码 4013 与 4030 的问题，请参见 OceanBase 数据库中错误代码 4013 与 4030 的区别。 可以通过搜索关键字 MEMORY 确认问题。

  grep "MEMORY" *
  

• 对于 RPC 错误码 4121、4122 与连接错误 4124，可以通过搜索 EASY SLOW 关键字确认网络延迟问题。 如果结果中存在大量日志，则说明出现了网络延迟的问题。

  grep "EASY SLOW" *
  

• 对于错误码 4019，可能是由于 OceanBase 数据库出现了异常死锁，需要执行 pstack 进行进程分析。

事务不结束问题

事务不结束的问题主要分为三类。

• 处于非提交阶段的事务。 通过查询事务虚拟表 __all_virtual_trans_stat，如果发现 state 为 0，说明处于非提交阶段。处于非提交阶段的事务如果一直没结束，存在几种可能。

  • 存在长时间执行未结束的大查询请求。通过查询该事务所有的事务上下文中的 part_trans_action 字段，如果存在处于 1 的情况，说明存在长时间执行未结束的大查询请求。

  • 如果 part_trans_action 字段为 2，说明当前语句执行报错后没有继续重试，或者是新的下一条语句一直没有继续执行。该问题有两个排查方向。

    1. 通过 dump tenant 关键字查看是否存在租户队列堆积的情况，如果存在堆积，需要分析当前租户 worker 资源配置是否合理。在合理的前提下，还出现了堆积，说明大概率存在死锁，需要 pstack 对应的 observer 进程，分析死锁问题。

    2. 如果不存在队列堆积，可能是客户端本身没有发起下一条语句，或者 OBServer 端由于没有回包等类似问题，导致客户端无法发起下一条语句。

  • 出现了事务间的死锁。有关锁冲突的排查方法，请参见 OceanBase 数据库中的行锁问题排查工具介绍。

  • 语句一直在执行报错重试。

    此时通过 trans_id 搜索对应事务的日志，找到语句重试的原因，排查是否符合预期。

• 处于提交阶段的事务。

  通过查询事务虚拟表 __all_virtual_trans_stat，如果 state 不为 0 或者 part_trans_action 为 3，说明处于提交阶段。

  处于提交阶段的事务可以通过以下步骤排查。

  1. 通过 trans_id 查询 __all_virtual_trans_stat，找到所有参与者上下文，其中 state 值最小的那个参与者，即长时间未提交的参与者。

  2. 找到长时间未提交的参与者所在的位置，通过 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	事务日志提交任务在异步提交队列中，等待后台异步提交。	同样可能是有滑动窗口超时的情况，或者是滑动窗口滑动速度过低。

     • 对于第一类异常，有可能是租户的 __all_dummy 表无主，__all_dummy 表用于提供当前租户的 GTS 服务。可以通过以下方式排查。

       其中，$dummy_id 的计算方法为 >>> $tenant_id << 40 | 135，$tenant_id 为租户 ID。

       grep "$dummy_id" election.log
       

     • 对于第二类与第三类异常，可以查询 _all_virtual_clog_stat 表，查看该分区是否无主，或者多数派副本的 is_in_sync 是否为 0。

• 处于回放阶段的事务上下文不结束。

  搜索虚拟表 __all_virtual_trans_stat，其中 ctx_create_time 等于 expired_time 的事务上下文是回放出来的事务上下文。

  对于这种情况，需要通过 partition 字段找到 Partition Leader 所在的机器，如果 Leader 的参与者上下文已经结束，说明当前事务不结束是因为备机不同步导致。

  此时查询 __all_virtual_clog_stat，通过 last_log_id 字段是否落后来推断副本是否存在日志落后的情况。

会话连接断开问题

会话连接断开有两种情况。

• 超过了 ob_trx_idle_timeout 设定的阈值。

  有关 ob_trx_idle_timeout 的详细信息，请参见《OceanBase 数据库 参考指南》中的 系统变量 参考。

• Session 无法处理现在的异常。

会话断开问题的排查方法如下。

1. 搜索 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)
   

2. 通过 session_id 找到对应的报错进行分析。