はじめに
PostgreSQLを使った開発やデバッグ時に、実際に実行されたSQLクエリを確認したい場面がある。
特に、アプリケーションから実行されるクエリの内容や実行時間を把握することで、パフォーマンス問題の特定や最適化等に役立つことがよくある。
PostgreSQLには詳細なログ機能が用意されており、実行されたSQL文、実行時間、エラーなどを出力できる。
今回は、DockerコンテナのPostgreSQLでSQLの実行ログを有効にして確認するということをやってみる。
環境
Windows 11 Pro
WSL2 (Ubuntu 24.04 LTS)
Docker Desktop 4.44.3 (202357)
Docker Compose version v2.39.2
Docker Version 28.3.3-1
PostgreSQL 17リポジトリ
変更内容については、いつものPostgreSQLのリポジトリにコミットした。
- katsuobushiFPGA / postgresql-procedure-dev
https://github.com/katsuobushiFPGA/postgresql-procedure-dev
PostgreSQLのログ設定
PostgreSQLのログ機能は、postgresql.confファイルで設定する。コンテナ環境では、環境変数や設定ファイルのマウントで設定を変更する。
主要なログ設定パラメータ
PostgreSQLのログ関連の主要な設定項目は以下となる。
| パラメータ | 説明 | デフォルト値 | 推奨値 |
|---|---|---|---|
| log_statement | ログ出力するSQL文の種類 | none | all |
| log_min_duration_statement | 指定時間以上のクエリをログ出力(ミリ秒) | -1 | 0 |
| log_line_prefix | ログ行のプレフィックス | %m [%p] | %m [%p] %u@%d |
| logging_collector | ログコレクタの有効化 | off | on |
| log_directory | ログファイルの出力ディレクトリ | log | log |
| log_filename | ログファイル名のパターン | postgresql-%Y-%m-%d_%H%M%S.log | デフォルト |
今回変更したパラメータ一覧
GitHubコミット(e832350)で実際に変更されたパラメータは以下の通り。
| パラメータ | 変更前(コメントアウト状態) | 変更後(有効化) | 説明 |
|---|---|---|---|
| log_destination | #log_destination = ‘stderr’ | log_destination = ‘stderr’ | ログ出力先の指定 |
| logging_collector | #logging_collector = off | logging_collector = on | ログコレクタの有効化 |
| log_directory | #log_directory = ’log' | log_directory = ’log' | ログファイル出力ディレクトリ |
| log_filename | #log_filename = ‘postgresql-…’ | log_filename = ‘postgresql-%Y-%m-%d_%H%M%S.log’ | ログファイル名パターン |
| log_file_mode | #log_file_mode = 0600 | log_file_mode = 0644 | ログファイルの作成モード |
| log_min_messages | #log_min_messages = warning | log_min_messages = info | ログ出力する最小レベル |
| log_min_error_statement | #log_min_error_statement = error | log_min_error_statement = error | エラー文の出力レベル |
| log_min_duration_statement | #log_min_duration_statement = -1 | log_min_duration_statement = 0 | 実行時間ログの閾値(ミリ秒) |
| log_statement_sample_rate | #log_statement_sample_rate = 1.0 | log_statement_sample_rate = 1.0 | ログ文のサンプリング率 |
| log_connections | #log_connections = off | log_connections = on | 接続ログの有効化 |
| log_disconnections | #log_disconnections = off | log_disconnections = on | 切断ログの有効化 |
| log_duration | #log_duration = off | log_duration = on | SQL実行時間ログの有効化 |
| log_line_prefix | #log_line_prefix = ‘%m [%p] ' | log_line_prefix = ‘%m [%p] %u@%d %a ' | ログ行のプレフィックス形式 |
| log_statement | #log_statement = ’none’ | log_statement = ‘all’ | ログ出力するSQL文の種類 |
| track_functions | #track_functions = none | track_functions = pl | PL/pgSQL関数の実行追跡 |
| log_statement_stats | #log_statement_stats = off | log_statement_stats = on | SQL実行統計の有効化 |
| client_min_messages | #client_min_messages = notice | client_min_messages = notice | クライアント向けメッセージの最小レベル |
パラメータの詳しい内容は下記を参照
- 第19章 サーバ設定-19.8. エラー報告とログ出力 | PostgreSQL 17.5文書
https://www.postgresql.jp/document/17/html/runtime-config-logging.html
Docker Composeの変更
コンテナ内で出力したログをホスト側でも確認できるようにボリュームマウントをしておく。
services:
db:
build:
context: ./db
ports:
- "5432:5432"
environment:
- POSTGRES_USER=postgres
- POSTGRES_PASSWORD=postgres
- POSTGRES_DB=postgres
volumes:
- ./initdb:/docker-entrypoint-initdb.d
- db-data:/var/lib/postgresql/data
- ./postgresql.conf:/etc/postgresql/postgresql.conf
- ./tests:/tests
- ./logs:/var/lib/postgresql/data/log
volumes:
db-data:Dockerfileの変更
プロシージャ開発に必要な拡張機能を含むDockerfileを作成する。
※今回は特に修正なし
FROM postgres:17
RUN apt-get update && \
apt-get install -y git make gcc libkrb5-dev postgresql-server-dev-17 curl
WORKDIR /tmp
RUN git clone https://github.com/EnterpriseDB/pldebugger
WORKDIR /tmp/pldebugger
# USE_PGXS=1 をつけること既存のPostgreSQLへの拡張インストールができる
RUN USE_PGXS=1 make
RUN USE_PGXS=1 make install
# pg_proveのインストール
RUN curl -LO http://xrl.us/cpanm \
&& chmod +x cpanm \
&& ./cpanm TAP::Parser::SourceHandler::pgTAP
# pgTAPのインストール
WORKDIR /tmp
RUN git clone https://github.com/theory/pgtap.git
WORKDIR /tmp/pgtap
RUN make
RUN make install
CMD ["postgres", "-c", "config_file=/etc/postgresql/postgresql.conf"]postgresql.confファイルの変更
ログ設定を含むpostgresql.confファイルを作成する。
diff --git a/postgresql.conf b/postgresql.conf
index f50581b..1fe61c5 100644
--- a/postgresql.conf
+++ b/postgresql.conf
@@ -466,24 +466,24 @@ listen_addresses = '*'
# - Where to Log -
-#log_destination = 'stderr' # Valid values are combinations of
+log_destination = 'stderr' # Valid values are combinations of
# stderr, csvlog, jsonlog, syslog, and
# eventlog, depending on platform.
# csvlog and jsonlog require
# logging_collector to be on.
# This is used when logging to stderr:
-#logging_collector = off # Enable capturing of stderr, jsonlog,
+logging_collector = on # Enable capturing of stderr, jsonlog,
# and csvlog into log files. Required
# to be on for csvlogs and jsonlogs.
# (change requires restart)
# These are only used if logging_collector is on:
-#log_directory = 'log' # directory where log files are written,
+log_directory = 'log' # directory where log files are written,
# can be absolute or relative to PGDATA
-#log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern,
+log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern,
# can include strftime() escapes
-#log_file_mode = 0600 # creation mode for log files,
+log_file_mode = 0644 # creation mode for log files,
# begin with 0 to use octal notation
#log_rotation_age = 1d # Automatic rotation of logfiles will
# happen after that time. 0 disables.
@@ -511,7 +511,7 @@ listen_addresses = '*'
# - When to Log -
-#log_min_messages = warning # values in order of decreasing detail:
+log_min_messages = info # values in order of decreasing detail:
# debug5
# debug4
# debug3
@@ -525,7 +525,7 @@ listen_addresses = '*'
# fatal
# panic
-#log_min_error_statement = error # values in order of decreasing detail:
+log_min_error_statement = error # values in order of decreasing detail:
# debug5
# debug4
# debug3
@@ -539,7 +539,7 @@ listen_addresses = '*'
# fatal
# panic (effectively off)
-#log_min_duration_statement = -1 # -1 is disabled, 0 logs all statements
+log_min_duration_statement = 0 # -1 is disabled, 0 logs all statements
# and their durations, > 0 logs only
# statements running at least this number
# of milliseconds
@@ -550,7 +550,7 @@ listen_addresses = '*'
# of milliseconds;
# sample fraction is determined by log_statement_sample_rate
-#log_statement_sample_rate = 1.0 # fraction of logged statements exceeding
+log_statement_sample_rate = 1.0 # fraction of logged statements exceeding
# log_min_duration_sample to be logged;
# 1.0 logs all such statements, 0.0 never logs
@@ -576,12 +576,12 @@ listen_addresses = '*'
# actions running at least this number
# of milliseconds.
#log_checkpoints = on
-#log_connections = off
-#log_disconnections = off
-#log_duration = off
+log_connections = on # log connections
+log_disconnections = on # log disconnections
+log_duration = on # log duration of completed statements
#log_error_verbosity = default # terse, default, or verbose messages
#log_hostname = off
-#log_line_prefix = '%m [%p] ' # special values:
+log_line_prefix = '%m [%p] %u@%d %a ' # special values:
# %a = application name
# %u = user name
# %d = database name
@@ -614,7 +614,7 @@ listen_addresses = '*'
#log_parameter_max_length_on_error = 0 # when logging an error, limit logged
# bind-parameter values to N bytes;
# -1 means print in full, 0 disables
-#log_statement = 'none' # none, ddl, mod, all
+log_statement = 'all' # none, ddl, mod, all
#log_replication_commands = off
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
@@ -640,16 +640,17 @@ listen_addresses = '*'
#track_io_timing = off
#track_wal_io_timing = off
#track_functions = none # none, pl, all
+track_functions = pl # Track PL/pgSQL function execution
#stats_fetch_consistency = cache # cache, none, snapshot
# - Monitoring -
#compute_query_id = auto
-#log_statement_stats = off
+log_statement_stats = on # log statement execution statistics
#log_parser_stats = off
#log_planner_stats = off
-#log_executor_stats = off
+#log_executor_stats = off # Cannot be enabled when log_statement_stats is on
#------------------------------------------------------------------------------
@@ -691,7 +692,7 @@ listen_addresses = '*'
# - Statement Behavior -
-#client_min_messages = notice # values in order of decreasing detail:
+client_min_messages = notice # values in order of decreasing detail:
# debug5
# debug4
# debug3
上記で設定は完了なので、実際にログ出力を確認してみる。
ログ出力を確認してみる
コンテナを起動してログを確認
# コンテナを起動
docker-compose up -d
# ログファイルの確認
ls -la logs/
# リアルタイムでログを監視
tail -f logs/postgresql-$(date +%Y-%m-%d).logSQLを実行してログを確認
別のターミナルでPostgreSQLに接続し、SQLを実行する。
# PostgreSQLに接続
docker compose exec db psql -U postgres -d postgres以下のSQLを実行して確認をしてみる。
# テーブル作成
CREATE TABLE users (
id SERIAL PRIMARY KEY,
name VARCHAR(100),
email VARCHAR(100)
);
# データ挿入
INSERT INTO users (name, email) VALUES
('田中太郎', '[email protected]'),
('佐藤花子', '[email protected]');
# データ検索
SELECT * FROM users WHERE name LIKE '%田中%';実行ログ
postgres=# CREATE TABLE users (
id SERIAL PRIMARY KEY,
name VARCHAR(100),
email VARCHAR(100)
);
CREATE TABLE
postgres=# INSERT INTO users (name, email) VALUES
('田中太郎', '[email protected]'),
('佐藤花子', '[email protected]');
INSERT 0 2
postgres=# SELECT * FROM users WHERE name LIKE '%田中%';
id | name | email
----+----------+--------------------
1 | 田中太郎 | [email protected]
(1 row)ログファイルには以下のような内容が出力される。
ログファイル
2025-08-23 15:24:05.942 GMT [651] [unknown]@[unknown] [unknown] LOG: connection received: host=[local]
2025-08-23 15:24:05.943 GMT [651] postgres@postgres [unknown] LOG: connection authenticated: user="postgres" method=trust (/var/lib/postgresql/data/pg_hba.conf:117)
2025-08-23 15:24:05.943 GMT [651] postgres@postgres [unknown] LOG: connection authorized: user=postgres database=postgres application_name=psql
2025-08-23 15:24:12.824 GMT [651] postgres@postgres psql LOG: statement: CREATE TABLE users (
id SERIAL PRIMARY KEY,
name VARCHAR(100),
email VARCHAR(100)
);
2025-08-23 15:24:12.847 GMT [651] postgres@postgres psql LOG: duration: 24.575 ms
2025-08-23 15:24:12.847 GMT [651] postgres@postgres psql LOG: QUERY STATISTICS
2025-08-23 15:24:12.847 GMT [651] postgres@postgres psql DETAIL: ! system usage stats:
! 0.006773 s user, 0.010429 s system, 0.024606 s elapsed
! [0.010429 s user, 0.010429 s system total]
! 16784 kB max resident size
! 1712/400 [1712/400] filesystem blocks in/out
! 75/259 [75/686] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 43/0 [44/0] voluntary/involuntary context switches
2025-08-23 15:24:12.847 GMT [651] postgres@postgres psql STATEMENT: CREATE TABLE users (
id SERIAL PRIMARY KEY,
name VARCHAR(100),
email VARCHAR(100)
);
2025-08-23 15:24:17.255 GMT [651] postgres@postgres psql LOG: statement: INSERT INTO users (name, email) VALUES
('田中太郎', '[email protected]'),
('佐藤花子', '[email protected]');
2025-08-23 15:24:17.258 GMT [651] postgres@postgres psql LOG: duration: 3.644 ms
2025-08-23 15:24:17.258 GMT [651] postgres@postgres psql LOG: QUERY STATISTICS
2025-08-23 15:24:17.258 GMT [651] postgres@postgres psql DETAIL: ! system usage stats:
! 0.001548 s user, 0.001548 s system, 0.003664 s elapsed
! [0.012016 s user, 0.012016 s system total]
! 16784 kB max resident size
! 0/48 [1712/448] filesystem blocks in/out
! 6/8 [81/694] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 2/0 [47/0] voluntary/involuntary context switches
2025-08-23 15:24:17.258 GMT [651] postgres@postgres psql STATEMENT: INSERT INTO users (name, email) VALUES
('田中太郎', '[email protected]'),
('佐藤花子', '[email protected]');
2025-08-23 15:24:20.893 GMT [651] postgres@postgres psql LOG: statement: SELECT * FROM users WHERE name LIKE '%田中%';
2025-08-23 15:24:20.895 GMT [651] postgres@postgres psql LOG: duration: 1.746 ms
2025-08-23 15:24:20.895 GMT [651] postgres@postgres psql LOG: QUERY STATISTICS
2025-08-23 15:24:20.895 GMT [651] postgres@postgres psql DETAIL: ! system usage stats:
! 0.001479 s user, 0.000000 s system, 0.001708 s elapsed
! [0.013617 s user, 0.012016 s system total]
! 16784 kB max resident size
! 16/0 [1728/448] filesystem blocks in/out
! 2/6 [83/700] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 1/0 [49/0] voluntary/involuntary context switches
2025-08-23 15:24:20.895 GMT [651] postgres@postgres psql STATEMENT: SELECT * FROM users WHERE name LIKE '%田中%';プロシージャもログ出力をされるかをやってみる
-- プロシージャの作成例
CREATE OR REPLACE PROCEDURE hello_world()
LANGUAGE plpgsql
AS $$
BEGIN
RAISE INFO 'Hello, World!';
END;
$$;-- プロシージャ実行
CALL hello_world();ログでは以下のように出力された。
ログファイル
2025-08-23 15:28:29.042 GMT [29] @ LOG: checkpoint starting: time
2025-08-23 15:28:33.178 GMT [29] @ LOG: checkpoint complete: wrote 42 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=4.121 s, sync=0.008 s, total=4.138 s; sync files=33, longest=0.002 s, average=0.001 s; distance=171 kB, estimate=171 kB; lsn=0/1CB8910, redo lsn=0/1CB88B8
2025-08-23 15:28:34.602 GMT [651] postgres@postgres psql LOG: statement: CALL hello_world();
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql INFO: Hello, World
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function hello_world() line 3 at RAISE
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql LOG: duration: 6.051 ms
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql LOG: QUERY STATISTICS
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql DETAIL: ! system usage stats:
! 0.005793 s user, 0.000000 s system, 0.006065 s elapsed
! [0.019511 s user, 0.012016 s system total]
! 19332 kB max resident size
! 24/0 [1752/448] filesystem blocks in/out
! 1/97 [84/797] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 1/0 [52/0] voluntary/involuntary context switches
2025-08-23 15:28:34.608 GMT [651] postgres@postgres psql STATEMENT: CALL hello_world();プロシージャ内でエラーになった場合の確認
エラーテスト用プロシージャを作成する
-- エラーハンドリングテスト用プロシージャ
CREATE OR REPLACE PROCEDURE test_error_handling(
IN p_test_type INTEGER,
OUT p_result TEXT
)
LANGUAGE plpgsql
AS $$
BEGIN
RAISE NOTICE 'Starting error handling test with type: %', p_test_type;
CASE p_test_type
WHEN 1 THEN
-- テーブル不存在エラー
SELECT COUNT(*) FROM non_existent_table INTO p_result;
WHEN 2 THEN
-- 型変換エラー
SELECT 'invalid_number'::INTEGER INTO p_result;
WHEN 3 THEN
-- カスタム例外
RAISE EXCEPTION 'Custom error: Invalid input value %', p_test_type;
WHEN 4 THEN
-- ゼロ除算エラー
SELECT (10 / 0)::TEXT INTO p_result;
ELSE
p_result := 'Success: No error occurred';
RAISE NOTICE 'Test completed successfully';
END CASE;
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Error caught in procedure: % %', SQLSTATE, SQLERRM;
p_result := 'Error: ' || SQLERRM;
-- エラーを再発生させる(ログに記録するため)
RAISE;
END;
$$;下記の実行文でテストしてみる。
個別にCALLしてみてもよい。
-- エラーハンドリングの動作確認
DO $$
DECLARE
result_val TEXT;
BEGIN
-- 正常ケース
CALL test_error_handling(0, result_val);
RAISE NOTICE 'Normal case result: %', result_val;
-- エラーケース(テーブル不存在)
BEGIN
CALL test_error_handling(1, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught error: %', SQLERRM;
END;
-- エラーケース(カスタム例外)
BEGIN
CALL test_error_handling(3, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught custom error: %', SQLERRM;
END;
END;
$$;実行ログ
postgres=# -- エラーハンドリングの動作確認
DO $$
DECLARE
result_val TEXT;
BEGIN
-- 正常ケース
CALL test_error_handling(0, result_val);
RAISE NOTICE 'Normal case result: %', result_val;
$$;;END; RAISE NOTICE 'Caught custom error: %', SQLERRM;
NOTICE: Starting error handling test with type: 0
NOTICE: Test completed successfully
NOTICE: Normal case result: Success: No error occurred
NOTICE: Starting error handling test with type: 1
NOTICE: Error caught in procedure: 42P01 relation "non_existent_table" does not exist
NOTICE: Caught error: relation "non_existent_table" does not exist
NOTICE: Starting error handling test with type: 3
NOTICE: Error caught in procedure: P0001 Custom error: Invalid input value 3
NOTICE: Caught custom error: Custom error: Invalid input value 3
DOログファイルも確認してみる。
ログファイル
2025-08-23 15:31:30.814 GMT [651] postgres@postgres psql LOG: statement: DO $$
DECLARE
result_val TEXT;
BEGIN
-- 正常ケース
CALL test_error_handling(0, result_val);
RAISE NOTICE 'Normal case result: %', result_val;
-- エラーケース(テーブル不存在)
BEGIN
CALL test_error_handling(1, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught error: %', SQLERRM;
END;
-- エラーケース(カスタム例外)
BEGIN
CALL test_error_handling(3, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught custom error: %', SQLERRM;
END;
END;
$$;
2025-08-23 15:31:30.818 GMT [651] postgres@postgres psql NOTICE: Starting error handling test with type: 0
2025-08-23 15:31:30.818 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 3 at RAISE
SQL statement "CALL test_error_handling(0, result_val)"
PL/pgSQL function inline_code_block line 6 at CALL
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql NOTICE: Test completed successfully
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 24 at RAISE
SQL statement "CALL test_error_handling(0, result_val)"
PL/pgSQL function inline_code_block line 6 at CALL
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql NOTICE: Normal case result: Success: No error occurred
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function inline_code_block line 7 at RAISE
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql NOTICE: Starting error handling test with type: 1
2025-08-23 15:31:30.819 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 3 at RAISE
SQL statement "CALL test_error_handling(1, result_val)"
PL/pgSQL function inline_code_block line 11 at CALL
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql NOTICE: Error caught in procedure: 42P01 relation "non_existent_table" does not exist
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 29 at RAISE
SQL statement "CALL test_error_handling(1, result_val)"
PL/pgSQL function inline_code_block line 11 at CALL
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql NOTICE: Caught error: relation "non_existent_table" does not exist
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function inline_code_block line 14 at RAISE
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql NOTICE: Starting error handling test with type: 3
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 3 at RAISE
SQL statement "CALL test_error_handling(3, result_val)"
PL/pgSQL function inline_code_block line 19 at CALL
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql NOTICE: Error caught in procedure: P0001 Custom error: Invalid input value 3
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function test_error_handling(integer) line 29 at RAISE
SQL statement "CALL test_error_handling(3, result_val)"
PL/pgSQL function inline_code_block line 19 at CALL
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql NOTICE: Caught custom error: Custom error: Invalid input value 3
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql CONTEXT: PL/pgSQL function inline_code_block line 22 at RAISE
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql LOG: duration: 6.607 ms
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql LOG: QUERY STATISTICS
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql DETAIL: ! system usage stats:
! 0.006338 s user, 0.000000 s system, 0.006585 s elapsed
! [0.026069 s user, 0.012016 s system total]
! 20868 kB max resident size
! 8/0 [1760/448] filesystem blocks in/out
! 1/68 [85/865] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 1/0 [54/0] voluntary/involuntary context switches
2025-08-23 15:31:30.820 GMT [651] postgres@postgres psql STATEMENT: DO $$
DECLARE
result_val TEXT;
BEGIN
-- 正常ケース
CALL test_error_handling(0, result_val);
RAISE NOTICE 'Normal case result: %', result_val;
-- エラーケース(テーブル不存在)
BEGIN
CALL test_error_handling(1, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught error: %', SQLERRM;
END;
-- エラーケース(カスタム例外)
BEGIN
CALL test_error_handling(3, result_val);
EXCEPTION
WHEN OTHERS THEN
RAISE NOTICE 'Caught custom error: %', SQLERRM;
END;
END;
$$;ちなみに直接呼んで、エラーハンドリングもしないと下記のようになる。
CALL test_error_handling(3, result_val);実行ログ
postgres=# CALL test_error_handling(3, result_val);
ERROR: column "result_val" does not exist
LINE 1: CALL test_error_handling(3, result_val);ログファイル
2025-08-23 15:35:08.936 GMT [651] postgres@postgres psql LOG: statement: CALL test_error_handling(3, result_val);
2025-08-23 15:35:08.936 GMT [651] postgres@postgres psql ERROR: column "result_val" does not exist at character 29
2025-08-23 15:35:08.936 GMT [651] postgres@postgres psql STATEMENT: CALL test_error_handling(3, result_val);設定例
開発環境用設定
開発時はすべてのSQLを記録し、詳細な情報を出力する。
# 開発用設定(postgresql.conf内)
log_statement = all
log_min_duration_statement = 0
log_line_prefix = '%m [%p] %u@%d %h '
log_connections = on
log_disconnections = on
log_duration = on
log_hostname = on
log_min_messages = info本番環境用設定
本番環境では、パフォーマンスに影響する長時間実行クエリのみを記録する。
# 本番用設定(100ms以上のクエリのみ)
log_statement = ddl
log_min_duration_statement = 100
log_line_prefix = '%m [%p] %u@%d '
log_connections = on
log_disconnections = on
log_checkpoints = on
log_lock_waits = on
log_min_messages = warningエラー調査用設定
エラーやデバッグ時に使用する詳細設定。
# エラー調査用設定
log_statement = all
log_min_duration_statement = 0
log_min_error_statement = error
log_min_messages = info
log_error_verbosity = verbose
log_line_prefix = '%m [%p] %u@%d %h %e '
log_connections = on
log_disconnections = onログローテーションの設定
大量のログが出力される環境では、ログローテーションの設定が必要となる。
# ログローテーション設定(postgresql.conf内)
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_rotation_age = 1d
log_rotation_size = 100MB
log_truncate_on_rotation = onログローテーション設定の説明
| パラメータ | 設定値 | 説明 |
|---|---|---|
log_rotation_age | 1d | 1日でローテーション |
log_rotation_size | 100MB | 100MBでローテーション |
log_truncate_on_rotation | on | ローテーション時にファイルを切り詰める |
ログ解析のクエリについて
よく実行されるクエリの確認
# よく実行されるクエリのパターンを確認
grep "statement:" logs/postgresql-*.log | \
sed 's/.*statement: //' | \
sort | uniq -c | sort -nr | head -10実行時間の長いクエリの特定
※別途スロークエリログとかに出力してもよいと思う。
# 実行時間が長いクエリを確認(例:1秒以上)
grep "duration:" logs/postgresql-*.log | \
awk '$NF > 1000.0 {print}' | \
sort -k7 -nrエラーの確認
# エラーログの確認
grep -i "error\|fatal\|panic" logs/postgresql-*.log参考
PostgreSQL公式ドキュメント - Error Reporting and Logging
https://www.postgresql.org/docs/17/runtime-config-logging.html第19章 サーバ設定-19.8. エラー報告とログ出力 | PostgreSQL 17.5文書
https://www.postgresql.jp/document/17/html/runtime-config-logging.htmlPostgreSQL公式ドキュメント - ログファイルの管理
https://www.postgresql.org/docs/17/logfile-maintenance.html第24章 定常的なデータベース保守作業-24.3. ログファイルの保守 | PostgreSQL 17.5文書
https://www.postgresql.jp/document/17/html/runtime-config-logging.htmlDocker Hub - PostgreSQL公式イメージ
https://hub.docker.com/_/postgres
おわりに
PostgreSQLコンテナでのSQLログ出力は、開発やデバッグ、パフォーマンス監視において有用であった。
プロシージャの開発については、アプリケーション側で呼んだ場合はエラーハンドリングしていないと原因の特定がかなり難しいので、ログで究明できるのは助かる。
また、実行されるクエリの詳細を把握することで最適化にも大きく役立つはず…!
ただ、本番環境ではパフォーマンスやセキュリティを考慮し、必要最小限のログ出力に留めることが必要だとも学んでいるので、用途に応じて設定を適切に調整し、ログ機能を活用する必要がある。
今回は、プロシージャのデバッグの際に原因の特定が全くできなかったのでログを出力するということをやってみた。
今後はこれを活用して業務でも問題を早期発見できるようにしていきたい。