PostgreSQLでストアドプロシージャ開発をするその7 ～プロシージャ内のSQLの実行計画を見る～

はじめに

前回に引き続き、ストアドプロシージャの開発に入門していく。
今回はプロシージャ内で実行される全てのSQLの実行計画を自動的に取得する方法について学ぶ。

プロシージャのパフォーマンスチューニングを行う際、プロシージャ内で実行されているSQLそれぞれの実行計画を確認したいことがある。
しかし、通常のEXPLAINでは、プロシージャを実行する前に計画を取得するため、実際の実行時のパラメータや動的SQLの実行計画を確認できない。

そこで、auto_explainモジュールを使用することにより、プロシージャ内で実行される全てのSQLの実行計画を自動的にログを出力できるようになるとのことで実際に試してみる。

環境

Windows 11 Professional
PostgreSQL 17
Docker Desktop 4.50.0 (209931)

今回の記事のゴール

この記事では、PostgreSQLのauto_explainモジュールを使って、プロシージャ内で実行される全てのSQLの実行計画を自動的に取得できるようになることを目標とする。

auto_explainとは

auto_explainは、PostgreSQLの公式拡張モジュールの一つで、指定した実行時間を超えるSQLの実行計画を自動的にログに出力する機能を提供する。

プロシージャ内で実行されるSQLも含めて、全てのSQLの実行計画が自動的に記録される。

考えうる限りだと以下のメリットがある。
例えば、

手動でEXPLAINを実行しなくても、ログに出力してくれる
EXECUTEで実行される動的SQLの実行計画も取得できる（これは地味に嬉しい）
プロシージャに渡された実際のパラメータでの実行計画が確認できる
しきい値を設定すれば、本番環境でも遅いクエリだけ記録できる

といった感じで使える。

auto_explainのパラメータ

以下はauto_explainで使用できるパラメータ一覧となる。
詳細はPostgreSQL公式ドキュメント - F.4. auto_explainを参照してほしい。

注意: 実際の設定時は、全てのパラメータ名にauto_explain.の接頭辞が必要

パラメータ	デフォルト値	説明
log_min_duration	`-1` (無効)	この時間(ミリ秒)を超えるSQL文の実行計画をログに出力 `0`で全てのSQL、`-1`で無効
log_analyze	`false`	`EXPLAIN ANALYZE`相当の情報(実測値)を出力するかどうか
log_buffers	`false`	バッファ使用状況を出力するかどうか
log_timing	`true`	各ノードの実行時間を出力するかどうか
log_triggers	`false`	トリガーの実行統計を出力するかどうか
log_verbose	`false`	`EXPLAIN VERBOSE`相当の詳細情報を出力するかどうか
log_nested_statements	`false`	ネストされた文(関数内のSQL等)もログに出力するかどうか
log_format	`text`	ログ出力形式 `text`、`xml`、`json`、`yaml`から選択可能
log_level	`log`	ログレベル `debug5`、`debug4`、`debug3`、`debug2`、`debug1`、 `info`、`notice`、`warning`、`log`から選択可能
log_settings	`false`	非デフォルト設定パラメータの情報をログに含めるかどうか（PostgreSQL 12以降）
sample_rate	`1.0`	実行計画を記録する文のサンプリング比率（0.0〜1.0） `1.0`で全て記録

準備

元となる環境については、以下のリポジトリのDockerを使用している。

katsuobushiFPGA / postgresql-procedure-dev
https://github.com/katsuobushiFPGA/postgresql-procedure-dev

auto_explainの設定

1. postgresql.confの設定

auto_explainを使用するには、PostgreSQLの設定ファイル(postgresql.conf)に以下の設定を追加する必要がある。

postgresql.conf

# ----------------------
# auto_explain設定
# ----------------------

# auto_explainモジュールをプリロード
shared_preload_libraries = 'auto_explain'

# 実行時間がこの値(ミリ秒)を超えるSQL文の実行計画をログに出力
# 0: 全てのSQL文の実行計画を出力
# -1: 無効（デフォルト）
auto_explain.log_min_duration = 0

