kt.log

Investigate query performance with Query Store on Azure Database for PostgreSQL

クエリのパフォーマンスを Azure Database for PostgreSQL の クエリ ストア を使って調査する

PostgreSQL に限らず、リレーショナルデータベースにおけるパフォーマンスチューニングに、クエリ実行に関する調査は必要不可欠です。具体的には、個々のクエリの実行時間を洗い出し、実行プランを把握し、待機イベント/待機統計等を調査してクエリの実行を阻害している要因を特定します。

本記事では、Azure Database for PostgreSQL において、上記をどのように行うのかを、 (Azure ではなく) PostgreSQL 自体が提供する方法と比較し、例を交えて解説します。

前提

  • PostgreSQL が提供する方法としては、主に pg_stat_statements を使用します。
  • Azure Database for PostgreSQL が提供する方法としては、 クエリ ストア を使用します。
  • psql コマンドの利用を想定します。
  • \x on を実行し、実行結果を見やすくしておきます。

クエリの実行時間

PostgreSQL

pg_stat_statements を使用します。

実行例

1
2
3
4
SELECT query, calls, total_time, rows 
FROM pg_stat_statements 
ORDER BY total_time DESC 
LIMIT 1;
1
(0 rows)

Azure Database for PostgreSQL

クエリ ストア を使用します。

最も実行時間が長いクエリを特定する例:

1
2
3
4
5
6
SELECT DISTINCT query_sql_text, total_time 
FROM query_store.query_texts_view AS qtv 
INNER JOIN query_store.runtime_stats_view AS rsv 
ON qtv.query_text_id = rsv.query_id 
ORDER BY total_time DESC 
LIMIT 1;
1
2
3
 -[ RECORD 1 ]--+-----------------------------------------------------
query_sql_text | SELECT pg_start_backup('2022-02-3--09-06-16', false)
total_time     | 12269.1204319065

クエリの実行プラン

PostgreSQL

EXPLAIN または EXPLAIN ANALYZE を使用します。

EXPLAIN の例

