事务问题排查

无论是在内部测试环境，还是线上运行的 OceanBase 集群，都有可能会遇到一些常见的事务报错。本文主要对这常见的事务错误进行了汇总，并总结常见的排查手段。

适用版本

OceanBase 数据库所有版本

问题描述

在运行 OceanBase 的过程中，OceanBase 会执行数据库事务，在执行后将执行返回的结果返回给发出请求的客户端。如果事务执行失败或者异常，会产生事务报错。常见的事务报错大体分为两大类，一类是事务执行过程中对客户端展示的错误，另一类是通过日志或内存表查询发现的环境异常。

问题排查思路

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

查询事务状态表 __all_virtual_trans_stat

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

说明

__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]
  

• 根据 __all_virtual_trans_stat 表中的 trans_id 搜索和事务本身有关的全部日志。

  例如 trans_id:{hash:16713812224872761916, inc:334222, addr:{ip:"xxx.xxx.xx.xxx", port:xxxx}, t:1588070679938314} 中，hash 表示事务 ID 的散列值，该散列值唯一，因此可以作为事务的唯一 ID 搜索日志，addr 表示开启事务的 IP 地址，t 表示事务的开始时间。

您可以根据日志中的相关告警或报错信息进行问题定位。

问题排查步骤

在进行详细的问题跟进排查时，可以通过 __all_virtual_trans_stat 表查到的 trans_id 进行排查日志，从而找到相应事务与报错原因。

一般情况下，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)

在该信息中可以看到 err，这是 OceanBase 数据库日志中的错误标识位，其中 4038 是对应的错误码。

在 OceanBase 数据库中，事务对应的错误码可以分为以下几类：事务回滚类、执行超时类、等待锁超时类、其他类。您可以根据不同的错误码进行问题排查。

事务回滚类

事务回滚类的错误码有以下四个。

出现上述四类报错时，说明出现了事务回滚的情况。事务回滚不一定是异常，在当前 OceanBase 数据库的实现中，事务超时、参与者切主都会引起事务回滚，因此在这些情况下，事务回滚可以视为正常现象。但若需要，仍可进行事务回滚问题排查。

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

1. 定位开启事务的 OBServer 节点信息。

   1. 客户端直连

      直连的 IP 地址就是开启事务的 OBServer 的 IP 地址。

   2. 非直连

      需要根据 OBProxy 的日志来确定事务开启的机器。根据查询结果中的 server_trace_id 与 server_ip 定位对应的 OBServer。

      [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={xx.xx.xx.xx: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. 排查 __all_virtual_trans_stat 表，找到事务的 trans_id，并通过 trans_id 搜索相关的 observer.log 日志。

   grep "transaction killed success" *
   

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

   • 如果存在 leader revoke 信息，说明是因为切主导致的事务被回滚。 如下命令是查找是否存在包含 leader revoke 信息的日志。

     grep "participant leader revoke" *
     

   • 如果 trans_expired_time 小于等于事务回滚的时间点，说明是因为事务超时导致的回滚。如下命令是查找包含 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 关键字来查询当前租户队列是否存在堆积。

语句执行失败重试也会导致事务超时，相关的错误码有以下三个。

等待锁超时类

常见的等待锁超时类的错误码有以下两个。

出现等锁超时的问题，首先会出现语句超时的情况。因此排查此类问题，首先需要按照上一节提到的语句超时排查方法排查语句超时时间设置是否合理。如果语句超时时间设置合理，则需要排查所等的事务是否存在长时间不结束的情况。

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

• Lock wait timeout exceeded 报错，说明事务在等待行锁。

  可以搜索下面的日志，搜索 dump tenant 关键字，其中 conflict_ctx 表示持有行锁的事务。

  grep "dump tenant" observer.log
  

其它类

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

• 错误码 4013 与 4030

  可以通过搜索关键字 MEMORY 确认问题。

  grep "MEMORY" *
  

• 错误码 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，说明当前语句执行报错后没有继续重试，或者是新的下一条语句一直没有继续执行。该问题有两个排查方向：

    • 租户队列堆积

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

    • 租户队列不堆积

      此时，可能是客户端本身没有发起下一条语句，或者 OBServer 端由于没有回包等类似问题，导致客户端无法发起下一条语句，请排查是否有死锁。若语句一直在执行报错重试，此时通过 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	事务日志提交任务在异步提交队列中，等待后台异步提交。	同样可能是有滑动窗口超时的情况，或者是滑动窗口滑动速度过低。

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

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

     grep "$dummy_id" election.log
     

     b. 对于第二类与第三类异常，可以查询 _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 找到对应的报错进行分析。