# EXPLAIN ANALYZEと同等の情報を出力（実測値を含む）
auto_explain.log_analyze = true

# バッファ使用状況を出力
auto_explain.log_buffers = true

# 各ノードの実行時間を出力
auto_explain.log_timing = true

# VERBOSEモード（詳細情報を出力）
auto_explain.log_verbose = false

# ネストされた文（関数やプロシージャ内のSQL）もログに出力
auto_explain.log_nested_statements = true

# トリガーの実行統計を出力
auto_explain.log_triggers = false

# ログ形式をJSON、XML、YAMLのいずれかで指定可能（デフォルトはTEXT）
# auto_explain.log_format = 'text'

2. Dockerでの設定方法

本リポジトリでは、Dockerを使用してPostgreSQLを起動している。
compose.ymlでpostgresql.confをマウントしているため、ホスト側のpostgresql.confを編集することでコンテナ内のPostgreSQLの設定を変更できる。

compose.ymlの確認

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:

3. 設定の反映

設定を変更したら、PostgreSQLを再起動して設定を反映させる。

# Dockerコンテナを再起動
docker compose down
docker compose up -d

# または、PostgreSQLのみを再起動
docker compose restart db

設定が正しく読み込まれたか確認する。

-- auto_explainの設定を確認
SHOW shared_preload_libraries;
SHOW auto_explain.log_min_duration;
SHOW auto_explain.log_analyze;
SHOW auto_explain.log_nested_statements;

※SHOWコマンドで設定したパラメータ値通りになっていればよい。

auto_explainを使った実行計画の確認

1. 簡単なプロシージャで確認

まず、簡単なプロシージャを作成して、auto_explainの動作を確認する。

CREATE OR REPLACE PROCEDURE get_todos_by_status(
    p_is_completed BOOLEAN
)
LANGUAGE plpgsql
AS $$
BEGIN
    -- シンプルなSELECT文
    PERFORM * FROM todos WHERE is_completed = p_is_completed;
    
    RAISE NOTICE 'Completed status: %', p_is_completed;
END;
$$;

このプロシージャを実行してみる。

CALL get_todos_by_status(true);

2. ログの確認

プロシージャを実行すると、logsディレクトリにログファイルが出力される。

# ログファイルの確認
cat logs/postgresql-*.log | grep -A 20 "duration:"

ログには以下のような実行計画が出力される

実行結果

2025-11-12 10:41:41.063 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.279 ms  plan:
	Query Text: SELECT * FROM todos WHERE is_completed = p_is_completed
	Seq Scan on todos  (cost=0.00..17.70 rows=385 width=77) (actual time=0.277..0.278 rows=0 loops=1)
	  Filter: is_completed
	  Rows Removed by Filter: 3
	  Buffers: shared read=1
2025-11-12 10:41:41.063 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT * FROM todos WHERE is_completed = p_is_completed"
	PL/pgSQL function get_todos_by_status(boolean) line 4 at PERFORM
2025-11-12 10:41:41.063 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  Completed status: t
2025-11-12 10:41:41.063 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function get_todos_by_status(boolean) line 6 at RAISE
2025-11-12 10:41:41.064 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 2.743 ms

3. 複数のSQLを含むプロシージャ

次に、複数のSQLを含むプロシージャで確認してみる。

-- 複数のSQLを含むプロシージャ
CREATE OR REPLACE PROCEDURE analyze_todos()
LANGUAGE plpgsql
AS $$
DECLARE
    v_total_count INTEGER;
    v_completed_count INTEGER;
    v_pending_count INTEGER;
