Search code examples
postgresqlloggingprepared-statementplpgsqlsql-execution-plan

How to log queries inside PLPGSQL with inlined parameter values

When a statement in my PLPGSQL function (Postgres 9.6) is being run I can see the query on one line, and then all the parameters on another line. A 2-line logging. Something like:

LOG:  execute <unnamed>: SELECT * FROM table WHERE field1=$1 AND field2=$2 ...    
DETAIL:  parameters: $1 = '-767197682', $2 = '234324' ....

Is it possible to log the entire query in pg_log WITH the parameters already replaced in the query and log it in a SINGLE line?

Because this would make it much easier to copy/paste the query to reproduce it in another terminal, especially if queries have dozens of parameters.

Solution

  • The reason behind this: PL/pgSQL treats SQL statements like prepared statements internally.

    First: With default settings, there is no logging of SQL statements inside PL/pgSQL functions at all. Are you using auto_explain?

    The first couple of invocations in the same session, the SPI manager (Server Programming Interface) generates a fresh execution plan, based on actual parameter values. Any kind of logging should report parameter values inline.

    Postgres keeps track and after a couple of invocations in the current session, if execution plans don't seem sensitive to actual parameter values, it will start reusing a generic, cached plan. Then you should see the generic plan of a prepared statements with $n parameters (like in the question).

    Details in the chapter "Plan Caching" in the manual.

    You can observe the effect with a simple demo. In the same session (not necessarily same transaction):

    CREATE TEMP TABLE tbl AS
SELECT id FROM generate_series(1, 100) id;

PREPARE prep1(int) AS
SELECT min(id) FROM tbl WHERE id > $1;

EXPLAIN EXECUTE prep1(3);  -- 1st execution

    You'll see the actual value:

    Filter: (id > 3)

    EXECUTE prep1(1);  -- several more executions
EXECUTE prep1(2);
EXECUTE prep1(3);
EXECUTE prep1(4);
EXECUTE prep1(5);

EXPLAIN EXECUTE prep1(3);

    Now you'll see a $n parameter:

    Filter: (id > $1)

    So you can get the query with parameter values inlined on the first couple of invocations in the current session.

    Or you can use dynamic SQL with EXECUTE, because, quoting the manual:

    Also, there is no plan caching for commands executed via EXECUTE. Instead, the command is always planned each time the statement is run. Thus the command string can be dynamically created within the function to perform actions on different tables and columns.

    That can actually affect performance, of course.

    Related: