事务超时问题排查指南

与 Oracle 数据库不同，在 OceanBase 数据库中存在事务超时的概念，可理解为事务可正常运行的最长时间。超过该时间后，事务仍会占有 session，因此新进入该 session 的 SQL 均会报错，直到用户执行 ROLLBACK 回滚事务。

事务超时时间在 V3.x 默认为 100s，而在 V4.x 默认为 1 天，可通过以下两种语句来设置超时时间。

• 修改当前 session 超时时间。

  obclient> set session ob_trx_timeout = 200000000;
  

• 设置全局超时时间，只对新创建的 session 生效，旧 session 需断开重连才能获取新值。

  obclient> set global ob_trx_timeout = 200000000;
  

排查方法

1. 搜索日志，找到报错点获取 trans_id，搜索 trans_id 获取事务超时时间。

   • OceanBase 数据库 V3.x 版本，执行如下命令。

     grep -rn “hash:1099511627906” ./observer.log* | vim -
     

     如果没找到，可以在 rootservice.log 中查找。

     grep -rn “hash:1099511627906” ./rootservice.log* | vim -
     

     判断以下两点：

     • 通过 trans_id 中的 t（即为事务开始时间）和事务设置超时间隔判断事务超时时间是否准确。
     • 事务报错点是否已经到达事务超时时间。

   • OceanBase 数据库 V4.x 版本，执行如下命令。

     如果有事务超时 SQL 的 trace_id，根据 trace_id 进行过滤 observer 日志，寻找 tx desc trace。

     grep 'YFD9645869C3-0005ED07C7BF9E31' observer.log.20221109203721644 | grep -F '[tx desc trace]'
     

     也可以根据事务 ID 进行查找，如下：1004 租户的 655 号事务，事务 ID 在租户内唯一。

     grep -F '[T1004]' observer.log.20221109203721644 | grep -F 'txid:{txid:655}' | grep -F '[tx desc trace]'
     

     找到事务 trace 后可以看到事务整体生命周期：

     (TRACE=begin_ts=1667993839393067 2022-11-09 11:37:19.393067
     [reuse] u=0 ret:0, addr:0x7efe215de830, txid:{txid:579}, thread_id:117848
     [create_global_implicit_savepoint] u=1197105 ret:0, txid:{txid:655}, savepoint:1667993840589454, release:true, opid:2, ref:2, thread_id:117882
     [create_global_implicit_savepoint] u=4132579 ret:0, txid:{txid:655}, savepoint:1667993844722419, release:true, opid:3, ref:2, thread_id:28864
     [create_global_implicit_savepoint] u=11293538 ret:0, txid:{txid:655}, savepoint:1667993856015606, release:true, opid:4, ref:2, thread_id:117863
     [create_global_implicit_savepoint] u=301610890 ret:0, txid:{txid:655}, savepoint:1667994157626350, release:true, opid:5, ref:2, thread_id:117875
     [create_global_implicit_savepoint] u=157057679 ret:0, txid:{txid:655}, savepoint:1667994314684531, release:true, opid:6, ref:2, thread_id:42556
     [create_global_implicit_savepoint] u=409584664 ret:0, txid:{txid:655}, savepoint:1667994724268515, release:true, opid:7, ref:2, thread_id:35915
     [create_global_implicit_savepoint] u=596163300 ret:0, txid:{txid:655}, savepoint:1667995320432291, release:true, opid:8, ref:2, thread_id:35894
     [create_global_implicit_savepoint] u=783093033 ret:0, txid:{txid:655}, savepoint:1667996103525395, release:true, opid:9, ref:2, thread_id:43436
     [create_global_implicit_savepoint] u=527212400 ret:0, txid:{txid:655}, savepoint:1667996630737949, release:true, opid:10, ref:2, thread_id:42556
     [create_global_implicit_savepoint] u=240061108 ret:0, txid:{txid:655}, savepoint:1667996870798752, release:true, opid:11, ref:2, thread_id:31113
     [create_global_implicit_savepoint] u=136148286 ret:0, txid:{txid:655}, savepoint:1667997006947347, release:true, opid:12, ref:2, thread_id:42556
     [create_global_implicit_savepoint] u=131774359 ret:0, txid:{txid:655}, savepoint:1667997138721736, release:true, opid:13, ref:2, thread_id:40763
     [add_tx_exec_result] u=1797 opid:13, num:1, flag:false, thread_id:40763
     [create_global_implicit_savepoint] u=134803339 ret:0, txid:{txid:655}, savepoint:1667997273527045, release:true, opid:14, ref:2, thread_id:117875
     total_timeu=3434134077)
     

     事务开始时间就是 begin 时间，可以据此判断是否真的发生了事务超时，上述示例值班中每create_global_implicit_savepoint 对应一个 SQL 的 DML 语句。可以看出，2 个 DML 语句之间间隔很长，说明 SQL 执行很慢。

2. 分析业务模型。

   当超时无异常时，需分析业务模型，判断事务超时是否符合预期。

   通过查询 gv$sql_audit 可获取该事务相关执行 SQL 的信息，但因 sql_audit 有刷新机制，因此不能保证一定能获取结果，因此可以执行如下命令先关闭 SQL 审计，保证执行的语句在内存中不被刷掉。

   obclient> ALTER SYSTEM SET enable_sql_audit=0;
   

   获取本事务的SQL语句如下：

   • OceanBase 数据库 V3.x 版本。

     obclient> select usec_to_time(request_time),query_sql,elapsed_time from oceanbase.__all_virtual_sql_audit where tenant_id = 1004 and transaction_hash = xxx;
     

   • OceanBase 数据库 V4.x 版本。

     obclient> select usec_to_time(request_time),query_sql,elapsed_time from oceanbase.__all_virtual_sql_audit 
             where tenant_id = 1004 and transaction_id = xxx; 
     

常见错误使用场景

• 场景一：设置了 autocommit=0，导致大量 SQL 在一个事务内执行。

  需要根据日志中获取的 session id 查找 gv$sql_audit 来判断是否存在非预期的设置。

• 场景二：存在大事务，未调大事务超时时间，分析业务模型以获取预估时间，可通过拆分成小事务或调大超时时间解决。

• 场景三：SQL 运行慢或因为网络等原因导致 msg 处理慢从而造成非预期的运行时间增加导致最终未在事务有效期内执行完毕。

解决方法

• 执行如下语句将该 session 执行的 SQL 语句按照执行时间排序。

  obclient> select * from gv$sql_audit where SID = ... AND REQUEST_TIME > (事务开始时间) ORDER BY ELAPSED_TIME DESC;
  

可通过 OCP 监控或 tsar 来判断环境或 OBServer 是否出现异常。后续需联系技术支持具体分析。