Why does auto_explain only log nested statements on first call of PL/pgSQL function?

Question

On my Postgres server I am using the auto_explain module with log_nested_statements on to log other function calls in PL/pgSQL functions.

594 session_preload_libraries = 'auto_explain'
595
596 auto_explain.log_min_duration = 0
597 auto_explain.log_nested_statements = true
598 auto_explain.sample_rate = 1.0

I have a toy PL/pgSQL function baz(count int):

Schema              | public
Name                | baz
Result data type    | text
Argument data types | count integer
Type                | normal
Volatility          | volatile
Parallel            | unsafe
Owner               | aerust
Security            | invoker
Access privileges   |
Language            | plpgsql
Source code         |                                      +
                    | DECLARE                              +
                    |     i int := 0;                      +
                    |     result text := '';               +
                    | BEGIN                                +
                    |                                      +
                    |     IF (count < 1) THEN              +
                    |     RETURN result;                   +
                    |     END IF;                          +
                    |                                      +
                    |     LOOP                             +
                    |     EXIT WHEN i = count;             +
                    |     i := i + 1;                      +
                    |     result := result || ' ' || foo();+
                    |     END LOOP;                        +
                    |                                      +
                    |     RETURN result;                   +
                    | END;                                 +
                    |
Description         |

Which calls a SQL function foo():

Schema              | public
Name                | foo
Result data type    | text
Argument data types |
Type                | normal
Volatility          | immutable
Parallel            | unsafe
Owner               | aerust
Security            | invoker
Access privileges   |
Language            | sql
Source code         |  SELECT 'foo ' || bar()
Description         |

On the first call of the function baz(1) in a database connection I see each nested statement logged as part of the plan:

2019-03-19 15:25:05.765 PDT [37616] LOG:  statement: select baz(1);
2019-03-19 15:25:05.768 PDT [37616] LOG:  duration: 0.002 ms  plan:
    Query Text:  SELECT 'bar'
    Result  (cost=0.00..0.01 rows=1 width=32)
2019-03-19 15:25:05.768 PDT [37616] CONTEXT:  SQL function "bar" statement 1
    SQL function "foo" during startup
    SQL statement "SELECT result || ' ' || foo()"
    PL/pgSQL function foo(integer) line 14 at assignment
2019-03-19 15:25:05.768 PDT [37616] LOG:  duration: 0.001 ms  plan:
    Query Text:  SELECT 'foo ' || bar()
    Result  (cost=0.00..0.01 rows=1 width=32)
2019-03-19 15:25:05.768 PDT [37616] CONTEXT:  SQL function "foo" statement 1
    SQL statement "SELECT result || ' ' || foo()"
    PL/pgSQL function foo(integer) line 14 at assignment
2019-03-19 15:25:05.768 PDT [37616] LOG:  duration: 0.952 ms  plan:
    Query Text: select baz(1);
    Result  (cost=0.00..0.26 rows=1 width=32)

But, when I call the function again on the same connection I do not see the nested statements in the logs:

2019-03-19 15:29:06.608 PDT [37616] LOG:  statement: select baz(1);
2019-03-19 15:29:06.608 PDT [37616] LOG:  duration: 0.046 ms  plan:
    Query Text: select baz(1);
    Result  (cost=0.00..0.26 rows=1 width=32)

Why is this? And how do I get the nested statements to be logged on subsequent calls of the function during the same database connection?

score 4 · Accepted Answer · answered Mar 19 '19 at 23:17

You could do this to get the statements logged every time:

ALTER FUNCTION foo() STABLE;

But then your performance would suffer a little.

To unravel the mystery:

Execution plans of SQL statements called inside PL/pgSQL functions are cached for the lifetime of the database session, so they are only parsed once, when the function is first executed.
IMMUTABLE expressions are evaluated when an SQL statement is parsed and are turned into constants.

The statements that are only logged the first time are statements that are only evaluated when the SQL statements in baz are parsed.

Why does auto_explain only log nested statements on first call of PL/pgSQL function?

1 Answers1