パラレル実行の問題診断

パラレル実行の問題を診断するには、大きく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分ごとに1回の収集と表示を意味します。

過去2日間のCPU使用状況の確認：

tsar -n 2 -i 1 --cpu

ディスクやネットワークがパンクした場合は、ハードウェア容量不足または同時実行負荷が過大である可能性が高いため、まずこの観点から問題を解決します。

SQL診断

パラレル実行の問題が発生した場合、SQLレベル、パラレル実行スレッドレベル、演算子レベルの順に段階的に調査できます。

SQLが実行中であることの確認

SQLが正常に実行されていることの確認：TIMEフィールドに注目します。GV$OB_PROCESSLIST ビューのTIMEフィールドが毎回増加し、STATEがACTIVEであれば、Queryはまだ実行中です。

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の条件でこのビューをクエリする場合、これを「リアルタイムSQL PLAN MONITOR」へのアクセスとも呼びます。このアクセスインターフェースは今後変更される可能性があります。

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は、そのオペレーターがオペレーターツリー内での深さを表します。

スローPDML診断

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

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

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

   obclient> SELECT * FROM .all_virtual_px_worker.stat;
   

2. PDMLの総実行回数（threadsフィールド）を確認し、それが並列度よりもはるかに大きい場合、再試行が発生していることを示します。

   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