BEGIN
    RAISE NOTICE '=== TODO分析を開始します ===';
    
    -- 1. 全件数を取得
    SELECT COUNT(*) INTO v_total_count FROM todos;
    
    -- 2. 完了済み件数を取得
    SELECT COUNT(*) INTO v_completed_count 
    FROM todos 
    WHERE is_completed = true;
    
    -- 3. 未完了件数を取得
    SELECT COUNT(*) INTO v_pending_count 
    FROM todos 
    WHERE is_completed = false;
    
    -- 4. 結果を表示
    RAISE NOTICE '全体: %件', v_total_count;
    RAISE NOTICE '完了: %件', v_completed_count;
    RAISE NOTICE '未完了: %件', v_pending_count;
    
    -- 5. 期限切れのタスクを抽出
    PERFORM * FROM todos 
    WHERE is_completed = false 
      AND due_date < CURRENT_DATE;
      
    RAISE NOTICE '=== 分析完了 ===';
END;
$$;

実行してログを確認する。

CALL analyze_todos();

ログには、プロシージャ内で実行された全てのSQLの実行計画が出力される

実行結果

2025-11-12 10:43:03.538 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  statement: CALL analyze_todos();
2025-11-12 10:43:03.538 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  === TODO分析を開始します ===
2025-11-12 10:43:03.538 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function analyze_todos() line 7 at RAISE
2025-11-12 10:43:03.538 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.011 ms  plan:
	Query Text: SELECT COUNT(*)                    FROM todos
	Aggregate  (cost=19.62..19.64 rows=1 width=8) (actual time=0.009..0.010 rows=1 loops=1)
	  Buffers: shared hit=1
	  ->  Seq Scan on todos  (cost=0.00..17.70 rows=770 width=0) (actual time=0.006..0.007 rows=3 loops=1)
	        Buffers: shared hit=1
2025-11-12 10:43:03.538 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT COUNT(*)                    FROM todos"
	PL/pgSQL function analyze_todos() line 10 at SQL statement
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.004 ms  plan:
	Query Text: SELECT COUNT(*)                             FROM todos 
	    WHERE is_completed = true
	Aggregate  (cost=18.66..18.67 rows=1 width=8) (actual time=0.003..0.003 rows=1 loops=1)
	  Buffers: shared hit=1
	  ->  Seq Scan on todos  (cost=0.00..17.70 rows=385 width=0) (actual time=0.003..0.003 rows=0 loops=1)
	        Filter: is_completed
	        Rows Removed by Filter: 3
	        Buffers: shared hit=1
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT COUNT(*)                             FROM todos 
	    WHERE is_completed = true"
	PL/pgSQL function analyze_todos() line 13 at SQL statement
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.004 ms  plan:
	Query Text: SELECT COUNT(*)                           FROM todos 
	    WHERE is_completed = false
	Aggregate  (cost=18.66..18.67 rows=1 width=8) (actual time=0.004..0.004 rows=1 loops=1)
	  Buffers: shared hit=1
	  ->  Seq Scan on todos  (cost=0.00..17.70 rows=385 width=0) (actual time=0.002..0.003 rows=3 loops=1)
	        Filter: (NOT is_completed)
	        Buffers: shared hit=1
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT COUNT(*)                           FROM todos 
	    WHERE is_completed = false"
	PL/pgSQL function analyze_todos() line 18 at SQL statement
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  全体: 3件
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function analyze_todos() line 23 at RAISE
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  完了: 0件
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function analyze_todos() line 24 at RAISE
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  未完了: 3件
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function analyze_todos() line 25 at RAISE
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.003 ms  plan:
	Query Text: SELECT * FROM todos 
	    WHERE is_completed = false 
	      AND due_date < CURRENT_DATE
	Seq Scan on todos  (cost=0.00..21.55 rows=128 width=77) (actual time=0.002..0.003 rows=1 loops=1)
	  Filter: ((NOT is_completed) AND (due_date < CURRENT_DATE))
	  Rows Removed by Filter: 2
	  Buffers: shared hit=1
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT * FROM todos 
	    WHERE is_completed = false 
	      AND due_date < CURRENT_DATE"
	PL/pgSQL function analyze_todos() line 28 at PERFORM
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  === 分析完了 ===
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function analyze_todos() line 32 at RAISE
2025-11-12 10:43:03.539 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 1.205 ms

4. 動的SQLの実行計画を確認

