Parallel execution diagnostics

You can diagnose parallel execution issues from two perspectives. For the whole system, you can check whether the network, disk I/O, and CPU resources are used up. For specific SQL statements, you can locate the problematic SQL statements and check its internal status.

System diagnostics

When a performance issue occurs in a busy business system, you first need to perform preliminary diagnostics for the whole system by using either of the following two methods:

• OceanBase Cloud Platform (OCP): You can observe the system performance on the GUI.
• Command-line system tools such as TSAR: You can query historical monitoring data of network, disk, and CPU resources.

TSAR is a tool for system monitoring and performance analysis. It can provide details about CPU, disk, and network resources. Here are some examples of using TSAR commands.

View the CPU utilization:

TSAR --cpu

View the disk I/O:

TSAR --io

View the network transmission rate:

TSAR --traffic

TSAR also provides other options and parameters. For example, -d 2 specifies to query the data of the last two days and -i 1 specifies to collect data at an interval of 1 minute and display the collected data by minute.

View the CPU utilization in the last two days:

TSAR -n 2 -i 1 --cpu

If the disk or network resources are used up, you can first check whether the hardware capacity is too small or the parallel execution load is too heavy.

SQL diagnostics

When a parallel execution issue occurs, you can perform diagnostics at the SQL layer, parallel execution (PX) thread layer, and operator layer in sequence.

Verify whether the SQL query is still in progress

Query the GV$OB_PROCESSLIST view. If the value of the TIME field keeps increasing and the value of the STATE field is ACTIVE, the SQL query is still in progress.

View the RETRY_CNT and RETRY_INFO fields to verify whether the SQL query is repeatedly retried. RETRY_CNT indicates the number of retries. RETRY_INFO indicates the reason for the last retry. If no retry is performed, the value of RETRY_CNT is 0. TOTAL_TIME indicates the total execution time of the SQL query, including the time consumed for each retry.

If the SQL query is repeatedly retried, determine whether manual intervention is required based on the error code provided in RETRY_INFO. In OceanBase Database of a version earlier than V4.1, the most common error is -4138 (OB_SNAPSHOT_DISCARDED). If this error is returned, increase the value of undo_retention by referring to the Classification and optimization topic.

-- MySQL mode
SELECT
  TENANT,INFO,TRACE_ID,STATE,TIME,TOTAL_TIME,RETRY_CNT,RETRY_INFO
FROM
  oceanbase.GV$OB_PROCESSLIST;

-- Oracle mode
SELECT
  TENANT,INFO,TRACE_ID,STATE,TIME,TOTAL_TIME,RETRY_CNT,RETRY_INFO
FROM
  sys.GV$OB_PROCESSLIST;

Verify whether the SQL query is being executed in parallel

You can query the GV$OB_PX_WORKER_STAT view for all active PX threads in an OceanBase cluster.

-- MySQL mode
obclient> SELECT * FROM oceanbase.GV$OB_PX_WORKER_STAT;
SESSION_ID: 3221520411
 TENANT_ID: 1002
    SVR_IP: 192.xx.xx.xx
  SVR_PORT: 19510
  TRACE_ID: Y4C360B9E1F4D-0005F9A76E9E66B2-0-0
     QC_ID: 1
    SQC_ID: 0
 WORKER_ID: 0
    DFO_ID: 0
START_TIME: 2023-04-23 17:29:17.372461

-- Oracle mode
obclient> SELECT * FROM SYS.GV$OB_PX_WORKER_STAT;
SESSION_ID: 3221520410
 TENANT_ID: 1004
    SVR_IP: 192.xx.xx.xx
  SVR_PORT: 19510
  TRACE_ID: Y4C360B9E1F4D-0005F9A76E9E66B1-0-0
     QC_ID: 1
    SQC_ID: 0
 WORKER_ID: 0
    DFO_ID: 0
START_TIME: 2023-04-23 17:29:15.372461

Based on the trace ID queried from the GV$OB_PROCESSLIST view, you can query the GV$OB_PX_WORKER_STAT view for the data flow operations (DFOs) being executed in the current SQL query, as well as the execution time of the DFOs.

