Amazon RDS PostgreSQL または Aurora PostgreSQL のクエリの実行プランをログ記録して、クエリのパフォーマンスを調整する方法を教えてください。
クエリにどの実行プランが使用されているかを知った上で調整したいと考えています。Amazon Relational Database Service (Amazon RDS) PostgreSQL DB インスタンスや Amazon Aurora PostgreSQL DB クラスター用のクエリの実行計画をログ記録する方法を教えてください。
解決方法
auto_explain モジュールを使用すると、クエリの実行プランをログ記録できます。
1. shared_preload_libraries パラメータに auto_explain を追加します。
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)
関連情報
auto_explain に関する PostgreSQL のドキュメント
エラー報告とログ記録に関する PostgreSQL ドキュメント
EXPLAIN の使用に関する PostgreSQLドキュメント
関連するコンテンツ
- 質問済み 6年前lg...
- 承認された回答質問済み 4ヶ月前lg...
- 質問済み 3ヶ月前lg...
- AWS公式更新しました 1年前