auto_explainは、動的SQLの実行計画も確認できる。

-- 動的SQLを使用するプロシージャ
CREATE OR REPLACE PROCEDURE dynamic_search_todos(
    p_column_name TEXT,
    p_column_value TEXT
)
LANGUAGE plpgsql
AS $$
DECLARE
    sql_query TEXT;
    v_count INTEGER;
BEGIN
    -- 動的にSQLを組み立てる
    sql_query := format(
        'SELECT COUNT(*) FROM todos WHERE %I = %L',
        p_column_name,
        p_column_value
    );
    
    RAISE NOTICE '実行するSQL: %', sql_query;
    
    -- 動的SQLを実行
    EXECUTE sql_query INTO v_count;
    
    RAISE NOTICE '該当件数: %件', v_count;
END;
$$;

実行してみる。

-- titleカラムで検索
CALL dynamic_search_todos('title', 'Buy groceries');

-- descriptionカラムで検索
CALL dynamic_search_todos('description', 'Important task');

ログには、実行された動的SQLの実行計画も出力される

実行結果

2025-11-12 10:45:07.231 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  statement: CALL dynamic_search_todos('title', 'Buy groceries');
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  実行するSQL: SELECT COUNT(*) FROM todos WHERE title = 'Buy groceries'
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function dynamic_search_todos(text,text) line 13 at RAISE
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.013 ms  plan:
	Query Text: SELECT COUNT(*) FROM todos WHERE title = 'Buy groceries'
	Aggregate  (cost=19.64..19.65 rows=1 width=8) (actual time=0.010..0.012 rows=1 loops=1)
	  Buffers: shared hit=1
	  ->  Seq Scan on todos  (cost=0.00..19.62 rows=4 width=0) (actual time=0.009..0.009 rows=0 loops=1)
	        Filter: (title = 'Buy groceries'::text)
	        Rows Removed by Filter: 3
	        Buffers: shared hit=1
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT COUNT(*) FROM todos WHERE title = 'Buy groceries'"
	PL/pgSQL function dynamic_search_todos(text,text) line 16 at EXECUTE
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  該当件数: 0件
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function dynamic_search_todos(text,text) line 18 at RAISE
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 1.394 ms
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  QUERY STATISTICS
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 DETAIL:  ! system usage stats:
	!	0.000906 s user, 0.000000 s system, 0.001410 s elapsed
	!	[0.017949 s user, 0.000000 s system total]
	!	21596 kB max resident size
	!	32/0 [1536/144] filesystem blocks in/out
	!	4/1 [97/901] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	2/0 [69/13] voluntary/involuntary context switches
2025-11-12 10:45:07.232 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 STATEMENT:  CALL dynamic_search_todos('title', 'Buy groceries');
2025-11-12 10:45:09.723 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  statement: CALL dynamic_search_todos('description', 'Important task');
2025-11-12 10:45:09.723 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  実行するSQL: SELECT COUNT(*) FROM todos WHERE description = 'Important task'
2025-11-12 10:45:09.723 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function dynamic_search_todos(text,text) line 13 at RAISE
2025-11-12 10:45:09.723 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.036 ms  plan:
	Query Text: SELECT COUNT(*) FROM todos WHERE description = 'Important task'
	Aggregate  (cost=19.64..19.65 rows=1 width=8) (actual time=0.018..0.018 rows=1 loops=1)
	  Buffers: shared hit=1
	  ->  Seq Scan on todos  (cost=0.00..19.62 rows=4 width=0) (actual time=0.015..0.015 rows=0 loops=1)
	        Filter: (description = 'Important task'::text)
	        Rows Removed by Filter: 3
	        Buffers: shared hit=1
