Search for the logs of a specific SQL request

OceanBase Database allows you to search for logs related to specific SQL requests. However, depending on the syslog level settings and the SQL exceptions, you may not always find the logs that you need.

Searching for logs related to specific SQL requests is a highly useful technique in observability. The basic technique involves retrieving logs from the log files by using the IP address of the node and the TRACE_ID, allowing us to establish a full chain of events to identify the initial occurrence. This technique stands out for its "post-event" and "end-to-end" attributes, providing a powerful complement to metrics. Metrics help you notice exceptions, while syslogs provide you with details for end-to-end tracing.

Procedure

1. Log on to the OceanBase cluster and execute the following sample SQL statement, which will return an error:

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

   Notice

   In a real production environment, SQL statements are executed by the application system, and in the case of an exception, such as when an error code is returned, or the execution consumes a long time, contact O&M engineers to help locate the causes.

2. Log on to the sys tenant and query the GV$OB_SQL_AUDIT view to check the execution information about the SQL statement.

   Notice

   If the GV$OB_SQL_AUDIT view does not return any result, check whether the enable_sql_audit parameter is set to False, which means that the SQL Audit feature is disabled. For more information about the enable_sql_audit parameter, see 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)
   

   The preceding query result shows the TRACE_ID of the SQL request and the IP address of the node where it is executed.

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

   Notice

   In this example, the IP address of the node and TRACE_ID are obtained by using the GV$OB_SQL_AUDIT view. OceanBase Database also allows you to obtain that information by using other methods, such as using the logs of OceanBase Database Proxy (ODP) or the views of wait events.

3. Log on to the target node and search the log file by using 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'
   

   Notice

   If you cannot find the relevant logs by grepping in observer.log, it could be because the observer.log file has been rotated. In such cases, you can use the following command to grep through the rotated log files: grep YB4206019C9E-0005F55950FFAF04-0-0 observer.log.*.

   After you find the logs related to the TRACE_ID, you can analyze them:

   • Analyze the node based on various information such as log context, OS metrics, and OS events.
   • Perform end-to-end tracing to analyze the related OBServer nodes, ODP nodes, and application nodes based on the remote procedure calls (RPCs) associated with the TRACE_ID.