Get query plan for SQL statement nested in a PL/pgSQL function

Question

Is it possible to get the query plan for an SQL statement executed inside a user defined function (UDF)? Like with using EXPLAIN in pgAdmin or psql as client. I see the UDF abstracted away into a single operation F() in pgAdmin.

Currently, I pull out statements and run them manually. But this isn't going to cut it for large queries.

For example, consider the UDF below. It can print its dynamically generated query string. But that can't be run separately as it depends on a temporary table created in the local context.

CREATE OR REPLACE FUNCTION get_paginated_search_results(
    forum_id_ INTEGER,
    query_    CHARACTER VARYING,
    from_date_ TIMESTAMP WITHOUT TIME ZONE DEFAULT NULL,
    to_date_ TIMESTAMP WITHOUT TIME ZONE DEFAULT NULL,
    in_categories_ INTEGER[] DEFAULT '{}')
RETURNS SETOF post_result_entry AS $$
DECLARE
    join_string CHARACTER VARYING := ' ';
    from_where_date CHARACTER VARYING := ' ';
    to_where_date CHARACTER VARYING := ' ';
    query_string_ CHARACTER VARYING := ' ';
BEGIN
    IF NOT from_date_ IS NULL THEN
        from_where_date := ' AND fp.posted_at > ''' || from_date_ || '''';
    END IF;

    IF NOT to_date_ IS NULL THEN
        to_where_date := ' AND fp.posted_at < ''' || to_date_ || '''';
    END IF;

    CREATE LOCAL TEMP TABLE un_cat(id) ON COMMIT DROP AS (select * from unnest(in_categories_)) ;

    if in_categories_ != '{}' THEN
        join_string := ' INNER JOIN forum_topics ft ON fp.topic_id = ft.id ' ||
        ' INNER JOIN un_cat uc ON uc.id = ft.category_id ' ;
    END IF;

    query_string_ := '
    SELECT index,posted_at,post_text,name,join_date,quotes
    FROM forum_posts fp
    INNER JOIN forum_user fu ON
    fu.forum_id = fp.forum_id AND fu.id = fp.user_id' ||
        join_string
    ||
    'WHERE fu.forum_id = ' || forum_id_ || ' AND
    to_tsvector(''english'',fp.post_text) @@ to_tsquery(''english'','''|| query_||''')' || 
        from_where_date || 
        to_where_date
    ||';';

    RAISE NOTICE '%', query_string_ ;
    
    RETURN QUERY
    EXECUTE query_string_;
END;
$$ LANGUAGE plpgsql;

Answer 1

You should be able to use auto-explain. Turn it on and

SET auto_explain.log_min_duration = 0;

and you should get the plans in your log for all statements run in that session.

You might also want to set

SET auto_explain.log_analyze = true; but you'll essentially run everything double - once for 'real' and once to EXPLAIN ANALYZE on. During a non-timing performance testing phase, this output can be much more useful than EXPLAIN plans alone, as it provides what plan actually happened.

Answer 2

I addition to @rfusca's advice: SQL statements inside plpgsql functions are considered nested statements and you need to set the additional Parameter auto_explain.log_nested_statements.

Unlike some other extensions, you don't have to run CREATE EXTENSION for this one. Just load it dynamically into your session with LOAD. You must be superuser for this.
Your session could look like this:

LOAD 'auto_explain';
SET auto_explain.log_min_duration = 1; -- exclude very fast trivial queries
SET auto_explain.log_nested_statements = ON; -- statements inside functions
-- SET auto_explain.log_analyze = ON; -- get actual times, too
SELECT * FROM get_paginated_search_results(...);

Note that the default for auto_explain.log_min_duration is -1, which disables logging of plans. So you need to set that to some other value to log any plans at all.

May produce a lot of log output.

Log messages are written to log files with default settings. To get them in the client directly (works at least in psql), also:

SET client_min_messages TO log;

See:

• Getting the query plan for statements inside a stored procedure in PostgreSQL

The current manual on auto_explain.
Depesz wrote a blog article about it when it was introduced with PostgreSQL 8.4.