1. Problem Background#
For a function in pg that takes more than 30 minutes to execute, we need to identify which SQL statement is causing the slowness. However, if we directly query using pg_stat_activity, we can only see the statements of the upper-level executing function, unlike Oracle and SQL Server where we can see what is currently being executed.
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;
Execute the function
test_db=# \timing
Timing is on.
test_db=# select test_f();
test_f
-----------
100000000
(1 row)
Time: 16203.883 ms
Check the running status
-- 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 | |
2. Summary and Comparison of Methods#
| Method | Analyzing Function Code Directly | Using raise notice | Setting auto_explain with pg_nested_statements=true | Using pg_stat_statements.track=all |
|---|---|---|---|---|
| Pros | Straightforward, suitable for simple function code. | 1. Straightforward 2. Can locate slow SQL during program execution. | 1. Can display execution plans and execution times for each SQL statement in the function. 2. Can be enabled globally or per session. | 1. Can display statistics for each SQL statement in the function, indirectly analyzing slow SQL. 2. Can be enabled globally or per session. |
| Cons | Not feasible for complex functions. | Requires many raise notices for complex functions, not convenient. | 1. Not suitable for high-load databases with many functions, cannot be enabled globally. 2. Session-level enablement needs to be manually executed, cannot analyze during program execution. 3. Not recommended for functions with DML operations, or transaction execution with rollback. | 1. Not suitable for high-load databases with many functions, cannot be enabled globally. 2. More difficult to locate than auto_explain in databases with many SQL executions. 3. Session-level enablement needs to be manually executed, cannot analyze during program execution. 4. Not recommended for functions with DML operations, or transaction execution with rollback. |
Here are the previously recorded methods for Oracle and SQL Server:
Methods for Locating Slow SQL in Oracle Stored Procedures_oracle slow sql_Hehuyi_In's Blog-CSDN Blog
Analyzing Function Code Directly#
\sf function_name can be used to view the function code, which is suitable for simple functions.
\sf test_f
If the SQL in the function is very long, the output may be misaligned, making it difficult to analyze. In this case, you can use psql to export it as a text file.
psql -c "\sf test_f" > test_f.sql
Using raise notice to Tag#
Note that raise should be used with the plpgsql language. Using SQL as above will result in an error. For convenience of testing, some modifications are made.
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();
Setting auto_explain to Display Execution Plans for Each SQL Statement#
For databases with a large workload, it is not suitable to capture all SQL statements globally. Instead, it can be enabled on the client side.
Set the following parameters, with the core being log_nested_statements = true, which displays the execution plans for all SQL statements within the function.
For installation of the auto_explain extension, see: [[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();
-- Execution time for 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
-- Execution time for SQL 2
LOG: duration: 1.114 ms plan:
Query Text:
select count(*) from test;
select count(*) from test2;
select count(*) from test,test2;
...
-- Total execution time
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)
Setting pg_stat_statements.track=all#
This method is also only suitable for client-side enablement or running after a reset in a testing environment. It is more difficult to locate than 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;
Reposted from:
Locating Slow SQL in PostgreSQL Functions