查找特定 SQL 请求的日志

OceanBase 数据库支持查找特定 SQL 请求的相关日志，受限于当前系统日志级别，及具体的 SQL 异常场景，不一定总是能在日志文件中找到对应 SQL 请求的日志，但总是值得我们试一试。

查找特定 SQL 请求的日志，在可观测性领域是一项非常有用的技术。基本技术点在于通过节点 IP 和 TRACE_ID 到日志文件中检索日志，从而捕捉蛛丝马迹，并按图索骥打通全链路，找到第一案发现场。其亮点在于具备“事后”和“全链路”两大属性，是监控指标的有力补充。监控指标善于异常发现，而系统日志善于发现细节和全链路跟踪。

操作步骤

1. 登录 OceanBase 集群，执行以下 SQL，该 SQL 会报错。

   obclient> select timestamp'0001-01-33';
   ERROR 1525 (HY000): Incorrect DATETIME value: '0001-01-33'
   

   注意

   此处的执行 SQL 仅为示意，实际工作中 SQL 一般由应用系统执行，某些情况下出现异常，例如返回错误码，或者耗时很高。应用人员联系运维人员协助定位问题。

2. 登录系统租户，通过 GV$OB_SQL_AUDIT 视图查询该 SQL 的执行信息。

   注意

   如果 GV$OB_SQL_AUDIT 查询不到结果，请检查是否关闭了 audit 功能, 即 enable_sql_audit 配置项是否设置为了 False。有关 enable_sql_audit 配置项的详细信息，参见 enable_sql_audit。

   obclient> select * from gv$ob_sql_audit where query_sql like '%select timestamp%' limit 1\G
   *************************** 1. row ***************************
                           SVR_IP: xx.xx.xx.158
                       SVR_PORT: 2882
                       REQUEST_ID: 374223576
                       SQL_EXEC_ID: 389174628
                       TRACE_ID: YB4206019C9E-0005F55950FFAF04-0-0
                               SID: 3222268068
                       CLIENT_IP: xx.xx.xx.88
                       CLIENT_PORT: 54896
                       TENANT_ID: 1
                       TENANT_NAME: sys
               EFFECTIVE_TENANT_ID: 1
                           USER_ID: 200001
                       USER_NAME: dba_read
                       USER_GROUP: 0
                   USER_CLIENT_IP: xx.xx.xx.113
                           DB_ID: 201001
                           DB_NAME: oceanbase
                           SQL_ID: 86CC23B2B299FFAB9C50809C7238E891
                       QUERY_SQL: select timestamp'0001-01-33'
                           PLAN_ID: 0
                   AFFECTED_ROWS: 0
                       RETURN_ROWS: 0
                   PARTITION_CNT: 0
                       RET_CODE: -5241
                           QC_ID: 0
                           DFO_ID: 0
                           SQC_ID: 0
                       WORKER_ID: 0
                           EVENT:
                           P1TEXT:
                               P1: 0
                           P2TEXT:
                               P2: 0
                           P3TEXT:
                               P3: 0
                           LEVEL: 0
                   WAIT_CLASS_ID: 100
                       WAIT_CLASS#: 0
                       WAIT_CLASS: OTHER
                           STATE: MAX_WAIT TIME ZERO
                   WAIT_TIME_MICRO: 0
           TOTAL_WAIT_TIME_MICRO: 0
                       TOTAL_WAITS: 0
                       RPC_COUNT: 0
                       PLAN_TYPE: 0
                   IS_INNER_SQL: 0
                   IS_EXECUTOR_RPC: 0
                       IS_HIT_PLAN: 0
                   REQUEST_TIME: 1678603660669976
                   ELAPSED_TIME: 254
                       NET_TIME: 0
                   NET_WAIT_TIME: 2
                       QUEUE_TIME: 53
                       DECODE_TIME: 0
                   GET_PLAN_TIME: 158
                   EXECUTE_TIME: 4
           APPLICATION_WAIT_TIME: 0
           CONCURRENCY_WAIT_TIME: 0
               USER_IO_WAIT_TIME: 0
                   SCHEDULE_TIME: 0
                   ROW_CACHE_HIT: 0
           BLOOM_FILTER_CACHE_HIT: 0
                   BLOCK_CACHE_HIT: 0
                       DISK_READS: 0
                       RETRY_CNT: 0
                       TABLE_SCAN: 0
               CONSISTENCY_LEVEL: -1
           MEMSTORE_READ_ROW_COUNT: 0
           SSSTORE_READ_ROW_COUNT: 0
               DATA_BLOCK_READ_CNT: 0
           DATA_BLOCK_CACHE_HIT: 0
           INDEX_BLOCK_READ_CNT: 0
           INDEX_BLOCK_CACHE_HIT: 0
               BLOCKSCAN_BLOCK_CNT: 0
               BLOCKSCAN_ROW_CNT: 0
   PUSHDOWN_STORAGE_FILTER_ROW_CNT: 0
               REQUEST_MEMORY_USED: 65536
           EXPECTED_WORKER_COUNT: 0
               USED_WORKER_COUNT: 0
                       SCHED_INFO: NULL
               FUSE_ROW_CACHE_HIT: 0
               PS_CLIENT_STMT_ID: -1
               PS_INNER_STMT_ID: -1
                           TX_ID: 0
               SNAPSHOT_VERSION: 0
                   REQUEST_TYPE: 2
           IS_BATCHED_MULTI_STMT: 0
                   OB_TRACE_INFO: NULL
                       PLAN_HASH: 0
               LOCK_FOR_READ_TIME: 0
                   PARAMS_VALUE:
   1 row in set (1.08 sec)
   

   通过以上查询结果，我们可以获取到该 SQL 请求执行的目标节点及 TRACE_ID。

   SVR_IP: xx.xx.xx.158
   TRACE_ID: YB4206019C9E-0005F55950FFAF04-0-0
   

   注意

   本例中通过 GV$OB_SQL_AUDIT 视图获取节点 IP 和 TRACE_ID，OceanBase 数据库还提供了其他多种获取方式，例如通过 ODP 的日志，例如通过等待事件相关的视图。

3. 登录目标节点，并通过 TRACE_ID 检索日志文件。

   [hellodba@xx.xx.xx.158 /home/admin/oceanbase/log]
   $ grep 'YB4206019C9E-0005F55950FFAF04-0-0' observer.log
   [2023-03-12 14:47:40.670100] WARN  resolve_const (ob_resolver_utils.cpp:2420) [116987][T1_TNT_L0_G0][T1][YB4206019C9E-0005F55950FFAF04-0-0] [lt=21] Incorrect DATETIME value: '0001-01-33'
   [2023-03-12 14:47:40.670205] WARN  resolve_const (ob_resolver_utils.cpp:2420) [116987][T1_TNT_L0_G0][T1][YB4206019C9E-0005F55950FFAF04-0-0] [lt=37] Incorrect DATETIME value: '0001-01-33'
   

   注意

   如果在 observer.log 中 grep 不到相关日志，可能是因为 observer.log 切了文件，可以 grep YB4206019C9E-0005F55950FFAF04-0-0 observer.log.*。

   检索到 TRACE_ID 相关的日志只是第一步，细致入微的分析才是检索的目的：

   • 结合日志上下文、OS 指标、OS 事件等多角度指标，对本节点进行分析。
   • 通过 TRACE_ID 对应的 RPC 调用，串联起其他 OceanBase 节点、ODP 节点、应用节点，对全链路进行分析。