Trace機能を利用した直前のSQLリクエストログの検索

OceanBaseデータベースは、Trace機能に基づいて直前のSQLリクエストの完全なログを迅速に取得することをサポートしています。

対象のSQLリクエストログを容易に検索するために、事前にログ出力レベルを設定することで、SQLモジュール以外のログの出力を削減できます。ログ出力レベルの設定に関する詳細は、ログ出力レベルの設定を参照してください。

具体的な操作手順は以下のとおりです：

1. Trace機能を有効にします。

   Trace機能を有効にするには、以下の2つの方法があります：

   • セッション変数ob_enable_show_traceを設定することでTrace機能を有効にします。この方法は、現在のセッションの以降すべてのステートメントに適用されます。

      obclient [test]> SET ob_enable_show_trace=ON;
     

   • Hintのtrace_logフィールドを設定することでTrace機能を有効にします。この方法は、Hintを持つ現在のステートメントにのみ適用されます。より詳細なHintステートメントに関する説明については、Optimizer Hintを参照してください。

     obclient [test]> SELECT /*+trace_log=on*/c1 FROM t1 LIMIT 2;
     

2. SHOW TRACEを使用してSQLの実行情報を確認します。

   Trace機能を有効にしてSQLリクエストを実行した後、SHOW TRACEステートメントを使用して、直前のSQLステートメントの詳細な実行追跡情報を取得できます。

   obclient [test]> SHOW TRACE;
   +-------------------------------------------+----------------------------+------------+
   | Operation                                 | StartTime                  | ElapseTime |
   +-------------------------------------------+----------------------------+------------+
   | com_query_process                         | 2023-03-22 14:30:27.552259 | 0.405 ms   |
   | └── mpquery_single_stmt             | 2023-03-22 14:30:27.552266 | 0.386 ms   |
   |     ├── sql_compile                 | 2023-03-22 14:30:27.552283 | 0.083 ms   |
   |     │   └── pc_get_plan           | 2023-03-22 14:30:27.552286 | 0.025 ms   |
   |     └── sql_execute                 | 2023-03-22 14:30:27.552379 | 0.242 ms   |
   |         ├── open                    | 2023-03-22 14:30:27.552380 | 0.024 ms   |
   |         ├── response_result         | 2023-03-22 14:30:27.552417 | 0.140 ms   |
   |         │   ├── get_das_id        | 2023-03-22 14:30:27.552421 | 0.000 ms   |
   |         │   └── do_local_das_task | 2023-03-22 14:30:27.552435 | 0.049 ms   |
   |         └── close                   | 2023-03-22 14:30:27.552570 | 0.039 ms   |
   |             ├── close_das_task      | 2023-03-22 14:30:27.552571 | 0.012 ms   |
   |             └── end_transaction     | 2023-03-22 14:30:27.552596 | 0.003 ms   |
   +-------------------------------------------+----------------------------+------------+
   12 rows in set (0.006 sec)
   

   ElapseTimeフィールドは、現在のステップで費やされた時間をミリ秒単位で示します。例えば、pc_get_planのElapseTimeフィールドが0.025 msと表示されている場合、OceanBaseデータベースがPlan Cacheから実行計画を取得するのに0.025 msかかったことを意味します。 一般的な関連Operationの紹介は以下のとおりです。より多くのOperationタイプについては、フルリンクトレースプロセスのspanを参照してください。

   • com_query_process：クエリ処理。

   • mpquery_single_stmt：単一ステートメントのアクセスパス。

   • sql_compile：SQLのコンパイル。

   • pc_get_plan：実行計画の取得。

   • hard_parse：ハードパース。

   • parse：ソフトパース。

   • resolve：構文木のセマンティクスを解析し、ステートメントを生成する。

   • rewrite：SQLのリライト。

   • optimize：コストベースの最適化を行い、実行計画ログを生成する。

   • code_generate：実行計画ログに基づいて物理実行計画を生成する。

   • pc_add_plan：生成された実行計画をplan cacheに追加する。

   • sql_execute：物理実行計画を実行する。

   • open：実行計画を開く。

   • response_result：実行計画の処理と結果。

   • get_das_id：dasタスクIDを取得する。

   • do_local_das_task：ローカルdasタスクを実行する。

   • px_schedule：pxに従ってタスクを分割する。

   • px_task：pxサブタスクを実行する。

   • close：実行計画を閉じる。

   • close_das_task：dasタスクを閉じる。

   • end_transaction：トランザクションを終了する。

   • cmd_execute：コマンドを実行する。

   • cmd_open：cmd計画を開始する。

   • ps_prepare：preprocess statementの事前処理。

   • ps_execute：preprocess statementの実行。

   • ps_close：preprocess statementを閉じる。

   • pl_entry：ストアドプロシージャ処理。

   • pl_compile：ストアドプロシージャオブジェクトのコンパイル。

   • pc_get_pl_object：plan cacheからストアドプロシージャオブジェクトを取得する。

   • pc_add_pl_object：ストアドプロシージャオブジェクトをplan cacheに保存する。

   • pl_execute：ストアドプロシージャを実行する。

   • pl_spi_query：ストアドプロシージャ内のspiステートメントを実行する。

   • pl_spi_prepare：ストアドプロシージャの事前処理段階。

   • pl_spi_execute：ストアドプロシージャ内のspiステートメントを実行する。

   • inner_prepare：内部SQLの事前処理段階。

   • inner_execute：内部SQLの実行段階。

   • inner_execute_read：内部SQLの読み取り。

   • inner_execute_write：内部SQLの書き込み。

   • inner_commit：内部SQLトランザクションのコミット。

   • inner_rollback：内部SQLトランザクションのロールバック。

3. trace_idを使用してログファイルから直前のSQLリクエストの完全なログを検索します。

   OceanBaseデータベースのログ出力には常にtrace_idが含まれます。ログファイル(observer.log、election.log、rootservice.log)で対応するtrace_idを検索することで、直前のSQLリクエストの完全なログを取得できます。

   1. last_trace_id()を使用してtrace_idを取得します。

      obclient [test]> SELECT last_trace_id() FROM DUAL;
      +-----------------------------------+
      | last_trace_id()                   |
      +-----------------------------------+
      | YB42AC1E87CC-0005F6BFDB3E2199-0-0 |
      +-----------------------------------+
      1 row in set (0.000 sec)
      

   2. 対応するOBServerノードにログインし、ログファイルがあるディレクトリに移動します。

      cd /home/admin/oceanbase/log
      

   3. trace_idに対応するログを取得し、grep $trace_id observer.logコマンドを実行します。例えば、trace_idがYB42AC1E87CC-0005F6BFDB3E2199-0-0のログを取得します。

      grep YB42AC1E87CC-0005F6BFDB3E2199-0-0  observer.log
      [2023-03-22 14:30:33.124342] [38419][T1_L0_G0][T1][YB42AC1E87CC-0005F6BFDB3E2199-0-0] {"trace_id":"0005f777-4c14-595f-508c-6681b3dac7c9","name":"pc_get_plan","id":"0005f777-4c14-59f1-5c54-a90e3ff82e85","start_ts":1679466633124337,"end_ts":1679466633124340,"parent_id":"0005f777-4c14-59ef-de27-961b48ecfdfd","is_follow":false}