If no required information is found in the GV$OB_PX_WORKER_STAT view but you can still find the corresponding SQL query in the GV$OB_PROCESSLIST view, the possible causes are as follows:

• All DFOs have been completed, the result set is large, and data is being outputting to the client.
• All DFOs except for the top-layer DFO have been completed.

Verify the execution status of each operator

Query the oceanbase.GV$SQL_PLAN_MONITOR view in MySQL mode or the SYS.GV$SQL_PLAN_MONITOR view in Oracle mode for the execution status of each operator in each PX thread. Since OceanBase Database V4.1, the GV$SQL_PLAN_MONITOR view records two parts of data:

• Operators that have been completed, namely operators that have called the close operation and no longer process data in the current thread.
• Operators that are being executed, namely operators that have not called the close operation and are processing data. To query data of these operators from the GV$SQL_PLAN_MONITOR view, you must specify request_id < 0 in the WHERE condition. When you use the request_id < 0 condition to query this view, you are calling the Realtime SQL PLAN MONITOR operation. This operation may change in the future.

In OceanBase Database of a version earlier than V4.1, you can view the status of only completed operators.

The important fields in the GV$SQL_PLAN_MONITOR view are described as follows:

• TRACE_ID: the unique ID of an SQL statement.
• PLAN_LINE_ID: the ID of an operator in the execution plan, which corresponds to the ID queried by using the EXPLAIN statement.
• PLAN_OPERATION: the name of the operator, such as TABLE SCAN or HASH JOIN.
• OUTPUT_ROWS: the number of rows generated by the current operator.
• FIRST_CHANGE_TIME: the time when the operator generated the first row.
• LAST_CHANGE_TIME: the time when the operator generated the last row.
• FIRST_REFRESH_TIME: the monitoring start time of the operator.
• LAST_REFRESH_TIME: the monitoring end time of the operator.

The preceding fields can basically describe the major data processing actions taken by an operator. Here are some examples.

• The following sample code queries the number of threads used by each operator in a completed SQL statement.

  SELECT PLAN_LINE_ID, PLAN_OPERATION, COUNT(*) THREADS
  FROM GV$SQL_PLAN_MONITOR
  WHERE TRACE_ID = 'YA1E824573385-00053C8A6AB28111-0-0'
  GROUP BY PLAN_LINE_ID, PLAN_OPERATION
  ORDER BY PLAN_LINE_ID;
  
  +--------------+------------------------+---------+
  | PLAN_LINE_ID | PLAN_OPERATION         | THREADS |
  +--------------+------------------------+---------+
  |            0 | PHY_PX_FIFO_COORD      |       1 |
  |            1 | PHY_PX_REDUCE_TRANSMIT |       2 |
  |            2 | PHY_GRANULE_ITERATOR   |       2 |
  |            3 | PHY_TABLE_SCAN         |       2 |
  +--------------+------------------------+---------+
  4 rows in set
  

• The following sample code queries the operators being executed, the number of threads used, and the number of rows that have been generated in an SQL statement being executed.

  SELECT PLAN_LINE_ID, CONCAT(LPAD('', PLAN_DEPTH, ' '), PLAN_OPERATION) OPERATOR, COUNT(*) THREADS, SUM(OUTPUT_ROWS) ROWS
  FROM GV$SQL_PLAN_MONITOR
  WHERE TRACE_ID = 'YA1E824573385-00053C8A6AB28111-0-0' AND REQUEST_ID < 0
  GROUP BY PLAN_LINE_ID, PLAN_OPERATION, PLAN_DEPTH
  ORDER BY PLAN_LINE_ID;
  

