Amazon RDS PostgreSQL または Aurora PostgreSQL のクエリの実行プランをログ記録して、クエリのパフォーマンスを調整する方法を教えてください。

所要時間4分

クエリにどの実行プランが使用されているかを知った上で調整したいと考えています。Amazon Relational Database Service (Amazon RDS) PostgreSQL DB インスタンスや Amazon Aurora PostgreSQL DB クラスター用のクエリの実行計画をログ記録する方法を教えてください。

解決方法

auto_explain モジュールを使用すると、クエリの実行プランをログ記録できます。

1. shared_preload_libraries パラメータに auto_explain を追加します。

2. DB インスタンスまたはクラスターを再起動します。

3. auto_explain を有効にするには、 auto_explain.log_min_duration パラメータを -1 以外の値に変更する必要があります。この値は、渡されて文が実行された場合、その実行プランがログ記録される最小文実行時間 (ミリ秒単位) です。パラメータを 0 に設定すると、すべてのプランがログ記録されます。

重要: auto_explain.log_min_duration パラメータを 0 に設定すると、パフォーマンスが低下し、記憶域スペースが広範囲に消費されます。これにより、インスタンスに問題が発生する可能性があります。

4. データベースでクエリを実行します。

5. 実行プランを含む PostgreSQL ログファイルを表示またはダウンロードします。次の実行プランの例には、実行時間 (4673.182 ms) とクエリテキストを含む実行プランがあります。

2020-01-02 03:08:44 UTC:27.0.3.156(21356):postgres@postgres:[2040]:LOG: duration: 4673.182 ms plan:
Query Text: SELECT COUNT(*) FROM hoge ORDER BY 1;
Sort (cost=215575.00..215575.00 rows=1 width=8)
Sort Key: (count(*))
-> Aggregate (cost=215574.98..215574.99 rows=1 width=8)
-> Seq Scan on hoge (cost=0.00..190336.18 rows=10095518 width=0)

auto_explain パラメータを使用してクエリのパフォーマンスを調整する

pg_autoexplain を有効にするだけでなく、auto_explain.log_min_duration パラメータを使うことで、他の便利なパラメータを使用することもできます。次の auto_explain パラメータ (再起動せずに変更可能) を使用して、クエリのパフォーマンスを調整できます。詳細については、「各パラメータ用の PostgreSQL ドキュメント」を参照してください。

auto_explain.log_analyze

auto_explain.log_analyze パラメータは、実行プランがログ記録されたときに、EXPLAIN ANALYZE 出力 (EXPLAIN 出力ではなく) を表示します。このパラメータは、オーバーヘッドが原因でクエリのパフォーマンスが低下することがあり、デフォルト値は off です。詳細については、Postgres ドキュメントの auto_explain.log_analze を参照してください。

次の例を参照してください。

2020-02-01 07:42:09 UTC:27.0.3.145(29943):master@postgres:[789]:LOG:  duration: 18.658 ms  plan:
 Query Text: SELECT COUNT(*) FROM t1 INNER JOIN t2 USING(id);
 Aggregate  (cost=577.45..577.46 rows=1 width=8) (actual time=18.641..18.641 rows=1 loops=1)
   ->  Hash Join  (cost=269.98..552.45 rows=9999 width=0) (actual time=8.108..16.576 rows=9999 loops=1)
         Hash Cond: (t1.id = t2.id)
         ->  Seq Scan on t1  (cost=0.00..144.99 rows=9999 width=4) (actual time=0.839..4.151 rows=9999 loops=1)
         ->  Hash  (cost=144.99..144.99 rows=9999 width=4) (actual time=7.186..7.186 rows=9999 loops=1)
               Buckets: 16384  Batches: 1  Memory Usage: 480kB
               ->  Seq Scan on t2  (cost=0.00..144.99 rows=9999 width=4) (actual time=0.667..4.289 rows=9999 loops=1)

auto_explain.log_buffers

auto_explain.log_buffers パラメータを使用して、実行プランをログ記録するときにバッファ使用状況の統計を表示するかどうかを決定します。このパラメータを使用すると、Explain で Buffers オプションを使用した場合と同じ効果があります。 auto_explain.log_analyze と auto_explain.log_buffers を有効にしてください。デフォルトでは、このパラメータは off になっており、ユーザーがスーパーユーザーである場合のみ変更できます。詳細については、PostgreSQL のドキュメントの auto_explain.log_buffers を参照してください。

