パラレル実行の問題診断

パラレル実行の問題を診断するには、大きく2つのアプローチがあります。まず、システム全体の状況を確認します。ネットワーク、ディスクI/O、CPUが過負荷になっているかどうかを確認します。次に、具体的なSQL文に焦点を当て、問題が発生しているSQLの場所とその内部状態を特定します。

システム診断

業務負荷の高いシステムでパフォーマンス問題が発生した場合、まずはシステムレベルでの初期診断を行う必要があります。一般的に、以下の2つのアプローチがあります。

• OCP（OceanBase Cloud Platform）は、システムのパフォーマンスを可視化して観測できます。
• tsarなどのコマンドラインシステムツールは、ネットワーク、ディスク、CPUなどの履歴監視データの照会をサポートします。

tsarはシステム監視とパフォーマンス分析ツールであり、CPU、ディスク、ネットワークなどの詳細な情報を提供します。以下に、tsarコマンドの一般的な使用例をいくつか示します。：

CPU使用率を確認する：

tsar --cpu

ディスクI/O使用状況を確認する：

tsar --io

ネットワーク転送速度を確認する：

tsar --traffic

上記の例に加えて、tsar は他のオプションとパラメータもサポートしています。例えば、パラメータ -d 2 を使用すると、2日前から現在までのデータを確認でき、-d YYYY-MM-DD を使用すると指定された日付 YYYY-MM-DD のデータを確認できます。また、-i 1 は1分ごとにデータを収集して表示するオプションです。

過去2日のCPU使用状況を確認する：

tsar -n 2 -i 1 --cpu

ディスクまたはネットワークがボトルネックになる場合は、ハードウェア容量が小さすぎるか、並行処理の負荷が大きすぎるかを優先的に解決します。

SQL診断

パラレル実行の問題が発生した場合、SQLレベル、パラレル実行スレッドレベル、演算子レベルと、階層的にチェックできます。

SQLが実行中かを確認する

SQLが正常に実行されているか確認します。TIMEフィールドに注目し、GV$OB_PROCESSLISTビューのTIMEフィールドが増加し、STATEがACTIVEである場合、クエリがまだ実行中であることを示します。

SQLが繰り返し再試行（リトライ）されているかを確認します。再試行が原因でSQLの結果が返ってこない場合、その情報は RETRY_CNT および RETRY_INFO フィールドで確認できます。RETRY_CNT は再試行回数を、RETRY_INFO は直近の再試行理由を示します。 再試行が発生していない場合、RETRY_CNT は 0 となります。TOTAL_TIME フィールドは、各再試行を含めた累積実行時間を表します。

SQLが繰り返し再試行されている場合は、RETRY_INFO に記載されたエラーコードに基づき、対応が必要かどうかを判断します。V4.1以前のバージョンにおいて最も一般的なエラーは -4138（OB_SNAPSHOT_DISCARDED）です。このエラーの場合、並行実行の分類を参照してundo_retention値を大きくすることで解決できます。

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

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

SQLがパラレルクエリを実行中かを確認する

OBServerクラスタでは、すべてのアクティブな並行実行スレッドをGV$OB_PX_WORKER_STATビューで確認できます。

-- MySQLモード
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モード
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

GV$OB_PROCESSLISTから取得したTRACE_IDを組み合わせて、このビューでSQLが現在どのDFOを実行中で、どのくらいの期間実行されているかなどの情報を確認できます。

このビューで何も確認できないが、GV$OB_PROCESSLISTには対応するSQLが表示されている場合、以下の原因が考えられます：

• すべてのDFOが実行完了し、結果セットが大きいことから、現在クライアントにデータを返送中です。
• 最上位のDFOを除いて、すべてのDFOが実行完了しています。

各演算子の実行状況を確認する

oceanbase.GV$SQL_PLAN_MONITOR（MySQLモード）または SYS.GV$SQL_PLAN_MONITOR（Oracleモード）を使用することで、各並列ワーカースレッドにおける各演算子の実行状態を確認できます。V4.1以降、GV$SQL_PLAN_MONITOR には以下2種類のデータが含まれます。

• 実行が完了した演算子：「実行完了」とは、その演算子の close インターフェースがすでに呼び出されており、現在のスレッドでデータを処理しなくなっている状態を指します。
• 実行中の演算子：「実行中」とは、その演算子の close インターフェースがまだ呼び出されておらず、現在データを処理している最中の状態を指します。この部分の演算子データを読み取るには、GV$SQL_PLAN_MONITOR ビューをクエリする際、WHERE句で request_id < 0 を指定する必要があります。request_id < 0 の条件を使用してこのビューを照会することを、「Realtime SQL PLAN MONITOR（リアルタイムSQLプランモニター）」へのアクセスとも呼びます。なお、このアクセス用インターフェースは将来変更される可能性があります。

V4.1 以前では、実行が完了した演算子の状況のみ確認できます。

GV$SQL_PLAN_MONITOR ビューにはいくつか重要な列があります。

• TRACE_ID：SQLを一意に識別するIDです。
• PLAN_LINE_ID：演算子の実行計画における番号で、explain ステートメントで確認できる番号と対応します。
• PLAN_OPERATION：演算子の名前、例えば TABLE SCAN、HASH JOIN などです。
• OUTPUT_ROWS：現在の演算子がすでに出力した行数です。
• FIRST_CHANGE_TIME：演算子が最初の行データを吐き出した時間です。
• LAST_CHANGE_TIME：演算子が最後の行データを吐き出した時間です。
• FIRST_REFRESH_TIME：演算子のモニタリングを開始した時間です。
• LAST_REFRESH_TIME：演算子のモニタリングを終了した時間です。

上記の列から、演算子がデータ処理で行った主要な動作をほぼ描き出すことができます。以下にいくつかのシナリオを例に挙げます。

• 実行が完了したSQLの各演算子がいくつのスレッドを使用して実行したかを確認する。

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

• 実行中のSQLの現在実行中の演算子、使用しているスレッド数、および既に出力されたデータ行数を確認します。

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;

• 実行が完了したSQLについて、各演算子の処理行数および出力行数を確認します。

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

上記の例では、見やすさのために PLAN_DEPTH フィールドを使用してインデント処理を行っています。PLAN_DEPTH は、演算子が演算子ツリー内でどの深さにあるかを示します。

V3.x系では、PDMLに特有の制限があります。実行時間が長いPDMLステートメントはundo_retention変数の制限に影響されます。実行時間がundo_retentionを超えると、SQLレベルでの自動リトライが発生し、ユーザー側からはこのPDMLステートメントが終了しないように見えることがあります。

以下のビューからPDMLの問題を診断できます：

1. PDMLが実行中であることを確認します。

   obclient> SELECT * FROM .all_virtual_px_worker.stat;
   

2. PDMLの総実行回数（thredsフィールド）を確認します。もし並列度を大幅に上回っている場合は、リトライが発生している可能性があります。

   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. processlist仮想テーブルからリトライが発生しているかを確認します。retry_cntフィールドが0より大きい場合、リトライが発生しています。

   -- time: 今回のリトライが開始されてからの経過時間
   -- total_time: ユーザーがSQLを実行してからの経過時間
   -- retry_cnt: これまでにリトライされた回数。リトライが発生していない場合は retry_cnt = 0
   -- retry_info: 最後のリトライがどのエラーコードでトリガーされたか
   select time, total_time, trace_id, retry_cnt, retry_info
   from __all_virtual_processlist;
   

4. undo_retentionの値を、単一のPDML実行の最大時間を超えるように変更します。単位は「秒」です。

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