【PostgreSQL】パフォーマンスの劣化したSQLを確認したい（log_min_duration_statement）

2023年12月18日 2023年12月16日

         QUERY PLAN
-----------------------------
 Planning time: 0.241 ms
 Execution time: 23286.662 ms
(14 行)

古いシステム、大量のレコードを取り扱うシステムに遭遇した時、とても不安に思います。
ズバリSQLのパフォーマンスなのですが、たまに見かけるそんなシステムの保守をするとき、必ずといっていいほどSQLのパフォーマンスが悪く、どこからメンテナンスしようか悩ましいときがあります。

PostgreSQLには実行に時間がかかったSQL（スロークエリ）をログに保存しておく機能があるので、設定しておくと改善対象のSQLが探しやすくなります。

1 log_min_duration_statementによる確認
2 0で設定しておくと・・・？
- 2.1 ”\d”の場合
- 2.2 ”SELECT * FROM ”入力後TABキーを押した場合

log_min_duration_statementによる確認

log_min_duration_statementを設定することで実現が可能。
デフォルトだと下記のように無効（-1）になっているため、自分で有効にする必要がある。

testdb=# show log_min_duration_statement ;
 log_min_duration_statement
----------------------------
 -1
(1 行)

設定値の単位はミリ秒。
SQLの実行に設定値以上の時間がかかった場合、そのSQLをログに書き出します。
SLAか社内ルールでパフォーマンスの取り決めがあれば加味して設定しておけば良いかと思います。

pg_settings.context（設定値反映タイミング）は”superuser”なのでreloadによる設定値の反映が可能。実行にかかった時間とSQLが記録されるので、”どんなスロークエリが実行されたか、どれぐらいかかったか”が記録されます。

2020-03-29 22:30:08.596 JST [2237] LOG:  duration: 197.932 ms  statement: select * from user_mst;

※上記は”select * from user_mst”というSQLが”197.932 ms”かかったことが記録されています。

0で設定しておくと・・・？

log_min_duration_statementを0に設定すると思わぬSQLが記録されることがあります。

0にすると0ミリ秒以上かかるSQLが記録されるので、実質全てのSQLが記録されます。
例えば”\d”を実行するとスキーマ一覧が表示されますが、実は内部でしっかりSQLが実行されてます。
また”SELECT * FROM ”まで打ち込んでTABキーを押すと候補となるテーブルなどがリストアップされてますが、これも内部的にSQLが実行されてます。

見ておくとちょっとおもしろいかも。

”\d”の場合

2020-03-29 22:45:43.976 JST [2237] LOG:  duration: 2.146 ms  statement: SELECT n.nspname as "Schema",
          c.relname as "Name",
          CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' WHEN 'p' THEN 'table' END as "Type",
          pg_catalog.pg_get_userbyid(c.relowner) as "Owner"
        FROM pg_catalog.pg_class c
             LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
        WHERE c.relkind IN ('r','p','v','m','S','f','')
              AND n.nspname <> 'pg_catalog'
              AND n.nspname <> 'information_schema'
              AND n.nspname !~ '^pg_toast'
          AND pg_catalog.pg_table_is_visible(c.oid)
        ORDER BY 1,2;

**”SELECT * FROM ”入力後TABキーを押した場合**

2020-03-29 22:49:29.154 JST [2237] LOG:  duration: 3.897 ms  statement: SELECT pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c WHERE c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(c.relname),1,0)='' AND pg_catalog.pg_table_is_visible(c.oid) AND c.relnamespace <> (SELECT oid FROM pg_catalog.pg_namespace WHERE nspname = 'pg_catalog')
        UNION
        SELECT pg_catalog.quote_ident(n.nspname) || '.' FROM pg_catalog.pg_namespace n WHERE substring(pg_catalog.quote_ident(n.nspname) || '.',1,0)='' AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,0) = substring('',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) > 1
        UNION
        SELECT pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg_class c, pg_catalog.pg_namespace n WHERE c.relnamespace = n.oid AND c.relkind IN ('r', 'S', 'v', 'm', 'f', 'p') AND substring(pg_catalog.quote_ident(n.nspname) || '.' || pg_catalog.quote_ident(c.relname),1,0)='' AND substring(pg_catalog.quote_ident(n.nspname) || '.',1,0) = substring('',1,pg_catalog.length(pg_catalog.quote_ident(n.nspname))+1) AND (SELECT pg_catalog.count(*) FROM pg_catalog.pg_namespace WHERE substring(pg_catalog.quote_ident(nspname) || '.',1,0) = substring('',1,pg_catalog.length(pg_catalog.quote_ident(nspname))+1)) = 1
        LIMIT 1000