1
2
3
4
5
6
7
EXPLAIN 
SELECT DISTINCT query_sql_text, total_time 
FROM query_store.query_texts_view AS qtv 
INNER JOIN query_store.runtime_stats_view AS rsv 
ON qtv.query_text_id = rsv.query_id 
ORDER BY total_time DESC 
LIMIT 1;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
-[ RECORD 1 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=513.75..513.75 rows=1 width=282)
-[ RECORD 2 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=513.75..516.25 rows=1000 width=282)
-[ RECORD 3 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: pivoted_runtime_stats_values.total_time DESC
-[ RECORD 4 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  HashAggregate  (cost=498.75..508.75 rows=1000 width=282)
-[ RECORD 5 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               Group Key: pivoted_runtime_stats_values.total_time, query_texts.query_sql_text
-[ RECORD 6 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash Join  (cost=478.39..493.75 rows=1000 width=282)
-[ RECORD 7 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Hash Cond: (runtime_stats_entries.query_id = query_texts.query_text_id)
-[ RECORD 8 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash Join  (cost=468.09..480.72 rows=1000 width=16)
-[ RECORD 9 ]-----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Hash Cond: (pivoted_runtime_stats_values.runtime_stats_entry_id = runtime_stats_entries.runtime_stats_entry_id)
-[ RECORD 10 ]----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Function Scan on crosstab pivoted_runtime_stats_values  (cost=0.00..10.00 rows=1000 width=16)
-[ RECORD 11 ]----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Hash  (cost=278.04..278.04 rows=15204 width=16)
-[ RECORD 12 ]----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 ->  Seq Scan on runtime_stats_entries  (cost=0.00..278.04 rows=15204 width=16)
-[ RECORD 13 ]----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash  (cost=9.02..9.02 rows=102 width=282)
-[ RECORD 14 ]----------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Seq Scan on query_texts  (cost=0.00..9.02 rows=102 width=282)

EXPLAIN ANALYZE の例

1
2
3
4
5
6
7
EXPLAIN ANALYZE 
SELECT DISTINCT query_sql_text, total_time 
FROM query_store.query_texts_view AS qtv 
INNER JOIN query_store.runtime_stats_view AS rsv 
ON qtv.query_text_id = rsv.query_id 
ORDER BY total_time DESC 
LIMIT 1;
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
-[ RECORD 1 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=513.75..513.75 rows=1 width=282) (actual time=531.545..531.548 rows=1 loops=1)
-[ RECORD 2 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=513.75..516.25 rows=1000 width=282) (actual time=531.544..531.547 rows=1 loops=1)
-[ RECORD 3 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: pivoted_runtime_stats_values.total_time DESC
-[ RECORD 4 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Method: top-N heapsort  Memory: 26kB
-[ RECORD 5 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  HashAggregate  (cost=498.75..508.75 rows=1000 width=282) (actual time=528.541..529.800 rows=8405 loops=1)
-[ RECORD 6 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               Group Key: pivoted_runtime_stats_values.total_time, query_texts.query_sql_text
-[ RECORD 7 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash Join  (cost=478.39..493.75 rows=1000 width=282) (actual time=507.635..520.945 rows=15647 loops=1)
-[ RECORD 8 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Hash Cond: (runtime_stats_entries.query_id = query_texts.query_text_id)
-[ RECORD 9 ]-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash Join  (cost=468.09..480.72 rows=1000 width=16) (actual time=507.535..518.182 rows=15647 loops=1)
-[ RECORD 10 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Hash Cond: (pivoted_runtime_stats_values.runtime_stats_entry_id = runtime_stats_entries.runtime_stats_entry_id)
-[ RECORD 11 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Function Scan on crosstab pivoted_runtime_stats_values  (cost=0.00..10.00 rows=1000 width=16) (actual time=504.439..511.154 rows=15647 loops=1)
-[ RECORD 12 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Hash  (cost=278.04..278.04 rows=15204 width=16) (actual time=3.066..3.066 rows=15647 loops=1)
-[ RECORD 13 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Buckets: 16384  Batches: 1  Memory Usage: 862kB
-[ RECORD 14 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 ->  Seq Scan on runtime_stats_entries  (cost=0.00..278.04 rows=15204 width=16) (actual time=0.019..1.573 rows=15647 loops=1)
-[ RECORD 15 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash  (cost=9.02..9.02 rows=102 width=282) (actual time=0.094..0.095 rows=108 loops=1)
-[ RECORD 16 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Buckets: 1024  Batches: 1  Memory Usage: 42kB
-[ RECORD 17 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Seq Scan on query_texts  (cost=0.00..9.02 rows=102 width=282) (actual time=0.012..0.053 rows=108 loops=1)
-[ RECORD 18 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning Time: 0.332 ms
-[ RECORD 19 ]----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution Time: 536.642 ms

Azure Database for PostgreSQL

本記事執筆時点においては、Azure Database for PostgreSQL が独自に提供する方法はありません。
query_store.qs_view に plan_id があり、実行プランの ID を取得できりようになってはいますが、まだ利用できません (値が入っていません)。
したがって、通常の PostgreSQL と同様、 EXPLAIN / EXPLAIN ANALYZE を使用します。

待機イベント

PostgreSQL

pg_stat_activity を使用します。

実行例

1
2
3
SELECT pid, wait_event_type, wait_event 
FROM pg_stat_activity 
WHERE wait_event IS NOT NULL;
1
(0 rows)

Azure Database for PostgreSQL

クエリ ストア を使用します。

最も実行時間が長いクエリの待機イベントを特定する例

1
2
3
4
5
6
7
8
SELECT DISTINCT pwsv.start_time, pwsv.end_time, qv.total_time, pwsv.event_type, pwsv.event, qtv.query_sql_text 
FROM query_store.pgms_wait_sampling_view AS pwsv 
INNER JOIN query_store.qs_view AS qv 
ON pwsv.query_id = qv.query_id 
INNER JOIN query_store.query_texts_view AS qtv 
ON pwsv.query_id = qtv.query_text_id 
ORDER BY total_time DESC 
LIMIT 1;
1
2
3
4
5
6
7
-[ RECORD 1 ]--+-----------------------------------------------------
start_time     | 2022-07-13 15:59:44+00
end_time       | 2022-07-13 16:14:44+00
total_time     | 12269.1204319065
event_type     | IO
event          | WALWrite
query_sql_text | SELECT pg_start_backup('2022-02-3--09-06-16', false)

まとめ

Azure Database for PostgreSQL において、クエリのパフォーマンスに関する調査をどのように行うのかを、PostgreSQL の標準的な方法と比較し、例を交えて解説しました。

クエリ ストア ではかなり詳細な情報を得ることができます。また、上記で挙げた SQL はほんの一例です。膨大なデータを活用し、パフォーマンスの改善に役立てていきましょう。

See also

全般

クエリの実行時間

クエリの実行プラン

待機イベント