PostgreSQL 13がやってくる！(4) - pg_stat_statementsの改善

はじめに

にゃーん。
今回は小ネタ。PostgreSQL 13で追加された、pg_stat_statements拡張モジュールの追加機能について試してみました。
(まだβ版リリース前なので、変更される可能性はありますが）

pg_stat_statements is 何？

pg_stat_statementsは、サーバで実行されたすべてのSQL文の実行時の統計情報を記録する拡張機能です。この拡張機能はPostgreSQL 8.4からサポートされています。

このモジュールの内容については、PostgreSQL文書を見てもらうのが手っ取り早いのですが、このモジュールを使うことで、運用中のクエリの性能が（レコード件数の増加や、実行計画の変更によって）の概要を確認することができます。
また、経時的な情報を確認するためには、pg_stat_statementsを利用した、pg_statsinfoを使います。

PostgreSQL 13で何が変わった？

PostgreSQL 13では、実行時の処理時間の情報だけでなくプランナによる「実行計画の生成時間」も取得できるようになりました。
収集された情報は、pg_stat_statementsビューで確認できるのですが、PostgreSQL 13ではそのpg_stat_statementsビューに以下の項目が追加されました。

この機能の改造に関するコミュニティ内の議論については、CommitfestのPlanning counters in pg_stat_statementsから追うことができます。（と、書きつつ自分もきちんと議論は追ってませんが・・・）

PostgreSQL 13で追加された、pg_stat_statementsの列は以下のとおり。

列名	型	内容
plans	bigint	ステートメントが計画された回数
total_plan_time	double precision	ステートメントの計画に費やされた合計時間（ミリ秒）
min_plan_time	double precisio	ステートメントの計画に費やされた最小時間（ミリ秒）
max_plan_time	double precisio	ステートメントの計画に費やされた最大時間（ミリ秒）
mean_plan_time	double precisio	ステートメントの計画に費やされた平均時間（ミリ秒）
stddev_plan_time	double precisio	ステートメントの計画に費やされた時間の母標準偏差（ミリ秒）
wal_bytes	numeric	ステートメントによって生成されたWALバイトの合計量
wal_records	bigint	ステートメントによって生成されたWALレコードの総数
wal_num_fpw	bigint	ステートメントによって生成されたWALフルページ書き込みの総数

実行時間と同等の情報が、実行計画生成に関しても追加されたって感じですね。
あと、更にWAL生成に関する統計情報が追加されたようです。

試してみた(1) プラン生成時間の統計情報

実行改革の生成時間に差をつけるために、今回は以下の2つのパターンのテーブルに対する検索を行う。

• パターン１(1000の子テーブルをもつHASHパーティション)
• パターン2（パーティションを保たない単なるテーブル)

準備

以下のようなSQLスクリプトをpsqlに食わせる。

$ more part.sql
DROP TABLE accounts1 CASCADE;
DROP TABLE accounts2 CASCADE;

CREATE TABLE accounts1(aid int not null, bid int, abalance int, filler character(84)) PARTITION BY HASH (aid);

SELECT 'CREATE TABLE accounts_p' ||
generate_series(0, 999)
|| ' PARTITION OF accounts1 FOR VALUES WITH (MODULUS 1000, REMAINDER ' ||
generate_series(0, 999)
|| ');'
\gexec

CREATE TABLE accounts2(aid int not null, bid int, abalance int, filler character(84));

これをpsqlに食わせると、accounts1は1000の子ーテーブルを持つHASHパーティションテーブルとなる。accnouts2は同じ列を持つ普通のテーブルとなる。

クエリの実行

一旦、pg_stat_statementsの情報をクリアする。

testdb=# SELECT pg_stat_statements_reset();
 pg_stat_statements_reset
--------------------------

(1 row)

その後に、以下のクエリをそれぞれ3回実行する。

testdb=# SELECT COUNT(*) FROM accounts1;
 count
-------
     0
(1 row)

testdb=# SELECT COUNT(*) FROM accounts2;
 count
-------
     0
(1 row)

ビューの確認。

この状態で、実行計画生成に関する統計情報を収集する。