• The following sample code queries the number of rows that have been processed by each operator and the number of rows that have been generated by each operator in a completed SQL statement.

  SELECT PLAN_LINE_ID, CONCAT(LPAD('', PLAN_DEPTH, ' '), PLAN_OPERATION) OPERATOR, SUM(OUTPUT_ROWS) ROWS
  FROM GV$SQL_PLAN_MONITOR
  WHERE TRACE_ID = 'Y4C360B9E1F4D-0005F9A76E9E6193-0-0'
  GROUP BY PLAN_LINE_ID, PLAN_OPERATION, PLAN_DEPTH
  ORDER BY PLAN_LINE_ID;
  +--------------+-----------------------------------+------+
  | PLAN_LINE_ID | OPERATOR                          | ROWS |
  +--------------+-----------------------------------+------+
  |            0 | PHY_PX_MERGE_SORT_COORD           |    2 |
  |            1 |  PHY_PX_REDUCE_TRANSMIT           |    2 |
  |            2 |   PHY_SORT                        |    2 |
  |            3 |    PHY_HASH_GROUP_BY              |    2 |
  |            4 |     PHY_PX_FIFO_RECEIVE           |    2 |
  |            5 |      PHY_PX_DIST_TRANSMIT         |    2 |
  |            6 |       PHY_HASH_GROUP_BY           |    2 |
  |            7 |        PHY_HASH_JOIN              | 2002 |
  |            8 |         PHY_HASH_JOIN             | 2002 |
  |            9 |          PHY_JOIN_FILTER          | 8192 |
  |           10 |           PHY_PX_FIFO_RECEIVE     | 8192 |
  |           11 |            PHY_PX_REPART_TRANSMIT | 8192 |
  |           12 |             PHY_GRANULE_ITERATOR  | 8192 |
  |           13 |              PHY_TABLE_SCAN       | 8192 |
  |           14 |          PHY_GRANULE_ITERATOR     | 8192 |
  |           15 |           PHY_TABLE_SCAN          | 8192 |
  |           16 |         PHY_GRANULE_ITERATOR      | 8192 |
  |           17 |          PHY_TABLE_SCAN           | 8192 |
  +--------------+-----------------------------------+------+
  18 rows in set
  

The PLAN_DEPTH field is used for indentation for better display effects. PLAN_DEPTH specifies the depth of an operator in the operator tree.

Slow PDML diagnostics

In OceanBase Database V3.x, PDML statements with a long execution time are subject to the setting of the undo_retention variable. If the execution time of a PDML statement exceeds the value of undo_retention, an automatic retry may be triggered at the SQL level. From the user's perspective, the execution of the PDML statement does not end after a long period of time.

You can diagnose PDML issues based on views as follows:

1. Verify whether a PDML statement is being executed.

   obclient> SELECT * FROM .all_virtual_px_worker.stat;
   

2. Learn of the total executions of a PDML statement from the threads filed.

   If the number of executions is far greater than the degree of parallelism (DOP), the statement has been retried.

   obclient> select op_id,op,rows,rescan, threads, (close_time - open_time) open_dt, (last_row_eof_time-first_row_time) row_dt, open_time, close_time, first_row_time, last_row_eof_time FROM
   -> (
   -> select plan_line_id op_id, concat(lpad('', plan_depth, ''), plan operation) op, sum(output_rows) rows, sum(STARTS) rescan,min(first_refresh_time) open_time, max(last_refresh_time) close_time,min(first_change_time) first_row_time, max(last_change_time) last_row_eof_time,count(1) threads from oceanbase.gv$sql_plan_monitor where trace_id = 'YB42C0A8051D-000600EFF65FBCFB-0-0' group by plan_line_id, plan_operation order by plan_line_id
   -> )a;
   

3. Query the __all_virtual_processlist view.

   If the value of the retry_cnt field exceeds 0, the statement has been retried.

   -- time: the execution duration of the current retry.
   -- total_time: the time elapsed since the SQL query was initiated.
   -- retry_cnt: the number of retries that have been made. retry_cnt = 0 indicates that no retry has been made.
   -- retry_info: the error code that triggered the last retry.
   select time, total_time, trace_id, retry_cnt, retry_info 
   from __all_virtual_processlist;
   

4. Modify undo_retention to a value greater than the maximum execution time of a single PDML statement, in seconds.

   obclient> SHOW VARIABLES LIKE "%undo%"
   +---------------+-------+
   | Variable_name | Value |
   +---------------+-------+
   | undo_retention| 1800  |
   +---------------+-------+
   1 row in set