Running EXPLAIN ANALYZE on functions

Sometimes it can help to look at Postgres query plans inside a function. The problem is that running EXPLAIN ANALYZE on a function usually just shows a function scan or result node, which gives little insight into how the queries actually perform.

auto_explain is a pre-installed module that is able to log query plans for queries within functions.

auto_explain has a few settings that you still need to configure:

• auto_explain.log_nested_statements: log the plans of queries within functions
• auto_explain.log_analyze: capture the explain analyze results instead of explain
• auto_explain.log_min_duration: if a query is expected to run for longer than the setting's threshold, log the plan

Changing these settings at a broad scale can lead to excessive logging. Instead, you can change the configs within a begin/rollback block with the set local command. This ensures the changes are isolated to the transaction, and any writes made during testing are undone.

1
begin;
2
3
set local auto_explain.log_min_duration = '0';       -- log all query plans
4
set local auto_explain.log_analyze = true;           -- use explain analyze
5
set local auto_explain.log_buffers  = true;          -- use explain (buffers)
6
set local auto_explain.log_nested_statements = true; -- log query plans in functions
7
8
select example_func(); ---<--ADD YOUR FUNCTION HERE
9
10
rollback;

If needed, you can change these settings for specific roles, but we don't recommend configuring the value below 1s for extended periods, as it may degrade performance.

For instance, you could change the value for the authenticator role (powers the Data API).

1
ALTER ROLE postgres SET auto_explain.log_min_duration = '.5s';

After running your test, you should be able to find the plan in the Postgres logs. The auto_explain module always starts logs with the term "duration:", which can be used as a filter keyword.

You can also filter for the specific function in the log explorer with the below query:

1
select
2
  cast(postgres_logs.timestamp as datetime) as timestamp,
3
  event_message as query_and_plan,
4
  parsed.user_name,
5
  parsed.context
6
from
7
  postgres_logs
8
  cross join unnest(metadata) as metadata
9
  cross join unnest(metadata.parsed) as parsed
10
where regexp_contains(event_message, 'duration:') and regexp_contains(context, '(?i)FUNCTION_NAME')
11
order by timestamp desc
12
limit 100;