OceanBase 数据库集群配置项 enable_record_trace_log 的使用说明

enable_record_trace_log 配置项用于设置是否记录追踪日志。具体来说，当一条 SQL 在 OBServer 端的执行耗时超过一定的阈值后（对应系统配置项 trace_log_slow_query_watermark），该 SQL 会被标记为慢 SQL 并被记录到 OBServer 的运行日志中去。本文介绍该参数的开启、关闭方法，主要作用和最佳实践。

详细说明

参数说明

示例如下。

MySQL [oceanbase]> show parameters like 'enable_record_trace_log'; -- specifies whether to always record the trace log. The default value is True.用于设置是否记录追踪日志。生产环境在开启 Perf Event(enable_perf_event)和SQL Audit(enable_sql_audit) 功能的情况下，为性能考虑此参数可以考虑关闭。默认值：True。CLUSTER 集群级别/DYNAMIC_EFFECTIVE 动态生效
+-------+----------+---------------+----------+-------------------------+-----------+-------+------------------------------------------------------------------------------+----------+---------+---------+-------------------+
| zone  | svr_type | svr_ip        | svr_port | name                    | data_type | value | info                                                                         | section  | scope   | source  | edit_level        |
+-------+----------+---------------+----------+-------------------------+-----------+-------+------------------------------------------------------------------------------+----------+---------+---------+-------------------+
| zone2 | observer | xx.xxx.80.115 |     2882 | enable_record_trace_log | NULL      | True  | specifies whether to always record the trace log. The default value is True. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
| zone1 | observer | xx.xxx.80.111 |     2882 | enable_record_trace_log | NULL      | True  | specifies whether to always record the trace log. The default value is True. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
| zone3 | observer | xx.xxx.80.168 |     2882 | enable_record_trace_log | NULL      | True  | specifies whether to always record the trace log. The default value is True. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
+-------+----------+---------------+----------+-------------------------+-----------+-------+------------------------------------------------------------------------------+----------+---------+---------+-------------------+
3 rows in set (0.01 sec)

开启、关闭方法

• 开启方法。

  -- 连接到 root@sys 系统租户后执行
  MySQL [oceanbase]> ALTER SYSTEM SET enable_record_trace_log=True;
  Query OK, 0 rows affected (0.01 sec)
  
  -- 或者
  MySQL [oceanbase]> ALTER SYSTEM SET enable_record_trace_log=1;
  Query OK, 0 rows affected (0.01 sec)
  

• 关闭方法。

  -- 连接到 root@sys 系统租户后执行：
  MySQL [oceanbase]> ALTER SYSTEM SET enable_record_trace_log=False;
  Query OK, 0 rows affected (0.01 sec)
  
  -- 或者
  MySQL [oceanbase]> ALTER SYSTEM SET enable_record_trace_log=0;
  Query OK, 0 rows affected (0.01 sec)
  

主要作用

enable_record_trace_log 参数的主要作用是将 OBServer 端的慢 SQL 执行日志都记录到 observer.log 日志中去。因此，如果把 enable_record_trace_log 参数设置 false，会导致在 observer.log 日志中查看不到 slow query 的信息。

1. 执行测试。

   MySQL [test]> system date ; select sleep(90) from dual ; system date;
   Wed Mar 19 20:47:38 CST 2025
   +-----------+
   | sleep(90) |
   +-----------+
   |         0 |
   +-----------+
   1 row in set (1 min 30.001 sec)
   
   Wed Mar 19 20:49:08 CST 2025
   

2. 查看对应的 observer.log 中慢查询日志。

   [admin@observer /home/admin/oceanbase/log]$ grep 'slow query' observer.log.20250319205059937 | grep -i sleep
   [2025-03-19 20:49:08.248970] TRACE [TRACE] after_process (obmp_base.cpp:145) [99562][T1002_L0_G100][T1002][XXXXX-XXXXX-XXXXX-XXXXX] [lt=15] [slow query](TRACE=begin_ts=1742388458248587 2025-03-19 12:47:38.248587|[process_begin] u=0 in_queue_time:264, receive_ts:1742388458248309, enqueue_ts:1742388458248552|[start_sql] u=1 addr:{ip:"xx.xxx.80.168", port:26502}|[query_begin] u=1 trace_id:XXXXX-XXXXX-XXXXX-XXXXX|[before_processor_run] u=9 |[session] u=4 sid:3221616881, tenant_id:1002|[parse_begin] u=77 stmt:"select sleep(90) from dual", stmt_len:26|[pc_choose_plan] u=30 |[check_priv] u=3 |[plan_id] u=9 plan_id:4920|[do_open_plan_begin] u=5 plan_id:4920|[sql_start_stmt_begin] u=2 |[sql_start_stmt_end] u=1 |[exec_plan_begin] u=0 |[exec_plan_end] u=3 |[do_open_plan_end] u=0 |[value_start_calc_row] u=6 |[value_after_calc_row] u=0 |[close_plan_begin] u=90000098 |[start_end_stmt] u=63 |[end_stmt] u=0 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:-1|[store_found_rows] u=1 found_rows:0, return_rows:1|[auto_end_plan_begin] u=2 |[auto_end_plan_end] u=2 |[query_end] u=43 |[session] u=9 sid:3221616881, tenant_id:1002|[process_end] u=10 run_ts:1742388458248598|total_timeu=90000380)
   
   MySQL [test]> select usec_to_time(1742388458248598);
   +--------------------------------+
   | usec_to_time(1742388458248598) |
   +--------------------------------+
   | 2025-03-19 20:47:38.248598     |
   +--------------------------------+
   1 row in set (0.002 sec)
   

