Aurora PostgreSQL Limitless Database の PostgreSQL ログでの分散クエリトレース - Amazon Aurora
トレース IDクエリトレースの使用ログの例

Aurora PostgreSQL Limitless Database の PostgreSQL ログでの分散クエリトレース

分散クエリトレースは、Aurora PostgreSQL Limitless Database 全体で PostgreSQL ログのクエリをトレースして相関させるツールです。Aurora PostgreSQL では、トランザクション ID を使用してトランザクションを識別します。ただし、Aurora PostgreSQL Limitless Database では、トランザクション ID はさまざまなルーターで繰り返し使用される場合があります。そのため、Limitless Database では代わりにトレース ID を使用することをお勧めします。

主なユースケースを以下に示します。

  • rds_aurora.limitless_get_last_trace_id() 関数を使用して、現在のセッションで最後に実行されたクエリの一意のトレース ID を特定します。次に、そのトレース ID を使用して Amazon CloudWatch Logs で DB クラスターロググループを検索し、関連するすべてのログを見つけます。

    log_min_messages パラメータと log_min_error_statement パラメータを併用すると、出力されるログの量を制御し、トレース ID を含むステートメントを出力できます。

  • log_min_duration_statement パラメータを使用して、すべてのクエリが実行時間とトレース ID を出力する実行時間を判断します。その後、この実行時間を CloudWatch Logs の DB クラスターロググループで検索して、ボトルネックノードとプランナーの最適化作業を決定できます。

    log_min_duration_statement パラメータは、log_min_messages および log_min_error_statement パラメータの値に関係なく、すべてのノードに対してトレース ID を有効にします。

トレース ID

この機能の中心となるのは、トレース ID と呼ばれる一意の識別子です。トレース ID は、PostgreSQL ログの STATEMENT ログ行に追加される 31 桁の文字列で、特定のクエリ実行に関連するログを相関させるための正確な識別子として機能します。例は、1126253375719408504000000000011 および 1126253375719408495000000000090 です。

トレース ID は、以下で構成されます。

  • トランザクション識別子 – トランザクションを一意に識別する最初の 20 桁。

  • コマンド識別子 – トランザクション内の個々のクエリを示す最初の 30 桁。

    明示的なトランザクションブロック内で 4,294,967,294 件を超えるクエリが実行された場合、コマンド識別子は 1 に戻ります。この場合、PostgreSQL ログの次の LOG メッセージで通知されます。

    wrapping around the tracing ID back to 1 after running 4294967294 (4.2 billion or 2^32-2) queries inside of an explicit transaction block

  • ノードタイプ識別子 – ノードがコーディネータールーター (1) または参加者ノード (0) として機能しているかどうかを示す最後の桁。

次の例は、トレース ID のコンポーネントを示しています。

  • 1126253375719408504000000000011:

    • トランザクション識別子 – 1126253375719408504

    • コマンド識別子 — 112625337571940850400000000001 は、トランザクションブロックの最初のコマンドを示します

    • ノードタイプ識別子 — 1 は、コーディネータールーターを示します

  • 1126253375719408495000000000090:

    • トランザクション識別子 – 1126253375719408495

    • コマンド識別子 — 112625337571940849500000000009 は、トランザクションブロック内の 9 番目のコマンドを示します

    • ノードタイプ識別子 — 0 は、参加ノードを示します

クエリトレースの使用

クエリトレースを使用するには、次のタスクを実行します。

  1. トレースが有効になっていることを確認します。

    次のコマンドを使用して確認できます。

    SHOW rds_aurora.limitless_log_distributed_trace_id;

    デフォルトでは有効 (on) になっています。有効になっていない場合は、次のコマンドを使用して設定します。

    SET rds_aurora.limitless_log_distributed_trace_id = on;

  2. ログの重要度レベルを設定して、出力されるログの量を制御します。

    ログの量は、log_min_messages パラメータによって制御されます。log_min_error_statement パラメータは、トレース ID を含む STATEMENT 行を出力するために使用されます。どちらもデフォルトで ERROR に設定されています。次のコマンドを使用して確認できます。

    SHOW log_min_messages;
SHOW log_min_error_statement;

    重要度レベルを更新し、現在のセッションの STATEMENT 行を出力するには、次のいずれかの重要度レベルで次のコマンドを使用します。

    SET log_min_messages = 'DEBUG5 | DEBUG4 | DEBUG3 | DEBUG2 | DEBUG1 | INFO | NOTICE | WARNING | ERROR | LOG | FATAL | PANIC';
SET log_min_error_statement = 'DEBUG5 | DEBUG4 | DEBUG3 | DEBUG2 | DEBUG1 | INFO | NOTICE | WARNING | ERROR | LOG | FATAL | PANIC';

    以下に例を示します。

    SET log_min_messages = 'WARNING';