testdb=# SELECT plans, total_plan_time, min_plan_time, min_plan_time, mean_plan_time, stddev_plan_time, query FROM pg_stat_statements WHERE query ~ 'COUNT';
 plans | total_plan_time | min_plan_time | min_plan_time | mean_plan_time |   stddev_plan_time   |             query
-------+-----------------+---------------+---------------+----------------+----------------------+--------------------------------
     4 |      147.851933 |     14.427471 |     14.427471 |    36.96298325 |    38.68939290687077 | SELECT COUNT(*) FROM accounts1
     3 |        0.287184 |      0.071609 |      0.071609 |       0.095728 | 0.032555040848794306 | SELECT COUNT(*) FROM accounts2
(2 rows)

testdb=#

想定どおり、(1000の子テーブルを持つ)パーティションテーブルに対する検索は通常のテーブルと比較すると、実行計画生成だけでも、かなり時間がかかることがわかる。

試してみた(2) WALに関する統計情報

今度は、

準備

以下の2種類のテーブルを用意する。
1つは普通のテーブル。もう一つは同じ構造だけど、UNLOGGED TABLEとして生成する。

CREATE TABLEの背景でもWALは生成される。

testdb=# CREATE TABLE test (id int, data text);
CREATE TABLE
testdb=# CREATE UNLOGGED TABLE test_u (id int, data text);
CREATE TABLE
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test';
                      query                       | calls | wal_records | wal_num_fpw | wal_bytes
--------------------------------------------------+-------+-------------+-------------+-----------
 CREATE TABLE test (id int, data text)            |     1 |         112 |          23 |     94742
 CREATE UNLOGGED TABLE test_u (id int, data text) |     1 |         111 |           2 |     11796
(2 rows)

CREATE TABLEの背景でそれなりのWALが生成されていることがわかる。CREATE TABLEのの背景で、多くのシステムカタログの更新が行われるからなんだろうなあ。
また、通常のテーブルとUNLOGGED TABLEで、WALに関する情報の生成量が結構違うことがわかる。

DMLの実行

上記の2種のテーブルに対して、INSERT/UPDATE/DELETE/UPDATE（厳密にはDMLではないが）を実行した結果を順々に示していく。

通常のテーブル

INSERT/UPDATE/DELETEを実行すると、それぞれのSQL文についてのWAL情報が加算されているのがわかる。TRUNCATEでも増加する。

testdb=# INSERT INTO test VALUES (generate_series(1, 3), md5(clock_timestamp()::text));
INSERT 0 3
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test';
                                      query                                      | calls | wal_records | wal_num_fpw | wal_bytes
---------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 CREATE TABLE test (id int, data text)                                           |     1 |         112 |          23 |     94742
 CREATE UNLOGGED TABLE test_u (id int, data text)                                |     1 |         111 |           2 |     11796
 INSERT INTO test VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           3 |           0 |       276
(3 rows)

testdb=# UPDATE test SET data = md5(clock_timestamp()::text) WHERE id = 3;
UPDATE 1
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test';
                                      query                                      | calls | wal_records | wal_num_fpw | wal_bytes
---------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 UPDATE test SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           1 |           0 |        99
 CREATE TABLE test (id int, data text)                                           |     1 |         112 |          23 |     94742
 CREATE UNLOGGED TABLE test_u (id int, data text)                                |     1 |         111 |           2 |     11796
 INSERT INTO test VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           3 |           0 |       276
(4 rows)

testdb=# DELETE FROM test WHERE id = 3;
DELETE 1
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test';
                                      query                                      | calls | wal_records | wal_num_fpw | wal_bytes
---------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 UPDATE test SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           1 |           0 |        99
 DELETE FROM test WHERE id = $1                                                  |     1 |           1 |           0 |        54
 CREATE TABLE test (id int, data text)                                           |     1 |         112 |          23 |     94742
 CREATE UNLOGGED TABLE test_u (id int, data text)                                |     1 |         111 |           2 |     11796
 INSERT INTO test VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           3 |           0 |       276
(5 rows)

