OceanBase 学习笔记111：如何基于 Trace 功能查找上一次 SQL 请求日志？

OceanBase 数据库支持基于 Trace 功能快速获取上一次 SQL 请求的完整日志。

为了便于查找目标 SQL 请求日志，您可提前通过设置日志打印级别来减少 SQL 模块之外的日志的打印。有关日志打印级别的相关设置请参见 设置日志打印级别。

具体操作步骤如下：

1. 开启 Trace 功能。

   可通过如下两种方式来开启 Trace 功能：

   • 通过设置 Hint中的 trace_log 字段来开启 Trace 功能。这种方式只对携带 Hint 的当前语句生效。更多 Hint 语句相关的介绍，请参见《 SQL 调优指南》中的 Optimizer Hint 。

     obclient > SELECT /*+trace_log=on*/c1 FROM t1 LIMIT 2;
     

   • 通过设置 Session 变量 ob_enable_show_trace 来开启 Trace 功能。这种方式对本 Session 的后续所有语句生效。

     obclient > SET ob_enable_show_trace='ON';
     

2. 获取上一次 SQL 请求日志的 trace_id 。

   开启 Trace 功能并执行 SQL 请求后，通过 SHOW TRACE 语句可获取上一次 SQL 请求日志的 trace_id 。

   obclient> SHOW TRACE;
   +------------------------------+----------------------------------------------------------------------------+------+
   | Title                        | KeyValue                                                                   | Time |
   +------------------------------+----------------------------------------------------------------------------+------+
   | process begin                | in_queue_time:12, receive_ts:1623988240448815, enqueue_ts:1623988240448816 | 0    |
   | query begin                  | trace_id:YC1E64586A5D-0005C4C77E56FA98                                     | 2    |
   | parse begin                  | stmt:"select count(*) from t1", stmt_len:23                                | 49   |
   | pc get plan begin            |                                                                            | 7    |
   | pc get plan end              |                                                                            | 18   |
   | transform_with_outline begin |                                                                            | 2    |
   | transform_with_outline end   |                                                                            | 45   |
   | resolve begin                |                                                                            | 22   |
   | resolve end                  |                                                                            | 130  |
   | transform begin              |                                                                            | 40   |
   | transform end                |                                                                            | 138  |
   | optimizer begin              |                                                                            | 2    |
   | get location cache begin     |                                                                            | 96   |
   | get location cache end       |                                                                            | 108  |
   | optimizer end                |                                                                            | 272  |
   | cg begin                     |                                                                            | 0    |
   | cg end                       |                                                                            | 984  |
   | execution begin              | arg1:false, end_trans_cb:false                                             | 78   |
   | do open plan begin           | plan_id:197                                                                | 29   |
   | sql start stmt begin         |                                                                            | 1    |
   | sql start stmt end           |                                                                            | 1    |
   | execute plan begin           |                                                                            | 0    |
   | execute plan end             |                                                                            | 9    |
   | sql start participant begin  |                                                                            | 0    |
   | sql start participant end    |                                                                            | 1    |
   | do open plan end             |                                                                            | 0    |
   | table scan begin             |                                                                            | 11   |
   | table scan end               |                                                                            | 42   |
   | start_close_plan begin       |                                                                            | 1344 |
   | start_end_participant begin  |                                                                            | 13   |
   | start_end_participant end    |                                                                            | 1    |
   | start_close_plan end         |                                                                            | 1    |
   | start_auto_end_plan begin    |                                                                            | 2    |
   | start_auto_end_plan end      |                                                                            | 1    |
   | execution end                |                                                                            | 2    |
   | query end                    |                                                                            | 52   |
   | NULL                         | PHY_SCALAR_AGGREGATE                                                       |      |
   | t1                           |  PHY_TABLE_SCAN                                                            |      |
   +------------------------------+----------------------------------------------------------------------------+------+
   38 rows in set (0.01 sec)
   

   Time 字段表示当前该步骤花费的时间，单位是微秒。例如： pc get plan end 的 Time 字段显示为 18us ，表示 OceanBase 数据库从 Plan Cache 中获取一条执行计划花费了 18us 。

3. 通过 trace_id 在日志文件查询上一次 SQL 请求的完整日志。

   OceanBase 数据库日志打印时均会携带 trace_id ，通过在日志文件（ observer.log、election.log 和 rootservice.log ）中搜索对应的 trace_id ，可以获取上一次 SQL 请求的完整日志。

   grep $trace_id observer.log
   

   例如：获取 trace_id 为 YB42AC1E87ED-0005C6866C3BAFB1-0-0 的日志。

   grep YB42AC1E87ED-0005C6866C3BAFB1-0-0 observer.log
   observer.log: [2021-07-15 14:05:11.218141] WARN  [SQL] execute_get_plan (ob_sql.cpp:3159) [119331][0][YB42AC1E87ED-0005C6866C3BAFB1-0-0] [lt=5] [dc=0] fail to get plan retry(ret=-5138)