【PgSQL】最も時間のかかるSQLを持つ位置関数

一、問題の背景#

pg の中で、ある関数の実行時間が 30 分を超える場合、どの SQL が遅いのかを確認します。しかし、pg_stat_activity を直接クエリすると、上位の実行関数の文しか表示されず、Oracle や SqlServer のように現在実行中のものを確認することはできません。

create table test(id int);
INSERT INTO test(id) VALUES (generate_series(1, 10000));
 
create table test2(id int);
INSERT INTO test2(id) VALUES (generate_series(1, 10000));

create or replace function test_f() returns bigint
as $$
	select count(*) from test;
	select count(*) from test2;
	select count(*) from test,test2;
$$ language sql;

関数の実行

test_db=# \timing
Timing is on.
test_db=# select test_f();
  test_f
-----------
 100000000
(1 row)
Time: 16203.883 ms

実行状況を確認

-- PG >= 9.6
select pid,usename,substring(query from 0 for 50),now()-query_start as time,wait_event_type,wait_event from pg_stat_activity where state = 'active';


  pid   | usename  |                     substring                     |      time       | wait_event_type | wait_event
--------+----------+---------------------------------------------------+-----------------+-----------------+------------
 395096 | postgres | select test_f();                                  | 00:00:01.197204 |                 |

二、方法のまとめと比較#

方法	関数コードの直接分析	raise notice でマーキング	auto_explain を設定して pg_nested_statements=true にする	pg_stat_statements.track=all
利点	簡単で、関数コードが非常にシンプルな場合に適しています。	1. 直接的 2. プログラム実行時に遅い SQL を特定できる	1. 各 SQL の実行計画と実行時間を表示できる。 2. グローバルまたはセッションレベルで有効にできる	1. 各 SQL の統計データを表示でき、遅い SQL を間接的に分析できる 2. グローバルまたはセッションレベルで有効にできる。
欠点	複雑な関数にはほとんど適用できません。	複雑な関数の場合、マーキングする必要があり、非常に不便です。	1. 負荷が高い、関数が多いライブラリでは、基本的にグローバルで有効にできません。 2. セッションレベルで有効にするには、手動で実行する必要があり、プログラム実行時に分析できません。 3.DML 操作のある関数には実行しないか、トランザクションを実行してからロールバックする必要があります。	1. 負荷が高い、関数が多いライブラリでは、基本的にグローバルで有効にできません。 2.SQL の実行が多いライブラリでは、auto_explain よりも特定が難しいです。 3. セッションレベルで有効にするには、手動で実行する必要があり、プログラム実行時に分析できません。 4.DML 操作のある関数には実行しないか、トランザクションを実行してからロールバックする必要があります。

以前に記録した Oracle と SQL Server の特定方法も添付しています：

Oracle ストアドプロシージャの遅い SQL の特定方法_oracle ストアドプロシージャ_Hehuyi_In のブログ - CSDN ブログ

SQL Server でストアドプロシージャ内の最も時間がかかる部分を見つける方法_Hehuyi_In のブログ - CSDN ブログ

関数コードの直接分析#

\sf 関数名 で関数コードを表示できます。これは、関数が非常にシンプルな場合に使用できます。

\sf test_f

関数内の SQL が非常に長い場合、出力が改行される可能性があるため、テキストにエクスポートするために psql を使用することもできます。

psql -c "\sf test_f" > test_f.sql

raise notice でマーキング#

注意点として、raise は plpgsql 言語を使用する必要があります。上記の例では sql を使用するとエラーが発生するため、テストのために少し変更しました。

CREATE OR REPLACE FUNCTION test_f_2() RETURNS integer AS $$
declare num int;
BEGIN
	raise notice 'notice 1, start at: %',clock_timestamp();
	insert into test select count(*) from test;
	raise notice 'notice 2, start at: %',clock_timestamp();
	select count(*) into num from test,test2;
	raise notice 'notice 3, start at: %',clock_timestamp();
	insert into test2 select count(*) from test2;
	raise notice 'notice end, end at: %',clock_timestamp();
	return num;
END;
$$ LANGUAGE plpgsql;

select test_f_2();

auto_explain で各 SQL の実行計画を表示#

大規模なライブラリでは、SQL をグローバルにキャプチャすることは適していません。そのため、クライアント側で有効にすることができます。
以下のパラメータを設定しますが、log_nested_statements = trueが重要で、関数内のすべての SQL の実行計画を表示します。

拡張機能 auto_explain のインストールについては、[[6. Extensions-PG#auto_explain]] を参照してください。

LOAD 'auto_explain';
set client_min_messages='log';
set auto_explain.log_min_duration = 0;
set auto_explain.log_analyze = true;
set auto_explain.log_verbose = true;
set auto_explain.log_buffers = true;
set auto_explain.log_nested_statements = true;

test_db=# select test_f();
-- SQL 1の実行時間
LOG:  duration: 0.984 ms  plan:
Query Text:
select count(*) from test;
select count(*) from test2;
select count(*) from test,test2;

Aggregate  (cost=170.00..170.01 rows=1 width=8) (actual time=0.983..0.983 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=45
  ->  Seq Scan on public.test  (cost=0.00..145.00 rows=10000 width=0) (actual time=0.003..0.568 rows=10002 loops=1)
        Output: id
        Buffers: shared hit=45

-- SQL 2の実行時間
LOG:  duration: 1.114 ms  plan:
Query Text:
select count(*) from test;
select count(*) from test2;
select count(*) from test,test2;

...

-- 全体の実行時間
LOG:  duration: 11760.851 ms  plan:
Query Text: select test_f();
Result  (cost=0.00..0.26 rows=1 width=4) (actual time=11760.840..11760.841 rows=1 loops=1)
  Output: test_f()
  Buffers: shared hit=232 dirtied=1
  test_f
-----------
 100040004
(1 row)

pg_stat_statements.track=all を設定#

基本的にはクライアント側で有効にすることもできますが、テスト環境でリセット後に個別に実行することもできます。auto_explain よりも特定が難しいです。
postgresql.conf

shared_preload_libraries = 'pg_stat_statements'

compute_query_id = on
pg_stat_statements.max = 10000
pg_stat_statements.track = all

set pg_stat_statements.track="all";
select test_f();

select userid::regrole,total_exec_time,query from pg_stat_statements order by total_exec_time desc;

引用元：
PostgreSQL で関数内の最も時間がかかる SQL を特定する