SET log_min_error_statement = 'WARNING';

  3. 特定の実行時間を超えた場合に、ログへのトレース ID の出力を有効にします。

    log_min_duration_statement パラメータは最小クエリ実行時間に変更でき、この時間を超えた場合、クエリは実行時間を含むログ行と、DB クラスター全体のトレース ID を出力します。このパラメータはデフォルトで -1 に設定されます。つまり、無効になっています。次のコマンドを使用して確認できます。

    SHOW log_min_duration_statement;

    これを 0 に変更すると、DB クラスター全体のすべてのクエリのログに実行時間とトレース ID が出力されます。次のコマンドを使用して、現在のセッションに対して 0 に設定できます。

    SET log_min_duration_statement = 0;

  4. トレース ID を取得します。

    クエリを実行した後 (明示的なトランザクションブロック内であっても)、rds_aurora.limitless_get_last_trace_id 関数を呼び出して、最後のクエリ実行のトレース ID を取得します。

    SELECT * FROM rds_aurora.limitless_get_last_trace_id();

    この関数は、トランザクション識別子とコマンド識別子を返します。ノードタイプ識別子は返されません。

    => SELECT * FROM customers;
 customer_id | fname | lname 
-------------+-------+-------
(0 rows)

=> SELECT * FROM rds_aurora.limitless_get_last_trace_id();
 transaction_identifier |       command_identifier       
------------------------+--------------------------------
 10104661421959001813   | 101046614219590018130000000001
(1 row)

    この関数は、非分散クエリには空白行を返します。非分散クエリにはトレース ID がないためです。

    => SET search_path = public;
SET

=> SELECT * FROM rds_aurora.limitless_get_last_trace_id();
 transaction_identifier | command_identifier 
------------------------+--------------------
                        | 
(1 row)
    注記

    VACUUM クエリと ANALYZE クエリの場合、実行時間のステートメントはトレース ID とともにログに記録されません。そのため、limitless_get_last_trace_id() はトレース ID を返しません。VACUUM または ANALYZE が長時間実行されるオペレーションの場合は、次のクエリを使用して、そのオペレーションのトレース ID を取得できます。

    SELECT * FROM rds_aurora.limitless_stat_activity 
WHERE distributed_tracing_id IS NOT NULL;

    最後のトレース ID が見つかる前にサーバーが停止した場合は、PostgreSQL ログを手動で検索して、停止直前のログでトレース ID を見つける必要があります。

  5. CloudWatch を使用して DB クラスターログ全体でトレース ID を検索します。

    次の例に示すように、CloudWatch Insights を使用して DB クラスターのロググループをクエリします。

    • 特定のトランザクション識別子をクエリし、その中ですべてのコマンドを実行します。

      fields @timestamp, @message
| filter @message like /10104661421959001813/
| sort @timestamp desc

    • 特定のコマンド識別子をクエリします。

      fields @timestamp, @message
| filter @message like /101046614219590018130000000001/
| sort @timestamp desc

  6. 分散クエリによって生成された DB クラスター全体のすべてのログを調べます。

ログの例

以下は、クエリトレースの使用例を示しています。

エラーが発生しやすいクエリのログの相関付け

この例では、customers テーブルが存在しない場合に、そのテーブルで TRUNCATE コマンドが実行されます。

クエリトレースなし

コーディネータールーターの PostgreSQL ログファイル:

2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:DETAIL: relation "public.customers" does not exist
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:CONTEXT: remote SQL command: truncate public.customers;
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:STATEMENT: truncate customers;

参加シャードの PostgreSQL ログファイル:

2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[ 27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[ 27503]:STATEMENT: truncate customers;

これらのログが一般的です。DB クラスター全体でクエリを簡単に相関付けるために必要な正確な識別子がありません。

クエリトレースあり

コーディネータールーターの PostgreSQL ログファイル:

2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:DETAIL: relation "public.customers" does not exist
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:CONTEXT: remote SQL command: truncate public.customers;
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:STATEMENT: /* tid = 1126253375719408502700000000011 */ truncate customers;

参加シャードの PostgreSQL ログファイル:

2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:ERROR:  failed to execute remote query
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:STATEMENT:  /* tid = 1126253375719408502700000000010 */ truncate customers;

クエリトレースが存在する場合、各ログ行には 31 桁の一意の識別子が追加されます。ここで、1126253375719408502700000000011 と 1126253375719408502700000000010 は、コーディネーターノードと参加ノードのトレース ID をそれぞれ表します。

  • トランザクション識別子 – 11262533757194085027

  • コマンド識別子 – 112625337571940850270000000001

  • ノードタイプ識別子 – 最後の桁、1 または 0 は、それぞれコーディネータールーターと参加ノードを示します。

ログを相関付けて、さまざまなノードのクエリ実行時間を特定する

この例では、すべてのクエリの実行時間が出力されるように、log_min_duration_statement パラメータが 0 に更新されています。

クエリトレースなし
2024-01-15 07:28:46 UTC:[local]:postgres@postgres_limitless:[178322]:LOG: duration: 12.779 ms statement: select * from customers;
クエリトレースあり

コーディネータールーターの PostgreSQL ログファイル:

2024-01-15 07:32:08 UTC:[local]:postgres@postgres_limitless:[183877]:LOG: duration: 12.618 ms statement: /* tid = 0457669566240497088400000000011 */ select * from customers;

参加シャードの PostgreSQL ログファイル:

2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.279 ms statement: /* tid = 0457669566240497088400000000010 */ START TRANSACTION ISOLATION LEVEL READ COMMITTED
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.249 ms parse <unnamed>: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.398 ms bind <unnamed>/c1: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.019 ms execute <unnamed>/c1: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.073 ms statement: /* tid = 0457669566240497088400000000010 */ COMMIT TRANSACTION