If OceanBase Diagnostic Tool (obdiag) is independently deployed, you can use obdiag analyze commands to analyze diagnostic information of OceanBase Database. These commands allow you to analyze OceanBase Database logs to identify errors that have occurred.
If your OceanBase cluster is deployed by using OceanBase Deployer (OBD), you can run obdiag commands on OBD to collect diagnostic information of the cluster. For more information about the commands, see obdiag commands.
Syntax of analyze commands
obdiag analyze <analyze type> [options]
Valid values of the analyze type parameter are as follows:
log: analyzes logs of OceanBase Database.flt_trace: performs end-to-end diagnostics.
obdiag analyze log
You can run this command to analyze logs of an OceanBase cluster online, or specify the --files option to enable offline analysis.
Note
- In online analysis mode, the runtime status of an OceanBase cluster is analyzed, and the logs are distributed on all OBServer nodes of the cluster.
- In offline analysis mode, which is enabled by specifying the
--filesoption, obdiag analyzes the logs of OBServer nodes that are already collected to the server where obdiag is deployed. - Before you use this command, make sure that you have configured the logon information of the target nodes in the
config.ymlconfiguration file of obdiag. For more information, see Configure obdiag.
obdiag analyze log [options]
The following table describes the options.
| Option | Required? | Data type | Default value | Description |
|---|---|---|---|---|
| --from | No | String | This option is left empty by default. | The start time of log collection in the yyyy-mm-dd hh:mm:ss format. For example, 1970-01-01 12:00:00. |
| --to | No | String | This option is left empty by default. | The end time of log collection in the yyyy-mm-dd hh:mm:ss format. For example, 1970-01-01 13:00:00. |
| --since | No | String | This option is left empty by default. | The most recent period for which logs are collected, in the \<n> <m\|h\|d> format, where n is a number, m indicates minutes, h indicates hours, and d indicates days. For example, 30m specifies to collect logs of the last 30 minutes. |
| --scope | No | String | all | The type of logs of the OceanBase cluster to be analyzed. Valid values: observer, election, rootservice, and all. |
| --grep | No | String | This option is left empty by default. | The search keyword. |
| --store_dir | No | String | The default path is the current path in which the command is executed. | The local path where the results are stored. |
| --log_level | No | String | WARN | The level of logs of the OceanBase cluster to be analyzed. Valid values in ascending order: DEBUG, TRACE, INFO, WDIAG, WARN, EDIAG, and ERROR. Logs of the specified level and higher are analyzed. |
| --files | No | String | This option is left empty by default. | If you specify the --files option, the offline log analysis mode is enabled. In offline analysis mode, you must specify the name or path of the log file of the OceanBase cluster, but do not need to specify the --from, --to, --since, or --ob_install_dir options. |
| -c | No | String | ~/.obdiag/config.yml |
The path of the configuration file. |
Example of online log analysis
obdiag analyze log --from 2023-10-08 10:25:00 --to 2023-10-08 11:30:00 ... FileListInfo: +----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Node | LogList | +================+=======================================================================================================================================================================================================================+ | xx.xx.xx.xx | ['observer.log.20231008104204260', 'observer.log.20231008111305072', 'observer.log.20231008114410668', 'observer.log.wf.20231008104204260', 'observer.log.wf.20231008111305072', 'observer.log.wf.20231008114410668'] | +----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ ... Analyze OceanBase Online Log Summary: +----------------+-----------+------------------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | Node | Status | FileName | ErrorCode | Message | Count | +================+===========+==============================================================================+=============+===============================================================================================================================+=========+ | xx.xx.xx.xx | Completed | analyze_pack_20231008171201/xx_xx_xx_xx/observer.log.20231008104204260 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 2 | +----------------+-----------+------------------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | xx.xx.xx.xx | Completed | analyze_pack_20231008171201/xx_xx_xx_xx/observer.log.20231008111305072 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 8 | +----------------+-----------+------------------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | xx.xx.xx.xx | Completed | analyze_pack_20231008171201/xx_xx_xx_xx/observer.log.20231008114410668 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 10 | +----------------+-----------+------------------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | xx.xx.xx.xx | Completed | analyze_pack_20231008171201/xx_xx_xx_xx/observer.log.20231008114410668 | -4009 | IO error | 20 | +----------------+-----------+------------------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ For more details, please run cmd 'cat analyze_pack_20231008171201/result_details.txt'Here are examples of analyzing logs of a recent period.
# Analyze the logs of the last hour online. When you run this command, obdiag pulls the logs of the last hour from the remote host for analysis to diagnose the errors that have occurred. obdiag analyze log --since 1h # Analyze the logs of the last 30 minutes online. When you run this command, obdiag pulls the logs of the last 30 minutes from the remote host for analysis to diagnose the errors that have occurred. obdiag analyze log --since 30m
Example of offline log analysis
$ ls -lh test/ -rw-r--r-- 1 admin staff 256M Oct 8 17:24 observer.log.20231008104204260 -rw-r--r-- 1 admin staff 256M Oct 8 17:24 observer.log.20231008111305072 -rw-r--r-- 1 admin staff 256M Oct 8 17:24 observer.log.20231008114410668 -rw-r--r-- 1 admin staff 18K Oct 8 17:24 observer.log.wf.20231008104204260 -rw-r--r-- 1 admin staff 19K Oct 8 17:24 observer.log.wf.20231008111305072 -rw-r--r-- 1 admin staff 18K Oct 8 17:24 observer.log.wf.20231008114410668 $ obdiag analyze log --files test/ Analyze OceanBase Offline Log Summary: +-----------+-----------+-----------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | Node | Status | FileName | ErrorCode | Message | Count | +===========+===========+=======================================================================+=============+===============================================================================================================================+=========+ | 127.0.0.1 | Completed | analyze_pack_20231008172144/127_0_0_1_/observer.log.20231008104204260 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 2 | +-----------+-----------+-----------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | 127.0.0.1 | Completed | analyze_pack_20231008172144/127_0_0_1_/observer.log.20231008111305072 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 8 | +-----------+-----------+-----------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | 127.0.0.1 | Completed | analyze_pack_20231008172144/127_0_0_1_/observer.log.20231008114410668 | -5006 | You have an error in your SQL syntax; check the manual that corresponds to your OceanBase version for the right syntax to use | 10 | +-----------+-----------+-----------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ | 127.0.0.1 | Completed | analyze_pack_20231008172144/127_0_0_1_/observer.log.20231008114410668 | -4009 | IO error | 20 | +-----------+-----------+-----------------------------------------------------------------------+-------------+-------------------------------------------------------------------------------------------------------------------------------+---------+ For more details, please run cmd 'cat analyze_pack_20231008172144/result_details.txt'Analyze the specified OBServer log file offline:
# Analyze the specified log file offline. obdiag analyze log --files observer.log.20230831142211247
obdiag analyze flt_trace
End-to-end diagnostics: OceanBase Database is a distributed database in which the call links are complex. When a timeout issue occurs, O&M engineers cannot quickly locate whether the issue is caused by OceanBase Database components or the network. They can only analyze the issue based on experience and OBServer logs. The trace.log feature is provided for the kernel of OceanBase Database V4.0 to perform end-to-end diagnostics. Two paths are involved in end-to-end tracing. In one path, the application sends a request to OceanBase Database Proxy (ODP) by using a client, such as JDBC or OCI, to access the OBServer. The access result is returned to the application. In the other path, the application directly accesses the OBServer node by using a client, and the access result is returned to the application. In end-to-end diagnostics, all components are diagnosed.
Working mechanisms of the end-to-end diagnostics feature of obdiag:
┌────────┐ ┌─────────────────────────────┐ ┌────────────────────────────┐
│ Server 1 │------>│ Search and filter the logs related to the specified flt_trace_id. │------>│ Return filtered logs to the node where obdiag is deployed. │---┐
└────────┘ └─────────────────────────────┘ └────────────────────────────┘ │
┌────────┐ ┌─────────────────────────────┐ ┌────────────────────────────┐ │ ┌────────────────────────────────┐
│ Server 2 │------>│ Search and filter the logs related to the specified flt_trace_id. │------>│ Return filtered logs to the node where obdiag is deployed. │---┼--->│ Aggregate logs obtained from parent and child nodes and generate a trace tree based on the hierarchical relationship between nodes.
└────────┘ └─────────────────────────────┘ └────────────────────────────┘ │ └────────────────────────────────┘
┌────────┐ ┌─────────────────────────────┐ ┌────────────────────────────┐ │
│ Server N │------>│ Search and filter the logs related to the specified flt_trace_id. │------>│ Return filtered logs to the node where obdiag is deployed. │---┘
└────────┘ └─────────────────────────────┘ └────────────────────────────┘
Step 1: Find the ID of a suspected slow SQL statement
If you suspect that an SQL statement is slow, you can query the gv$ob_sql_audit view to obtain its flt_trace_id. Here is an example:
OceanBase(root@test)>select query_sql, flt_trace_id from oceanbase.gv$ob_sql_audit where query_sql like 'select @@version_comment limit 1';
+----------------------------------+--------------------------------------+
| query_sql | flt_trace_id |
+----------------------------------+--------------------------------------+
| select @@version_comment limit 1 | 00060aa3-d607-f5f2-328b-388e17f687cb |
+----------------------------------+--------------------------------------+
1 row in set (0.001 sec)
The result indicates that the flt_trace_id of the suspected SQL statement is 00060aa3-d607-f5f2-328b-388e17f687cb.
You can also obtain the flt_trace_id by searching the trace.log file of ODP or the OBServer node. Here is an example:
head trace.log
[2023-12-07 22:20:07.242229] [489640][T1_L0_G0][T1][YF2A0BA2DA7E-00060BEC28627BEF-0-0] {"trace_id":"00060bec-275e-9832-e730-7c129f2182ac","name":"close_das_task","id":"00060bec-2a20-bf9e-56c9-724cb467f859","start_ts":1701958807240606,"end_ts":1701958807240607,"parent_id":"00060bec-2a20-bb5f-e03a-5da01aa3308b","is_follow":false}
The result indicates that the flt_trace_id of the suspected SQL statement is 00060bec-275e-9832-e730-7c129f2182ac.
Step 2: Set the configuration file
Note
Before you use this command, make sure that you have configured the logon information of the target nodes in the config.yml configuration file of obdiag. For more information, see Configure obdiag.
obdiag config -hxx.xx.xx.xx -uroot@sys -p***** -P2881
Step 3: Run the end-to-end diagnostics command
obdiag analyze flt_trace [options]
The following table describes the options.
| Option | Required? | Data type | Default value | Description |
|---|---|---|---|---|
| --flt_trace_id | Yes | String | The value of the flt_trace_id field. |
You can obtain the value by querying the flt_trace_id field in the gv$ob_sql_audit view or searching the trace.log file. |
| --store_dir | No | String | The default path is the current path in which the command is executed. | The local path where the results are stored. |
| --files | No | String | This option is left empty by default. | If you specify the --files option, the offline log analysis mode is enabled. |
| --top | No | String | 5 | The displayed number of leaf nodes that take the longest time in the result of the end-to-end diagnostics. |
| --recursion | No | String | 8 | The maximum number of layers for recursive end-to-end diagnostics. |
| --output | No | String | 60 | The number of displayed rows of the result. The full result is stored in the result file. |
| -c | No | String | ~/.obdiag/config.yml |
The path of the configuration file. |
Here is an example:
$ obdiag analyze flt_trace --flt_trace_id 000605b1-28bb-c15f-8ba0-1206bcc08aa3
root node id: 000605b1-28bb-c15f-8ba0-1206bcc08aa3
TOP time-consuming leaf span:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name | Elapsed Time| NODE |
+---+----------------------------------+-------------+---------------------+
| 18| px_task | 2.758 ms | OBSERVER(xx.xx.xx.1)|
| 5 | pc_get_plan | 52 μs | OBSERVER(xx.xx.xx.1)|
| 16| do_local_das_task | 45 μs | OBSERVER(xx.xx.xx.1)|
| 10| do_local_das_task | 17 μs | OBSERVER(xx.xx.xx.1)|
| 17| close_das_task | 14 μs | OBSERVER(xx.xx.xx.1)|
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
18 - px_task Elapsed: 2.758 ms
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
5 - pc_get_plan Elapsed: 52 μs
NODE:OBSERVER(xx.xx.xx.1)
16 - do_local_das_task Elapsed: 45 μs
NODE:OBSERVER(xx.xx.xx.3)
10 - do_local_das_task Elapsed: 17 μs
NODE:OBSERVER(xx.xx.xx.1)
17 - close_das_task Elapsed: 14 μs
NODE:OBSERVER(xx.xx.xx.3)
Details:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name | Elapsed Time| NODE |
+---+----------------------------------+-------------+---------------------+
| 1 | TRACE | - | - |
| 2 | └─com_query_process | 5.351 ms | OBPROXY(xx.xx.xx.1) |
| 3 | └─mpquery_single_stmt | 5.333 ms | OBSERVER(xx.xx.xx.1)|
| 4 | ├─sql_compile | 107 μs | OBSERVER(xx.xx.xx.1)|
| 5 | │ └─pc_get_plan | 52 μs | OBSERVER(xx.xx.xx.1)|
| 6 | └─sql_execute | 5.147 ms | OBSERVER(xx.xx.xx.1)|
| 7 | ├─open | 87 μs | OBSERVER(xx.xx.xx.1)|
| 8 | ├─response_result | 4.945 ms | OBSERVER(xx.xx.xx.1)|
| 9 | │ ├─px_schedule | 2.465 ms | OBSERVER(xx.xx.xx.1)|
| 10| │ │ ├─do_local_das_task | 17 μs | OBSERVER(xx.xx.xx.1)|
| 11| │ │ ├─px_task | 2.339 ms | OBSERVER(xx.xx.xx.2)|
| 12| │ │ │ ├─do_local_das_task | 54 μs | OBSERVER(xx.xx.xx.2)|
| 13| │ │ │ └─close_das_task | 22 μs | OBSERVER(xx.xx.xx.2)|
| 14| │ │ ├─do_local_das_task | 11 μs | OBSERVER(xx.xx.xx.1)|
| 15| │ │ ├─px_task | 2.834 ms | OBSERVER(xx.xx.xx.3)|
| 16| │ │ │ ├─do_local_das_task | 45 μs | OBSERVER(xx.xx.xx.3)|
| 17| │ │ │ └─close_das_task | 14 μs | OBSERVER(xx.xx.xx.3)|
| 18| │ │ └─px_task | 2.758 ms | OBSERVER(xx.xx.xx.1)|
| 19| │ ├─px_schedule | 1 μs | OBSERVER(xx.xx.xx.1)|
| 20| │ └─px_schedule | 1 μs | OBSERVER(xx.xx.xx.1)|
| ..| ...... | ... | ...... |
+---+----------------------------------+-------------+---------------------+
For more details, please run cmd ' cat analyze_flt_result/000605b1-28bb-c15f-8ba0-1206bcc08aa3.txt '
View the details:
$ cat analyze_flt_result/000605b1-28bb-c15f-8ba0-1206bcc08aa3.txt
root node id: 000605b1-28bb-c15f-8ba0-1206bcc08aa3
TOP time-consuming leaf span:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name | Elapsed Time| NODE |
+---+----------------------------------+-------------+---------------------+
| 18| px_task | 2.758 ms | OBSERVER(xx.xx.xx.1)|
| 5 | pc_get_plan | 52 μs | OBSERVER(xx.xx.xx.1)|
| 16| do_local_das_task | 45 μs | OBSERVER(xx.xx.xx.1)|
| 10| do_local_das_task | 17 μs | OBSERVER(xx.xx.xx.1)|
| 17| close_das_task | 14 μs | OBSERVER(xx.xx.xx.1)|
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
18 - px_task Elapsed: 2.758 ms
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
5 - pc_get_plan Elapsed: 52 μs
NODE:OBSERVER(xx.xx.xx.1)
16 - do_local_das_task Elapsed: 45 μs
NODE:OBSERVER(xx.xx.xx.3)
10 - do_local_das_task Elapsed: 17 μs
NODE:OBSERVER(xx.xx.xx.1)
17 - close_das_task Elapsed: 14 μs
NODE:OBSERVER(xx.xx.xx.3)
Details:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name | Elapsed Time| NODE |
+---+----------------------------------+-------------+---------------------+
| 1 | TRACE | - | - |
| 2 | └─com_query_process | 5.351 ms | OBPROXY(xx.xx.xx.1) |
| 3 | └─mpquery_single_stmt | 5.333 ms | OBSERVER(xx.xx.xx.1)|
| 4 | ├─sql_compile | 107 μs | OBSERVER(xx.xx.xx.1)|
| 5 | │ └─pc_get_plan | 52 μs | OBSERVER(xx.xx.xx.1)|
| 6 | └─sql_execute | 5.147 ms | OBSERVER(xx.xx.xx.1)|
| 7 | ├─open | 87 μs | OBSERVER(xx.xx.xx.1)|
| 8 | ├─response_result | 4.945 ms | OBSERVER(xx.xx.xx.1)|
| 9 | │ ├─px_schedule | 2.465 ms | OBSERVER(xx.xx.xx.1)|
| 10| │ │ ├─do_local_das_task | 17 μs | OBSERVER(xx.xx.xx.1)|
| 11| │ │ ├─px_task | 2.339 ms | OBSERVER(xx.xx.xx.2)|
| 12| │ │ │ ├─do_local_das_task | 54 μs | OBSERVER(xx.xx.xx.2)|
| 13| │ │ │ └─close_das_task | 22 μs | OBSERVER(xx.xx.xx.2)|
| 14| │ │ ├─do_local_das_task | 11 μs | OBSERVER(xx.xx.xx.1)|
| 15| │ │ ├─px_task | 2.834 ms | OBSERVER(xx.xx.xx.3)|
| 16| │ │ │ ├─do_local_das_task | 45 μs | OBSERVER(xx.xx.xx.3)|
| 17| │ │ │ └─close_das_task | 14 μs | OBSERVER(xx.xx.xx.3)|
| 18| │ │ └─px_task | 2.758 ms | OBSERVER(xx.xx.xx.1)|
| 19| │ ├─px_schedule | 1 μs | OBSERVER(xx.xx.xx.1)|
| 20| │ └─px_schedule | 1 μs | OBSERVER(xx.xx.xx.1)|
| 21| └─close | 70 μs | OBSERVER(xx.xx.xx.1)|
| 22| └─end_transaction | 3 μs | OBSERVER(xx.xx.xx.1)|
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
1 -
2 - com_query_process Elapsed: 5.351 ms
NODE:OBPROXY(xx.xx.xx.1)
tags: [{'sess_id': 3221487633}, {'action_name': ''}, {'module_name': ''}, {'client_info': ''}, {'receive_ts': 1695108311007659}, {'log_trace_id': 'YA9257F000001-000605B0441954BC-0-0'}]
3 - mpquery_single_stmt Elapsed: 5.333 ms
NODE:OBSERVER(xx.xx.xx.1)
4 - sql_compile Elapsed: 107 μs
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'sql_text': 'select /*+parallel(2)*/ count(1) from t1 tt1, t1 tt2'}, {'sql_id': '797B7202BA69D4C2C77C12BFADDC19DC'}, {'database_id': 201001}, {'plan_hash': 150629045171310866}, {'hit_plan': True}]
5 - pc_get_plan Elapsed: 52 μs
NODE:OBSERVER(xx.xx.xx.1)
6 - sql_execute Elapsed: 5.147 ms
NODE:OBSERVER(xx.xx.xx.1)
7 - open Elapsed: 87 μs
NODE:OBSERVER(xx.xx.xx.1)
8 - response_result Elapsed: 4.945 ms
NODE:OBSERVER(xx.xx.xx.1)
9 - px_schedule Elapsed: 2.465 ms
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'used_worker_cnt': 0}, {'qc_id': 1}, {'dfo_id': 2147483647}, {'used_worker_cnt': 0}, {'qc_id': 1}, {'dfo_id': 1}]
10 - do_local_das_task Elapsed: 17 μs
NODE:OBSERVER(xx.xx.xx.1)
11 - px_task Elapsed: 2.339 ms
NODE:OBSERVER(xx.xx.xx.2)
tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 0}, {'task_id': 0}]
12 - do_local_das_task Elapsed: 54 μs
NODE:OBSERVER(xx.xx.xx.2)
13 - close_das_task Elapsed: 22 μs
NODE:OBSERVER(xx.xx.xx.2)
14 - do_local_das_task Elapsed: 11 μs
NODE:OBSERVER(xx.xx.xx.1)
15 - px_task Elapsed: 2.834 ms
NODE:OBSERVER(xx.xx.xx.3)
tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 0}]
16 - do_local_das_task Elapsed: 45 μs
NODE:OBSERVER(xx.xx.xx.3)
17 - close_das_task Elapsed: 14 μs
NODE:OBSERVER(xx.xx.xx.3)
18 - px_task Elapsed: 2.758 ms
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
19 - px_schedule Elapsed: 1 μs
NODE:OBSERVER(xx.xx.xx.1)
20 - px_schedule Elapsed: 1 μs
NODE:OBSERVER(xx.xx.xx.1)
21 - close Elapsed: 70 μs
NODE:OBSERVER(xx.xx.xx.1)
22 - end_transaction Elapsed: 3 μs
NODE:OBSERVER(xx.xx.xx.1)
tags: [{'trans_id': 0}]