次の出力例を参照してください。

2020-02-01 08:02:02 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 14.875 ms  plan:
 Query Text: SELECT COUNT(*) FROM t1 INNER JOIN t2 USING(id);
 Aggregate  (cost=577.45..577.46 rows=1 width=8) (actual time=14.861..14.861 rows=1 loops=1)
   Buffers: shared hit=93
   ->  Hash Join  (cost=269.98..552.45 rows=9999 width=0) (actual time=5.293..12.768 rows=9999 loops=1)
         Hash Cond: (t1.id = t2.id)
         Buffers: shared hit=93
         ->  Seq Scan on t1  (cost=0.00..144.99 rows=9999 width=4) (actual time=0.007..2.385 rows=9999 loops=1)
               Buffers: shared hit=45
         ->  Hash  (cost=144.99..144.99 rows=9999 width=4) (actual time=5.250..5.250 rows=9999 loops=1)
               Buckets: 16384  Batches: 1  Memory Usage: 480kB
               Buffers: shared hit=45
               ->  Seq Scan on t2  (cost=0.00..144.99 rows=9999 width=4) (actual time=0.009..2.348 rows=9999 loops=1)
                     Buffers: shared hit=45

auto_explain.log_nested_statements

auto_explain.log_nested_statements パラメータを使用して、ネストされた文をログ記録に用いることを検討します。このパラメータを有効にしない限り、既定では、最上位のクエリプランがログ記録されます。デフォルト値は off です。詳細については、PostgreSQL のドキュメントの auto_explain.nested_statements を参照してください。

次の例を参照してください。

CREATE OR REPLACE FUNCTION count_tables() RETURNS integer AS $$
        DECLARE
         i integer;
         j integer;
        BEGIN
                SELECT COUNT(*) INTO i FROM t1;
                SELECT COUNT(*) INTO j FROM t2;
                RETURN i + j;                
        END;
$$ LANGUAGE plpgsql;

次の出力例を参照してください。

2020-02-01 08:15:25 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 0.651 ms  plan:
 Query Text: SELECT COUNT(*)        FROM t1
 Aggregate  (cost=169.99..170.00 rows=1 width=8)
   ->  Seq Scan on t1  (cost=0.00..144.99 rows=9999 width=0)
2020-02-01 08:15:25 UTC:27.0.3.145(27477):master@postgres:[15514]:CONTEXT:  SQL statement "SELECT COUNT(*)        FROM t1"
 PL/pgSQL function count_tables() line 6 at SQL statement
2020-02-01 08:15:25 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 0.637 ms  plan:
 Query Text: SELECT COUNT(*)        FROM t2
 Aggregate  (cost=169.99..170.00 rows=1 width=8)
   ->  Seq Scan on t2  (cost=0.00..144.99 rows=9999 width=0)
2020-02-01 08:15:25 UTC:27.0.3.145(27477):master@postgres:[15514]:CONTEXT:  SQL statement "SELECT COUNT(*)        FROM t2"
 PL/pgSQL function count_tables() line 7 at SQL statement
2020-02-01 08:15:25 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 1.435 ms  plan:
 Query Text: SELECT count_tables();
 Result  (cost=0.00..0.26 rows=1 width=4)

auto_explain.log_timing

実行プランをログ記録するときにノードごとのタイミング情報を表示するかどうかを制御するには、auto_explain.log_timing パラメータを使用します。このパラメータを使用すると、[Timing] と [Explain] を使用する場合と同様に機能します。auto_explain.log_timing を無効にすると、システムクロックを繰り返し読み取るオーバーヘッドを軽減できます。デフォルト値は on です。詳細については、PostgreSQL のドキュメントの auto_explain.log_timing を参照してください。

auto_explain.log_triggers

実行プランをログ記録するときにトリガー実行の統計を含めるには、auto_explain.log_triggers パラメータを使用します。auto_explain.log_triggers を使用するときは、auto_explain.log_analyze も有効にする必要があります。デフォルト値は off です。

詳細については、PostgreSQL のドキュメントの auto_explain.log_triggers を参照してください。

次の例を参照してください。

