25

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;
0

2 Answers 2

22

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.

3
  • 4
    As @Erwin points out below, you should set the auto_explain.log_nested_statements = ON as well.
    – rfusca
    Commented Aug 29, 2012 at 15:22
  • @rfusca you'll essentially run everything double where is the proof for that? Some experiments I did do not show this behavior.
    – Sebastian
    Commented Jan 15, 2019 at 10:24
  • Realize this is referencing a 7 year old database at this point. It likely doesn't work like that anymore then if you're not seeing the same results.
    – rfusca
    Commented Jan 16, 2019 at 14:47
25

I addition to rfusca's advice: SQL statements inside PL/pgSQL functions (or any function that is not inlined) are considered nested statements. Set the parameter auto_explain.log_nested_statements to include those.

You don't need CREATE EXTENSION like for most extensions. Just LOAD it dynamically into your session.
You must be superuser for this:

LOAD 'auto_explain';
SET auto_explain.log_nested_statements = ON; -- statements inside functions
SET auto_explain.log_min_duration = 1;       -- exclude very fast queries taking < 1 ms
-- SET auto_explain.log_analyze = ON;        -- log execution times, too? (expensive!)

SELECT * FROM my_function(...);

Set auto_explain.log_min_duration to some other value than -1 to log any plans at all. The manual:

auto_explain.log_min_duration is the minimum statement execution time, in milliseconds, that will cause the statement's plan to be logged. Setting this to 0 logs all plans. -1 (the default) disables logging of plans. For example, if you set it to 250ms then all statements that run 250ms or longer will be logged. Only superusers can change this setting.

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):

SET client_min_messages TO log;

See:

Depesz wrote a blog article about it when it was introduced with PostgreSQL 8.4.

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.