1. はじめに
EXPLAIN ANALYZE の出力を「なんとなく読める」状態から、「見るポイントを特定できる」状態にまで理解する手助けにするのが本記事の目的です。
具体的には以下の4点を実測で確認します。
- work_mem の変化がソート・ハッシュ結合の実行計画にどう現れるか
- 結合手法（Hash Join / Nested Loop）の使い分けと読み方
- スキャン方式（Seq Scan / Index Scan）の選択基準
- 一時ファイルの発生を運用で検知する方法
pgbenchを使って、実際に手を動かしながら確認可能なので、是非皆さんもお試しください。
1.1 環境の情報
今回も引き続き下記の環境です。メモリーが1GiBだったので、一部処理でサーバーが固まるといった事があったので、実行する際には注意をお願いします。
| 項目 | 内容 |
|---|---|
| OS | AmazonLinux2023 |
| PostgreSQL | 16 |
| インスタンスタイプ | t3.micro (2 vCPU、 1GiB) |
警告
postgresql.confのshared_buffers、work_memのサイズは注意して設定してください。
EC2のメモリーを超えるような設定を実施した場合に、ハングアップする可能性があります。
PostgreSQLの利用メモリー合計は、shared_buffers + (work_mem ✖️ クライアント数)です。
1.2 事前準備
# pgbenchデータ作成（スケールは10、pgbench_accountsのサイズが約130MB）
$ pgbench -i -s 10 -U postgres pgbench_test
# pg_stat_statementsを有効化
$ sudo vi /var/lib/pgsql/data/postgresql.conf
# vi で下記を設定
# shared_preload_libraries = 'pg_stat_statements'
# PostgreSQLを再起動
$ sudo systemctl restart postgresql
# 拡張機能の登録
$ psql -U postgres -d pgbench_test -c "CREATE EXTENSION IF NOT EXISTS pg_stat_statements;"
# 結果確認
$ psql -U postgres -d pgbench_test -c "SELECT * FROM pg_extension WHERE extname = 'pg_stat_statements';"
oid | extname | extowner | extnamespace | extrelocatable | extversion | extconfig | extcondition
--------------------------------------------------------------------------------------------------------
41339 | pg_stat_statements | 10 | 2200 | t | 1.10 | |
(1 row)
# データを事前にメモリ展開するための拡張を有効化
$psql -U postgres -d pgbench_test -c "CREATE EXTENSION pg_prewarm;"
1.3 EXPLAINの結果を読んでみる
単純なソートで結果を取得するSQLを作成します。
$ mkdir pgsql
$ vi ./pgsql/sort_test.sql
下記がSQLの中身です。
-- ./pgsql/sort_test.sql
-- セッション中にパラレルクエリを無効化（実行計画を読みやすくするため）
SET max_parallel_workers_per_gather = 0;
-- 単純なソートのSELECT句を実行して、実行計画を出力
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)
SELECT aid, abalance FROM pgbench_accounts ORDER BY abalance DESC LIMIT 100;
上記のSQLを実行します。
# pgbench_accountsの全体を shared_buffers に強制ロード
$ psql -U postgres -d pgbench_test -c "SELECT pg_prewarm('pgbench_accounts', 'buffer');"
# 単純なsortで結果取得するSQLを実行
$ psql -U postgres -d pgbench_test -f ./pgsql/sort_test.sql
実行計画全体はこちらです。
------------------------------------------------------------------------------------------------------------------
Limit (cost=64613.28..64613.53 rows=100 width=8) (actual time=208.715..208.727 rows=100 loops=1)
Output: aid, abalance
Buffers: shared hit=16397
-> Sort (cost=64613.28..67113.28 rows=1000000 width=8) (actual time=208.714..208.719 rows=100 loops=1)
Output: aid, abalance
Sort Key: pgbench_accounts.abalance DESC
Sort Method: top-N heapsort Memory: 28kB
Buffers: shared hit=16397
-> Seq Scan on public.pgbench_accounts (cost=0.00..26394.00 rows=1000000 width=8) (actual time=0.021..108.627
rows=1000000 loops=1)
Output: aid, abalance
Buffers: shared hit=16394
Query Identifier: -4202989189067182007
Planning:
Buffers: shared hit=64
Planning Time: 0.272 ms
Execution Time: 208.750 ms
(16 rows)
| フィールド | 意味 | 注目ポイント |
|---|---|---|
| cost=xx..yy | プランナの推定コスト | 実測と大きく乖離していたら統計情報が古い |
| actual time=xx..yy | 実際の実行時間（ms） | ここが大きいノードがボトルネック |
| Buffers: shared hit=16397 | メモリもしくは一時ファイルの読み書きブロック数 | shared hitならメモリ上 |
| Sort Method: top-N heapsort Memory: 28kB | 並べ替え方式 | 「Memory」 or 「Disk」によって性能面で差異大 |
| Seq Scan on public.pgbench_accounts | テーブルへのアクセス方式が「Seq Scan」 | テーブルへのアクセス方式によって処理時間の差異あり |
今回の実行計画では、pgbenchのスケールを10、shared_bufferのサイズをpgbench_accountsが収まるサイズ（256MB）、データの読み込みは全てメモリー上にのった状態（pg_prewarm）で実行することで、「全てメモリ上から取得」なりました（shared_hit=XXXXXX）。
例えば、下記の条件に変えた場合の結果は以下のように変わります。
| 項目 | 値 |
|---|---|
| shared_buffers | 128MB |
| work_mem | 4MB |
実行計画を再取得します。
# 統計情報やキャッシュをクリア
$ psql -U postgres -d pgbench_test -c "SELECT pg_stat_reset();"
$ sudo systemctl stop postgresql
$ sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
$ sudo systemctl start postgresql
$ psql -U postgres -d pgbench_test -c "SELECT pg_prewarm('pgbench_accounts', 'buffer');"
# 再取得
$ psql -U postgres -d pgbench_test -f /tmp/sort_test.sql
一部のみの抜粋になりますが、「Buffers: shared hit=16153 read=244」で一部がディスクからの読み込みに変わってしまっています。
(色々省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: top-N heapsort Memory: 28kB
Buffers: shared hit=16153 read=244 #【注目】**若干物理アクセス発生**
(色々省略)
Planning Time: 9.525 ms
Execution Time: 218.338 ms
pg_prewarmなしで、work_memは4MBで再度実行計画を取得します。
# 統計情報やキャッシュをクリア
$ psql -U postgres -d pgbench_test -c "SELECT pg_stat_reset();"
$ sudo systemctl stop postgresql
$ sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
$ sudo systemctl start postgresql
# 再取得
$ psql -U postgres -d pgbench_test -f /tmp/sort_test.sql
こちらも一部のみの抜粋になりますが、「Buffers: shared hit=16153 read=244」で一部がディスクからの読み込みに変わってしまっています。
(色々省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: top-N heapsort Memory: 28kB
Buffers: shared hit=3 read=16394 #【注目】**物理アクセス発生**
(色々省略)
Planning Time: 13.648 ms
Execution Time: 656.647 ms
メモリー上にあるデータだけで処理できた場合との処理時間は大きく変わってきます。
| shared_buffers | prewarm実施有無 | Buffers | Execution Time |
|---|---|---|---|
| 256MB | あり | Buffers: shared hit=16397 | 208 ms |
| 128MB | あり | Buffers: shared hit=16153 read=244 | 218 ms |
| 128MB | なし | Buffers: shared hit=3 read=16394 | 656 ms |
「shared_buffersのサイズ」と「実際にデータがメモリーに載っているか」の両方が実行時間に大きく影響していることがわかります。
2. ソート
2.1 ソート：external merge Disk
「ソート」の確認では、下記SQLを利用します。単純に件数（100万件）を絞って、並べ替えて、結果を取得するSQLです。
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)
SELECT aid, abalance
FROM pgbench_accounts
ORDER BY abalance DESC
LIMIT 1000000; -- 【注目】データを100万件取得して、「ソート」するためwork_memを使う
2.2 「ソート」SQLの複数の実行計画（抜粋）
work_memを4MBに変更して、pg_prewarmを未実行で、上記の単純なソートのSQLの実行計画の結果です。
(省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: external merge Disk: 17672kB ←【注目】ディスクを使ったソート
Buffers: shared hit=3 read=16394, temp read=4411 written=4426
(省略)
Planning Time: 13.058 ms
Execution Time: 946.623 ms
次に、work_memは同じく4MBで、pg_prewarmを実行した上での結果です。
shared_buffers（共有メモリ）が利用できているので、実行時間はかなり早くなってます。
(省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: external merge Disk: 17672kB ←【注目】ディスクを使ったソート
Buffers: shared hit=16157 read=240, temp read=4411 written=4426
(省略)
Planning Time: 0.347 ms
Execution Time: 486.986 ms
次にwork_memを128MBに変更して、pg_prewarmを実行していない結果です。shared_buffersにデータが存在しないため、実行時間は遅くなってます。
(省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: quicksort Memory: 63639kB
Buffers: shared hit=3 read=16394
(省略)
Planning Time: 13.055 ms
Execution Time: 817.984 ms
work_memを128MBに変更して、pg_prewarmを実行した結果です。work_memも使えており、実行時間の結果も早くなってます。
(省略)
Sort Key: pgbench_accounts.abalance DESC
Sort Method: quicksort Memory: 63639kB
Buffers: shared hit=16163 read=234
(省略)
Planning Time: 0.346 ms
Execution Time: 382.424 ms
| work_mem | prewarm実施有無 | Sort Method | Execution Time |
|---|---|---|---|
| 4MB | なし | external merge Disk: 17672kB | 946.623 ms |
| 4MB | あり | external merge Disk: 17672kB | 486.986 ms |
| 128MB | なし | quicksort Memory: 63639kB | 817.984 ms |
| 128MB | あり | quicksort Memory: 63639kB | 382.424 ms |
単純なソートでは、work_memの差異に関しては、そこまで差異が発生していないように見えますが、486ms → 382msと100msの差なので、20%は差が発生している事が確認できます。
2.3 おまけ
おまけとして、LIMITを小さくした場合の結果ものせておきます。（sortがtop-N heapsortに変わります）
Sort Key: pgbench_accounts.abalance DESC
Sort Method: top-N heapsort Memory: 1159kB
Buffers: shared hit=16164 read=233
3. ハッシュ結合
テーブル間の結合に関して、実行計画を確認してみます。
3.1 初期化 & 使用SQL
$ pgbench -i -s 50 -U postgres pgbench_test
-- セッション中にパラレルクエリを無効化
SET max_parallel_workers_per_gather = 0;
-- マージ結合を無効化
SET enable_mergejoin = off;
-- ハッシュ結合
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)
SELECT a1.aid, a1.abalance,a1.filler , a2.abalance, a2.filler
FROM pgbench_accounts a1
JOIN pgbench_accounts a2 ON a1.aid = a2.aid;
3.2 「ハッシュ結合」SQLの複数の実行計画（抜粋）
work_memが4MBの状態で、pg_prewarmを実行せずに取得した実行計画です。
Hash Join (cost=267711.00..632533.01 rows=5000000 width=182) (actual time=7996.438..23676.574 rows=5000000 loops=1)
Output: a1.aid, a1.abalance, a1.filler, a2.abalance, a2.filler
Inner Unique: true
Hash Cond: (a1.aid = a2.aid)
Buffers: shared hit=33 read=163903, temp read=138806 written=138806
-> Seq Scan on public.pgbench_accounts a1 (cost=0.00..131968.00 rows=5000000 width=93) (actual time=0.401..8046.933
rows=5000000 loops=1)
Output: a1.aid, a1.abalance, a1.filler
Buffers: shared hit=32 read=81936
-> Hash (cost=131968.00..131968.00 rows=5000000 width=93) (actual time=7993.686..7993.687 rows=5000000 loops=1)
Output: a2.abalance, a2.filler, a2.aid
Buckets: 65536 Batches: 128 Memory Usage: 5393kB
Buffers: shared hit=1 read=81967, temp written=70182
-> Seq Scan on public.pgbench_accounts a2 (cost=0.00..131968.00 rows=5000000 width=93) (actual time=0.004..66
98.446 rows=5000000 loops=1)
Output: a2.abalance, a2.filler, a2.aid
Buffers: shared hit=1 read=81967
Query Identifier: -3849792278988458392
Planning:
Buffers: shared hit=106 read=28
Planning Time: 12.278 ms
Execution Time: 23860.683 ms
(20 rows)
次にwork_memは4MBで、pg_prewarmを実行した結果です。
（省略）
-> Hash (cost=131968.00..131968.00 rows=5000000 width=93) (actual time=6760.152..6760.154 rows=5000000 loops=1)
Output: a2.abalance, a2.filler, a2.aid
Buckets: 65536 Batches: 128 Memory Usage: 5393kB
Buffers: shared hit=16250 read=65718, temp written=70182
（省略）
Planning Time: 14.719 ms
Execution Time: 21817.516 ms
work_memを512MBに変更して実行してみます。
（省略）
-> Hash (cost=131968.00..131968.00 rows=5000000 width=93) (actual time=4140.342..4140.344 rows=5000000 loops=1)
Output: a2.abalance, a2.filler, a2.aid
Buckets: 8388608 Batches: 1 Memory Usage: 690536kB
Buffers: shared hit=1 read=81967
（省略）
Planning Time: 19.634 ms
Execution Time: 9346.566 ms
| work_mem | pg_prewarm有無 | Batches | Execution |
|---|---|---|---|
| 4MB | なし | Batches: 128 | 23,860 ms |
| 4MB | あり | Batches: 128 | 21,817 ms |
| 512MB | なし | Batches: 1 | 9,346 ms |
Batchesの数を見れば、ハッシュ結合の際にデータがメモリに収まっているかどうかが分かります。次の行の「temp written」は一時ファイルの書き出しが行われていることがわかります。
Buffers: shared hit=1 read=81967, temp written=70182
512MBの際には、しっかりMemoryにデータがのっており、実行時間も早いことが確認できます。
なお、ハッシュ結合では、下記のように動作します。
- 小さい方のテーブルをメモリ上にハッシュテーブルとして構築（Build フェーズ）
- 大きい方のテーブルを順に読み、ハッシュテーブルと照合（Probe フェーズ）
work_memに収まらない場合、ハッシュテーブルを複数の「Batche」に分割してディスクに書き出します。これがBatches: N（N>1）として実行計画に出力されます。
| Batches | 状態 | 対処 |
|---|---|---|
| 1 | メモリ完結（理想） | 対処不要 |
| 2以上 | ディスクスピル発生 | work_memの増加を検討 |
ハッシュ結合の場合には、「Batches」を確認して、２以上の場合には、メモリーが足りているかを確認のうえ、work_memの割り当てを増やすか、SQLチューニングが必要になります。
3.3 work_memの割り当て注意
t3.microで試していたのですが、pg_prewarmを実行するとサーバーがハングアップしてしまいました。理由は、下記の通りメモリーが溢れてしまったようです。合計で、930MBで1GBの上限に近づいてしまったようです。
| 項目 | 値 |
|---|---|
| shared_buffers | 128MB |
| work_mem | 512MB |
| OS | 300MB |
実際の運用では、スワップ領域を割り当てて、こう言った自体を回避してください。
# 1.領域の確認（Swap）
$ free -h
total used free shared buff/cache available
Mem: 916Mi 136Mi 575Mi 24Mi 204Mi 619Mi
Swap: 0B 0B 0B
# 2.swapファイル作成（2GB）
$ sudo fallocate -l 2G /swapfile
# 3.パーミッション設定
$ sudo chmod 600 /swapfile
# 4.swap初期化
$ sudo mkswap /swapfile
# 5.swap有効化
$ sudo swapon /swapfile
# 6.永続化（再起動後も有効）
$ echo '/swapfile swap swap defaults 0 0' | sudo tee -a /etc/fstab
# 7.swappiness を低めに設定（PostgreSQL推奨）
$ sudo sysctl vm.swappiness=10
$ echo 'vm.swappiness=10' | sudo tee -a /etc/sysctl.conf
# 8.確認
$ free -h
total used free shared buff/cache available
Mem: 916Mi 138Mi 572Mi 24Mi 206Mi 617Mi
Swap: 2.0Gi 0B 2.0Gi
4. ネステッドループ
4.1 利用したSQL
-- セッション中にパラレルクエリを無効化
SET max_parallel_workers_per_gather = 0;
-- 強制的にNested Loopにする
SET enable_hashjoin = off;
SET enable_mergejoin = off;
EXPLAIN (ANALYZE, BUFFERS)
SELECT a.abalance, t.tbalance
FROM pgbench_accounts a
JOIN pgbench_tellers t ON a.bid = t.bid
WHERE a.aid = 12345;
4.2 「ネステットループ」SQLの複数の実行計画（抜粋）
work_memは128MBで実行しています。
Nested Loop (cost=0.43..22.70 rows=10 width=8) (actual time=0.023..0.095 rows=10 loops=1)
Join Filter: (a.bid = t.bid)
Rows Removed by Join Filter: 490
Buffers: shared hit=7
-> Index Scan using pgbench_accounts_pkey on pgbench_accounts a (cost=0.43..8.45 rows=1 width=8) (actual time=0.016
..0.017 rows=1 loops=1)
Index Cond: (aid = 12345)
Buffers: shared hit=4
-> Seq Scan on pgbench_tellers t (cost=0.00..8.00 rows=500 width=8) (actual time=0.003..0.033 rows=500 loops=1)
Buffers: shared hit=3
Planning:
Buffers: shared hit=161
Planning Time: 0.571 ms
Execution Time: 0.152 ms
(13 rows)
外側（pgbench_accounts）で1行取り出し、それをキーに内側（pgbench_tellers）をIndex Scanで検索しています。Buffers: shared hit=X はすべて共有バッファから取得でき、ディスクI/Oがゼロであることを示します。
ネステッドループ（Nested Loop）は、ハッシュ結合（Hash Join）と異なりwork_memをほぼ消費しません。性能を左右するのはインデックスの有無です。
-- 主キー制約ごと削除
ALTER TABLE pgbench_accounts DROP CONSTRAINT pgbench_accounts_pkey;
-- セッション中にパラレルクエリを無効化
SET max_parallel_workers_per_gather = 0;
-- 強制的にNested Loopにする
SET enable_hashjoin = off;
SET enable_mergejoin = off;
-- 実行計画を取得
EXPLAIN (ANALYZE, BUFFERS)
SELECT a.abalance, t.tbalance
FROM pgbench_accounts a
JOIN pgbench_tellers t ON a.bid = t.bid
WHERE a.aid = 12345;
インデックススキャンではなく、シーケンシャルスキャン（SeqScan）になっている事が確認できます。
Nested Loop (cost=0.00..28897.25 rows=10 width=8) (actual time=9.956..593.685 rows=10 loops=1)
Join Filter: (a.bid = t.bid)
Rows Removed by Join Filter: 90
Buffers: shared read=16395
-> Seq Scan on pgbench_accounts a (cost=0.00..28894.00 rows=1 width=8) (actual time=9.234..592.947 rows=1 loops=1)
Filter: (aid = 12345)
Rows Removed by Filter: 999999
Buffers: shared read=16394
-> Seq Scan on pgbench_tellers t (cost=0.00..2.00 rows=100 width=8) (actual time=0.716..0.723 rows=100 loops=1)
Buffers: shared read=1
Planning:
Buffers: shared hit=118 read=27
Planning Time: 16.403 ms
Execution Time: 595.278 ms
(14 rows)
同じSQLですが、驚くほど結果が変わってきています。これが実行計画の違いです。
| スキャン方式 | Execution Time |
|---|---|
| Index Scan | 0.152 ms |
| Seq Scan | 595.278 ms |
念の為、主キー制約を戻しておきます。
-- 主キー制約を再作成（インデックスも同時に再作成される）
ALTER TABLE pgbench_accounts ADD PRIMARY KEY (aid);
4.3 スキャン方式の矯正切り替え
なお、enable_* パラメータでスキャン方式を強制切り替えすると、差を直接確認できます。
-- インデックススキャン（Index Scan）を無効にして、シーケンシャルスキャン（Seq Scan）を強制
SET enable_indexscan = off;
SET enable_bitmapscan = off;
EXPLAIN (ANALYZE, BUFFERS)
SELECT abalance FROM pgbench_accounts WHERE aid = 12345;
上記SQLを実行した結果です。
Seq Scan on pgbench_accounts (cost=0.00..144468.00 rows=1 width=4) (actual time=1.871..448.246 rows=1 loops=1)
Filter: (aid = 12345)
Rows Removed by Filter: 4999999
Buffers: shared hit=16198 read=65770
Planning:
Buffers: shared hit=64
Planning Time: 1.124 ms
Execution Time: 448.295 ms
(8 rows)
全5,000,000行を順番（シーケンシャル）に参照しており、Rows Removed by Filter: 4999999 がその証拠です。インデックススキャン（Index Scan）と比べると実行時間の差は歴然で、インデックスの効果がそのまま現れます。
4.4 ANALYZEによりスキャン方式が切り替わることを確認する
「統計情報」が古い場合、PostgreSQLが誤ったスキャン方式を選択することがあります。「統計情報」とは、行数・値の分布をPostgreSQLが内部で保持している情報です。
以下の手順で再現します。
まずは以下のSQLを順番に実行します。
-- pgbench_accountsから100行だけ抜き出して検証用テーブルを作成
CREATE TABLE test_accounts AS
SELECT * FROM pgbench_accounts LIMIT 100;
-- インデックスを作成
CREATE INDEX ON test_accounts(aid);
-- 統計情報を取得
ANALYZE test_accounts;
-- autovacuumを無効化（実験中に統計が自動更新されないようにする）
ALTER TABLE test_accounts SET (autovacuum_enabled = false);
-- 大量INSERT（統計情報を古くする）
INSERT INTO test_accounts(aid, bid, abalance, filler)
SELECT g + 100, (g % 50) + 1, 0, 'x'
FROM generate_series(1, 10000) g;
ANALYZE前の実行計画を取得します。
EXPLAIN (ANALYZE, BUFFERS)
SELECT abalance FROM test_accounts WHERE aid BETWEEN 1 AND 80;
Seq Scan on test_accounts (cost=0.00..290.50 rows=6623 width=4) (actual time=0.008..1.036 rows=80 loops=1)
Filter: ((aid >= 1) AND (aid <= 80))
Rows Removed by Filter: 10020
Buffers: shared hit=166
Planning Time: 0.133 ms
Execution Time: 1.050 ms
rows=6,623（推定）に対してactual rows=80と大幅に過大評価しています。プランナは「大量の行が返る」と誤認してSeq Scanを選択しています。
次に、統計情報を更新します。その後、再度同じSQLで実行計画を取得します。
ANALYZE test_accounts;
EXPLAIN (ANALYZE, BUFFERS)
SELECT abalance FROM test_accounts WHERE aid BETWEEN 1 AND 80;
Index Scan using test_accounts_aid_idx on test_accounts (cost=0.29..10.89 rows=80 width=4) (actual time=0.007..0.024 rows=80 loops=1)
Index Cond: ((aid >= 1) AND (aid <= 80))
Buffers: shared hit=4
Planning Time: 0.256 ms
Execution Time: 0.040 ms
ANALYZEにより統計情報が更新され、rows=80と実態に近い推定値になりました。結果としてIndex Scanに切り替わり、実行時間も約26倍改善しています。
DROP TABLE test_accounts;
4.4 スキャン方式の選択基準
テーブルの統計情報を元に推定して、スキャン方式を選択します。推定行数（rows=）と実測行数（actual rows=）が大きく乖離している場合は ANALYZE で統計情報を更新するとプランが改善することがあります。
| 状況 | 選ばれるスキャン |
|---|---|
| 全件または大部分を取得 | Seq Scan |
| 少数行をキー検索 | Index Scan |
| インデックス列だけを返す | Index Only Scan |
| 中間的な選択度（複数インデックス） | Bitmap Scan |
5. 運用面について
5.1 一時ファイルの発生を運用で検知する
実行計画は問題が起きてから調べることが多いですが、「一時ファイル」の発生をログで継続的に把握する方法もあります。
スケール 10で、pgbenchを初期化します。
pgbench -i -s 10 -U postgres pgbench_test
postgresql.confの設定を変更します。
# postgresql.conf
log_temp_files = 1024 # 1MB以上の一時ファイルをログに記録（単位: kB）
設定後、pgbenchを実行するとログに以下のような出力されます。
# 一時ファイルへの書き出しが発生するSQLを実行
$ psql -U postgres -d pgbench_test -f ./pgsql/hash_join.sql
# PostgreSQLログを確認する
$ sudo cat /var/lib/pgsql/data/log/postgresql-Wed.log
ログに下記の内容が出力されている場合には、ディスクアクセスが発生しており、性能が十分に発揮できていない可能性があります。
2026-04-29 07:55:46.143 UTC [2959] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp2959.42", size 3494977
2026-04-29 07:55:46.143 UTC [2959] STATEMENT: EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)
SELECT a1.aid, a1.abalance,a1.filler , a2.abalance, a2.filler
FROM pgbench_accounts a1
JOIN pgbench_accounts a2 ON a1.aid = a2.aid;
このように、どのSQLで一時ファイルを多用しているかをログから特定できます。
一時ファイルの発生状況確認
pg_stat_statementsと呼ばれるビューで、状況が確認可能です。
SELECT
LEFT(query, 80) AS query,
calls,
ROUND(total_exec_time::numeric, 1) AS total_ms,
temp_blks_written
FROM pg_stat_statements
WHERE temp_blks_written > 0
ORDER BY temp_blks_written DESC
LIMIT 10;
上記SQLを実行します。
$ psql -U postgres -d pgbench_test -f ./pgsql/pgstat.sql
query | calls | total_ms | temp_blks_written
----------------------------------------------------------------------------------------
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS) +| 11 | 177275.1 | 696010
SELECT a1.aid, a1.abalance,a1.filler | | |
alter table pgbench_accounts add primary key (aid) | 13 | 205087.3 | 549904
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS) +| 4 | 42641.3 | 101136
temp_blks_written が多いクエリがwork_mem不足で一時ファイルを多用している候補です。ここで見つけたクエリの実行計画を EXPLAIN (ANALYZE, BUFFERS) で確認する、という流れが実務での典型的な調査手順になります。
まとめ
| 確認したいこと | 見るフィールド | 判断基準 |
|---|---|---|
| ソートのメモリー不足 |
Sort Method / temp written
|
external merge Disk が出たらwork_mem不足 |
| 結合のメモリー不足 | Batches |
1以外ならwork_mem不足 |
| 無駄なスキャン | ノード名（Seq Scan / Index Scan） |
Rows Removed by Filter が多ければインデックスを検討 |
| 一時ファイルの監視 |
log_temp_files / temp_blks_written
|
しきい値を超えたら実行計画を確認 |
次回も引き続き性能面の改善にフォーカスをあてていきたいです。