3. 解读该慢查询日志。

   [admin@observer /home/admin/oceanbase/log]$ grep 'slow query' observer.log.20250319205059937 | grep -i sleep | sed 's/|\[/\n\[/g'
   [2025-03-19 20:49:08.248970] TRACE [TRACE] after_process (obmp_base.cpp:145) [99562][T1002_L0_G100][T1002][XXXXX-XXXXX-XXXXX-XXXXX] [lt=15] [slow query](TRACE=begin_ts=1742388458248587 2025-03-19 12:47:38.248587
   [process_begin] u=0 in_queue_time:264, receive_ts:1742388458248309, enqueue_ts:1742388458248552
   [start_sql] u=1 addr:{ip:"xx.xxx.80.168", port:26502}
   [query_begin] u=1 trace_id:XXXXX-XXXXX-XXXXX-XXXXX
   [before_processor_run] u=9
   [session] u=4 sid:3221616881, tenant_id:1002
   [parse_begin] u=77 stmt:"select sleep(90) from dual", stmt_len:26
   [pc_choose_plan] u=30
   [check_priv] u=3
   [plan_id] u=9 plan_id:4920
   [do_open_plan_begin] u=5 plan_id:4920
   [sql_start_stmt_begin] u=2
   [sql_start_stmt_end] u=1
   [exec_plan_begin] u=0
   [exec_plan_end] u=3
   [do_open_plan_end] u=0
   [value_start_calc_row] u=6
   [value_after_calc_row] u=0
   [close_plan_begin] u=90000098
   [start_end_stmt] u=63
   [end_stmt] u=0
   [close_plan_end] u=0
   [affected_rows] u=1 affected_rows:-1
   [store_found_rows] u=1 found_rows:0, return_rows:1
   [auto_end_plan_begin] u=2
   [auto_end_plan_end] u=2
   [query_end] u=43
   [session] u=9 sid:3221616881, tenant_id:1002
   [process_end] u=10 run_ts:1742388458248598|total_timeu=90000380)
   

   • [exec_plan_begin]：每个方框号（[]）中的文字表示该 SQL 执行经过的每一个内部模块。

   • trace_id：执行该SQL语句对应的 trace_id，您可以通过该 ID 从日志中搜索语句的执行信息。与 gv$sql_audit/gv$ob_sql_audit 视图里面的 trace_id 字段对应。

   • stmt：具体执行的 SQL 语句。

   • u：代表每一步消耗的时间，单位是微秒。

   • total_timeu： 是指整个过程消耗的总时间，单位是微秒，这里是 90000380us，即 90s。

4. 关闭 enable_record_trace_log 配置项。

   -- 连接到 root@sys 系统租户后执行，动态生效
   MySQL [oceanbase]> ALTER SYSTEM SET enable_record_trace_log=0;
   Query OK, 0 rows affected (0.01 sec)
   

5. 执行一条慢 SQL。

   MySQL [test]> system date ; select sleep(90) from dual ; system date;
   Wed Mar 19 21:02:53 CST 2025
   +-----------+
   | sleep(90) |
   +-----------+
   |         0 |
   +-----------+
   1 row in set (1 min 30.001 sec)
   Wed Mar 19 21:04:23 CST 2025
   

6. 查看慢查询记录。

   [admin@observer /home/admin/oceanbase/log]$ grep 'slow query' observer.log.20250319210159142 observer.log | grep -i sleep
   [admin@observer /home/admin/oceanbase/log]$
   

   可知关闭 enable_record_trace_log 配置项后，observer.log 中不再记录慢查询了。

最佳实践

1. PoC 性能压测环境和生产环境在开启 Perf Event（对应 enable_perf_event 配置项）和 SQL Audit（对应 enable_sql_audit 配置项）功能的情况下，为追求更优性能可以考虑关闭此参数。

2. 目前通过 OCP Web 界面部署的 OceanBase 数据库 V4.x 集群，无论选择哪种负载类型（注意：V4.2.5+、V4.3.2+ 才支持设置负载类型），默认都会把集群级别的 enable_record_trace_log 参数设置为 False。

   

备注

一条 SQL 被 OBServer 标记为慢查询的时间阈值受系统配置项 trace_log_slow_query_watermark 控制，当一条 SQL 在 OBServer 端的执行时间超过该阈值就被认为是慢查询，慢查询的追踪日志会被打印到 observer.log 运行日志中。

在内部测试时，为捕获业务执行的 SQL 模型，可以将这个 trace_log_slow_query_watermark 设置成最小值 1ms，这样一来几乎所有执行过的 SQL 都会在 observer.log 中记录 slow query 日志。

MySQL [oceanbase]> ALTER SYSTEM trace_log_slow_query_watermark = '1ms';

影响租户

影响 OceanBase 数据库中的 SYS 租户和 Oracle 租户以及 MySQL 租户。

适用版本

OceanBase 数据库所有版本。