Running EXPLAIN ANALYZE on functions

You call a slow database function, run EXPLAIN ANALYZE on it, and get back a plan that says almost nothing.

What you see

explain analyze select public.invoice_totals('7c1e0a52-3f4b-4d61-9a0e-2a8f5f0c9b11');

Result  (cost=0.00..0.26 rows=1 width=32) (actual time=1843.201..1843.202 rows=1 loops=1)
Planning Time: 0.031 ms
Execution Time: 1843.230 ms

For a set-returning function you may see Function Scan on invoice_totals instead. Either way, the total time is there but the queries that caused it are not.

Why it happens

EXPLAIN plans the statement you give it. For a plpgsql function, that statement is just "call this function". The queries inside the function body are planned separately when the function runs, so they never show up in the outer plan.

Simple language sql functions are different: when one is used in FROM and meets Postgres's inlining rules (a single select, not strict, not security definer, no set clause, declared stable or immutable), the planner folds its body into the outer query and EXPLAIN shows the real plan.

How to fix it

Option 1: plan the inner query yourself. This works in every SQL client, including Studio's SQL editor.

1. Copy the slow query out of the function body.
2. Turn the function parameters into a prepared statement, so Postgres plans it the way the function does:

prepare totals(uuid) as
  select date_trunc('month', issued_at) as month, sum(amount_cents)
  from public.invoices
  where account_id = $1
  group by 1;

explain (analyze, buffers) execute totals('7c1e0a52-3f4b-4d61-9a0e-2a8f5f0c9b11');
deallocate totals;

3. plpgsql caches plans, and after five calls it may switch to a generic plan that ignores the actual parameter value. To see that plan too:

set plan_cache_mode = force_generic_plan;
prepare totals(uuid) as select ...;  -- same query as above
explain (analyze, buffers) execute totals('7c1e0a52-3f4b-4d61-9a0e-2a8f5f0c9b11');
reset plan_cache_mode;

If the generic plan is much slower, the usual fix is an index that suits every value, or building that one query with execute format(...) so it's planned per call.

Option 2: auto_explain with nested statements. The auto_explain module can print the plan of every statement a function runs. Try it in one session:

set auto_explain.log_min_duration = 0;
set auto_explain.log_analyze = on;
set auto_explain.log_nested_statements = on;
set auto_explain.log_level = notice;

select public.invoice_totals('7c1e0a52-3f4b-4d61-9a0e-2a8f5f0c9b11');

log_level = notice sends the plans to your client as notices instead of to the server log. If you get "permission denied to set parameter", or no plans appear, your role can't use auto_explain in this session; use option 1. Not every SQL client displays notices. psql does.

On SupaHost

• The server log isn't something you can browse: there's no log explorer, and Postgres only logs fatal errors. That's why option 2 sends plans to the client.
• On Business, psql shows notices: sudo supahost-psql app-one over SSH. See SSH access and direct Postgres.
• When a function is called through the Data API (supabase.rpc()), it runs as anon or authenticated with RLS. To time it the same way, test inside set local role authenticated as shown in RLS performance best practices.

Related

• Query performance and EXPLAIN
• Database functions
• Speeding up slow queries with indexes