testdb=# TRUNCATE test;
TRUNCATE TABLE
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test';
                                      query                                      | calls | wal_records | wal_num_fpw | wal_bytes
---------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 UPDATE test SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           1 |           0 |        99
 DELETE FROM test WHERE id = $1                                                  |     1 |           1 |           0 |        54
 CREATE TABLE test (id int, data text)                                           |     1 |         112 |          23 |     94742
 TRUNCATE test                                                                   |     1 |          20 |           6 |     19872
 CREATE UNLOGGED TABLE test_u (id int, data text)                                |     1 |         111 |           2 |     11796
 INSERT INTO test VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           3 |           0 |       276
(6 rows)

UNLOGGED TABLE

UNLOGGED TABLEの場合、INSERT/UPDATE/DELETEの背景では、callsの値は増加するが、wal_records, wal_num_fpw, wal_bytes は増加しない。
TRUNCATEに関しては、UNLOGGED TABLEであっても、WALが生成されるようだ（たぶん、relfilenodeが変わる→pg_classの変更があるんだろう）。

testdb=# INSERT INTO test_u VALUES (generate_series(1, 3), md5(clock_timestamp()::text));
INSERT 0 3
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test_u';
                                       query                                       | calls | wal_records | wal_num_fpw | wal_bytes
-----------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 CREATE UNLOGGED TABLE test_u (id int, data text)                                  |     1 |         111 |           2 |     11796
 INSERT INTO test_u VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           0 |           0 |         0
(2 rows)

testdb=# UPDATE test_u SET data = md5(clock_timestamp()::text) WHERE id = 3;
UPDATE 1
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test_u';
                                       query                                       | calls | wal_records | wal_num_fpw | wal_bytes
-----------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 UPDATE test_u SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           0 |           0 |         0
 CREATE UNLOGGED TABLE test_u (id int, data text)                                  |     1 |         111 |           2 |     11796
 INSERT INTO test_u VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           0 |           0 |         0
(3 rows)

testdb=# DELETE FROM test_u WHERE id = 3;
DELETE 1
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test_u';
                                       query                                       | calls | wal_records | wal_num_fpw | wal_bytes
-----------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 DELETE FROM test_u WHERE id = $1                                                  |     1 |           0 |           0 |         0
 UPDATE test_u SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           0 |           0 |         0
 CREATE UNLOGGED TABLE test_u (id int, data text)                                  |     1 |         111 |           2 |     11796
 INSERT INTO test_u VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           0 |           0 |         0
(4 rows)

testdb=# TRUNCATE test_u;
TRUNCATE TABLE
testdb=# SELECT query, calls, wal_records, wal_num_fpw, wal_bytes FROM pg_stat_statements WHERE query ~ 'test_u';
                                       query                                       | calls | wal_records | wal_num_fpw | wal_bytes
-----------------------------------------------------------------------------------+-------+-------------+-------------+-----------
 DELETE FROM test_u WHERE id = $1                                                  |     1 |           0 |           0 |         0
 TRUNCATE test_u                                                                   |     1 |          20 |           6 |     20652
 UPDATE test_u SET data = md5(clock_timestamp()::text) WHERE id = $1               |     1 |           0 |           0 |         0
 CREATE UNLOGGED TABLE test_u (id int, data text)                                  |     1 |         111 |           2 |     11796
 INSERT INTO test_u VALUES (generate_series($1, $2), md5(clock_timestamp()::text)) |     1 |           0 |           0 |         0
(5 rows)

testdb=#

おわりに

実行計画の生成に時間がかかるケースというのは、主に子テーブル数の多いパーティーションテーブルで発生すると思うが、そういうときに、実行時処理時間が原因なのか、実行計画の生成に時間がかかるのかを切り分けるときに、この機能が威力を発揮しそうではある。

WALに関しては、どのSQL文でどの程度のWALが生成されるのかという情報が簡単に確認できるようになったのは非常に嬉しいかも。

なお、pg_stat_statementsを利用している、pg_statsinfoでこの追加された列を使うのようになるのかは、現時点ではわからない。pg_statsinfoの開発者には別途確認してみる予定。