パラレル実行の問題を診断するには、大きく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は、その演算子が演算子ツリー内での深さを表します。
注意
- スケジュールされていないDFOの演算子情報は、
GV$SQL_PLAN_MONITORには表示されません。 - 1つのPLに複数のSQLが含まれる場合、それらのTRACE_IDは同じです。
- 構成パラメータ
enable_sql_auditがFALSEに設定されている場合、データはGV$SQL_PLAN_MONITORに記録されません。
スローPDMLの診断
V3.x系では、PDMLにはいくつか特殊性があり、長時間実行されるPDMLステートメントはundo_retention変数の制限を受けます。実行時間がundo_retentionを超えると、SQLレベルで自動リトライが発生する可能性があり、ユーザー側から見た効果としては、このPDMLステートメントが終わらない状態になります。
以下のビューからPDMLの問題を診断できます：
PDMLが実行中であることを確認します。
obclient> SELECT * FROM .all_virtual_px_worker.stat;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;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;undo_retentionを変更し、その値を単一PDML実行の最大時間よりも大きく設定します。単位は「秒」です。
obclient> SHOW VARIABLES LIKE "%undo%" +---------------+-------+ | Variable_name | Value | +---------------+-------+ | undo_retention| 1800 | +---------------+-------+ 1 row in set