PostgreSQLのDockerコンテナでSQLの実行ログを出力する

はじめに

PostgreSQLを使った開発やデバッグ時に、実際に実行されたSQLクエリを確認したい場面がある。
特に、アプリケーションから実行されるクエリの内容や実行時間を把握することで、パフォーマンス問題の特定や最適化等に役立つことがよくある。

PostgreSQLには詳細なログ機能が用意されており、実行されたSQL文、実行時間、エラーなどを出力できる。
今回は、DockerコンテナのPostgreSQLSQLの実行ログを有効にして確認するということをやってみる。

環境

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のリポジトリにコミットした。

PostgreSQLのログ設定

PostgreSQLのログ機能は、postgresql.confファイルで設定する。コンテナ環境では、環境変数や設定ファイルのマウントで設定を変更する。

主要なログ設定パラメータ

PostgreSQLのログ関連の主要な設定項目は以下となる。

パラメータ説明デフォルト値推奨値
log_statementログ出力するSQL文の種類noneall
log_min_duration_statement指定時間以上のクエリをログ出力(ミリ秒)-10
log_line_prefixログ行のプレフィックス%m [%p]%m [%p] %u@%d
logging_collectorログコレクタの有効化offon
log_directoryログファイルの出力ディレクトリloglog
log_filenameログファイル名のパターンpostgresql-%Y-%m-%d_%H%M%S.logデフォルト

今回変更したパラメータ一覧

GitHubコミット(e832350)で実際に変更されたパラメータは以下の通り。

パラメータ変更前(コメントアウト状態)変更後(有効化)説明
log_destination#log_destination = ‘stderr’log_destination = ‘stderr’ログ出力先の指定
logging_collector#logging_collector = offlogging_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 = 0600log_file_mode = 0644ログファイルの作成モード
log_min_messages#log_min_messages = warninglog_min_messages = infoログ出力する最小レベル
log_min_error_statement#log_min_error_statement = errorlog_min_error_statement = errorエラー文の出力レベル
log_min_duration_statement#log_min_duration_statement = -1log_min_duration_statement = 0実行時間ログの閾値(ミリ秒)
log_statement_sample_rate#log_statement_sample_rate = 1.0log_statement_sample_rate = 1.0ログ文のサンプリング率
log_connections#log_connections = offlog_connections = on接続ログの有効化
log_disconnections#log_disconnections = offlog_disconnections = on切断ログの有効化
log_duration#log_duration = offlog_duration = onSQL実行時間ログの有効化
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 = nonetrack_functions = plPL/pgSQL関数の実行追跡
log_statement_stats#log_statement_stats = offlog_statement_stats = onSQL実行統計の有効化
client_min_messages#client_min_messages = noticeclient_min_messages = noticeクライアント向けメッセージの最小レベル

パラメータの詳しい内容は下記を参照

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ファイルを作成する。

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).log

SQLを実行してログを確認

別のターミナルで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_age1d1日でローテーション
log_rotation_size100MB100MBでローテーション
log_truncate_on_rotationonローテーション時にファイルを切り詰める

ログ解析のクエリについて

よく実行されるクエリの確認

# よく実行されるクエリのパターンを確認
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コンテナでのSQLログ出力は、開発やデバッグ、パフォーマンス監視において有用であった。
プロシージャの開発については、アプリケーション側で呼んだ場合はエラーハンドリングしていないと原因の特定がかなり難しいので、ログで究明できるのは助かる。
また、実行されるクエリの詳細を把握することで最適化にも大きく役立つはず…!

ただ、本番環境ではパフォーマンスやセキュリティを考慮し、必要最小限のログ出力に留めることが必要だとも学んでいるので、用途に応じて設定を適切に調整し、ログ機能を活用する必要がある。

今回は、プロシージャのデバッグの際に原因の特定が全くできなかったのでログを出力するということをやってみた。
今後はこれを活用して業務でも問題を早期発見できるようにしていきたい。

Hugo で構築されています。
テーマ StackJimmy によって設計されています。