2025-11-12 10:45:09.723 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  SQL statement "SELECT COUNT(*) FROM todos WHERE description = 'Important task'"
	PL/pgSQL function dynamic_search_todos(text,text) line 16 at EXECUTE
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 NOTICE:  該当件数: 0件
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 CONTEXT:  PL/pgSQL function dynamic_search_todos(text,text) line 18 at RAISE
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  duration: 0.616 ms
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 LOG:  QUERY STATISTICS
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 DETAIL:  ! system usage stats:
	!	0.000570 s user, 0.000000 s system, 0.000616 s elapsed
	!	[0.018617 s user, 0.000000 s system total]
	!	21596 kB max resident size
	!	0/0 [1536/144] filesystem blocks in/out
	!	0/0 [97/901] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [70/13] voluntary/involuntary context switches
2025-11-12 10:45:09.724 GMT [43] postgres@postgres pgAdmin 4 - CONN:4619614 STATEMENT:  CALL dynamic_search_todos('description', 'Important task');

Tips: 本番環境での使用

auto_explainは本番環境でも使用できるが、以下の点に注意する必要がある。

1. しきい値の設定

全てのSQLの実行計画を出力すると、ログファイルが膨大になる可能性がある。
本番環境では、遅いクエリのみをログに出力するようにしきい値を設定したほうが良い。

環境	設定	理由
開発環境	`log_min_duration = 0`	全てのSQLを記録して詳細に分析
	`log_analyze = true`	実測値を含む詳細情報を取得
本番環境	`log_min_duration = 100` (100ms~)	遅いクエリのみを記録してログ量を抑制
	`log_analyze = false`	オーバーヘッドを削減してパフォーマンス重視

2. パフォーマンスの影響

auto_explain.log_analyze = trueを設定すると、EXPLAIN ANALYZEと同等の情報を取得するため、多少のオーバーヘッドが発生する。
そのため、1. しきい値の設定 で設定する内容と同じ形で慎重に設定したほうが良さそうだ。
※つまり、本番環境では log_analyze = falseにしてオーバーヘッドを削減、またはlog_min_durationを大きめの値に設定ということになる。

3. ログのローテーション

ログファイルが肥大化しないように、ログのローテーション設定を確認する。例としては以下の通り。

パラメータ	設定例	説明
log_rotation_age	`1d`	ログファイルの自動ローテーション（1日ごと）
log_rotation_size	`10MB`	ログファイルのサイズでローテーション（10MB）
log_truncate_on_rotation	`on`	ローテーション時に既存ファイルを切り詰める

個人的な結論

auto_explainを使うことで、プロシージャ内で実行される全てのSQLの実行計画を簡単に取得できるようになった。

これによって以下の場面で有用であると感じた。
※本番環境では気軽に設定できないので、あくまで開発環境の中での話ではあるが。

SQLのデバッグ実行されるまでSQL文が確定しない動的SQLの実行計画を確認できる
プロシージャのチューニング複数のSQLを含むプロシージャで、ボトルネックとなっているSQLを特定できる

もし、本番で設定できるのであれば以下もメリットして挙げられる。

本番環境でのプロシージャ監視しきい値を設定することで、遅いクエリのみを自動的に記録できる

参考

F.4. auto_explain — 遅い問い合わせの実行計画を自動的にログ収集 | PostgreSQL 17.6文書
https://www.postgresql.jp/document/17/html/auto-explain.html
19.11. クライアント接続デフォルト | PostgreSQL 17.6文書
https://www.postgresql.jp/document/17/html/runtime-config-client.html
19.8. エラー報告とログ取得 | PostgreSQL 17.6文書
https://www.postgresql.jp/document/17/html/runtime-config-logging.html

おわりに

プロシージャのパフォーマンスチューニングを行う際、実行計画を確認することをまず一にやる必要がある。
のだが、プロシージャ内のSQLを見て一つずつEXPLAINを実行するのは非常に手間がかかるのである。
今回、auto_explainを使うことで、プロシージャ内の全てのSQLの実行計画を自動的に取得できることを知り、デバッグやチューニングの方法を学ぶことができた。

次回、特にテーマがなければインデックスとかについて調べていく。
※ある環境ではindex効いているのに、別の環境では効かないという現象に遭遇したので、そのあたりを深掘りしていきたい。
→大体こういうのは自分の見落としや勘違いだったりするのだが…。