CREATE FUNCTION emp_log_trigger_func() RETURNS trigger AS $emp_stamp$
    DECLARE
        count integer;
    BEGIN
        SELECT COUNT(*) INTO count FROM emp WHERE empname = NEW.empname;
        INSERT INTO emp_log(created_at, operation, user_name) VALUES(current_timestamp, TG_OP, user);
        RETURN NEW;
    END;
$emp_stamp$ LANGUAGE plpgsql;
CREATE TRIGGER emp_stamp BEFORE INSERT OR UPDATE ON emp
    FOR EACH ROW EXECUTE PROCEDURE emp_log_trigger_func();

次の出力例を参照してください。

2020-02-01 08:57:44 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 1.463 ms  plan:
 Query Text: INSERT INTO emp_log(created_at, operation, user_name) VALUES(current_timestamp, TG_OP, user)
 Insert on emp_log  (cost=0.00..0.03 rows=1 width=168) (actual time=1.461..1.461 rows=0 loops=1)
   ->  Result  (cost=0.00..0.03 rows=1 width=168) (actual time=0.009..0.010 rows=1 loops=1)
2020-02-01 08:57:44 UTC:27.0.3.145(27477):master@postgres:[15514]:CONTEXT:  SQL statement "INSERT INTO emp_log(created_at, operation, user_name) VALUES(current_timestamp, TG_OP, user)"
 PL/pgSQL function emp_log_trigger_func() line 3 at SQL statement
2020-02-01 08:57:44 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 1.602 ms  plan:
 Query Text: INSERT INTO emp VALUES('name', 100, current_timestamp, 'hoge');
 Insert on emp  (cost=0.00..0.01 rows=1 width=76) (actual time=1.600..1.600 rows=0 loops=1)
   ->  Result  (cost=0.00..0.01 rows=1 width=76) (actual time=0.006..0.006 rows=1 loops=1)
 Trigger emp_stamp: time=1.584 calls=1

auto_explain.log_verbose

実行プランのログを記録するときに詳細情報を表示するかどうかを決定するには、auto_explain.log_verbose パラメータを使用します。このパラメータを使用すると、Verbose オプションと Explain を使用する場合と同様に機能します。デフォルト値は off です。詳細については、PostgreSQL のドキュメントの auto_explain.log_verbose を参照してください。

次の例を参照してください。

2020-02-01 09:03:20 UTC:27.0.3.145(27477):master@postgres:[15514]:LOG:  duration: 3.492 ms  plan:
 Query Text: SELECT COUNT(*) FROM t1 INNER JOIN t2 USING(id);
 Aggregate  (cost=577.45..577.46 rows=1 width=8)
   Output: count(*)
   ->  Hash Join  (cost=269.98..552.45 rows=9999 width=0)
         Hash Cond: (t1.id = t2.id)
         ->  Seq Scan on public.t1  (cost=0.00..144.99 rows=9999 width=4)
               Output: t1.id
         ->  Hash  (cost=144.99..144.99 rows=9999 width=4)
               Output: t2.id
               Buckets: 16384  Batches: 1  Memory Usage: 480kB
               ->  Seq Scan on public.t2  (cost=0.00..144.99 rows=9999 width=4)
                     Output: t2.id

または、調整するために少ないクエリの説明プランを表示する場合は、そのようなクエリに対して EXPLAIN ANALYZE を実行できます。これにより、ログ作成のオーバーヘッドがなくなり、クエリのプランがステップごとに表示され、さらに各ステップの実行時間が表示されます。EXPLAIN ANALYZE 文を手動で呼び出す場合は、一時ファイルを生成したステップ、シーケンススキャンを実行しているステップなどのイベントを特定できます。

postgres=> EXPLAIN ANALYZE SELECT * FROM hoge ORDER BY 1;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Sort (cost=7343904.60..7444904.60 rows=40400000 width=4) (actual time=37795.033..45133.431 rows=40400000 loops=1)
Sort Key: id
Sort Method: external merge Disk: 553512kB
-> Seq Scan on hoge (cost=0.00..582762.00 rows=40400000 width=4) (actual time=0.579..8184.498 rows=40400000 loops=1)
Planning Time: 0.549 ms
Execution Time: 47161.516 ms
(6 rows)

Amazon RDS PostgreSQL または Aurora PostgreSQL のクエリの実行プランをログ記録して、クエリのパフォーマンスを調整する方法を教えてください。

解決方法

auto_explain パラメータを使用してクエリのパフォーマンスを調整する

関連情報

関連ビデオ

関連するコンテンツ