How can I log `PREPARE` statements in PostgreSQL?

Question

I'm using a database tool (Elixir's Ecto) which uses prepared statements for most PostgreSQL queries. I want to see exactly how and when it does that.

I found the correct Postgres config file, postgresql.conf, by running SHOW config_file; in psql. I edited it to include

log_statement = 'all'

as Dogbert suggested here.

According to the PostgreSQL 9.6 docs, this setting should cause PREPARE statements to be logged.

After restarting PostgreSQL, I can tail -f its log file (the one specified by the -r flag when running the postgres executable) and I do see entries like this:

LOG:  execute ecto_728: SELECT i0."id", i0."store_id", i0."title", i0."description"
  FROM "items" AS i0 WHERE (i0."description" LIKE $1)
DETAIL:  parameters: $1 = '%foo%'

This corresponds to a query (albeit done over binary protocol, I think) like

EXECUTE ecto_728('%foo%');

However, I don't see the original PREPARE that created ecto_728.

I tried dropping and recreating the database. Afterwards, the same query is executed as ecto_578, so it seems that the original prepared statement was dropped with the database and a new one was created.

But when I search the PostgreSQL log for ecto_578, I only see it being executed, not created.

How can I see PREPARE statements in the PostgreSQL log?

Why, out of interest? You're seeing the query text at execution time anyway. — Craig Ringer, Dec 09 '16 at 04:14
@CraigRinger No practical reason. :) I just want to understand the tools I'm using. Eg I'm curious if Ecto does the `PREPARE` when my code is compiled or when I boot my application. I suppose I can try compiling when PostgreSQL isn't running and see what happens. — Nathan Long, Dec 09 '16 at 14:19
Turns out that it does the `PREPARE` right before executing the query for the first time in a given session, because ["a named prepared-statement object lasts till the end of the current session"](https://www.postgresql.org/docs/9.6/static/protocol-flow.html#PROTOCOL-FLOW-EXT-QUERY) so there's really no other way to do it. — Nathan Long, Dec 09 '16 at 20:42

Nick Barnes · Accepted Answer · 2016-12-08T20:50:02.520

As you mentioned, your queries are being prepared via the extended query protocol, which is distinct from a PREPARE statement. And according to the docs for log_statement:

For clients using extended query protocol, logging occurs when an Execute message is received

(Which is to say that logging does not occur when a Parse or Bind message is received.)

However, if you set log_min_duration_statement = 0, then:

For clients using extended query protocol, durations of the Parse, Bind, and Execute steps are logged independently

Enabling both of these settings together will give you two log entries per Execute (one from log_statement when the message is received, and another from log_min_duration_statement once execution is complete).

Nice! See my answer for what I found out, if you're curious. Cheers! — Nathan Long, Dec 09 '16 at 20:36

score 1 · Answer 2 · edited May 23 '17 at 12:17

Nick's answer was correct; I'm just answering to add what I learned by trying it.

First, I was able to see three separate actions in the log: a parse to create the prepared statement, a bind to give the parameters for it, and an execute to have the database actually carry it out and return results. This is described in the PostgreSQL docs for the "extended query protocol".

LOG:  duration: 0.170 ms  parse ecto_918: SELECT i0."id", i0."store_id",
   i0."title", i0."description"
  FROM "items" AS i0 WHERE (i0."description" LIKE $1)
LOG:  duration: 0.094 ms  bind ecto_918: SELECT i0."id", i0."store_id",
  i0."title", i0."description"
  FROM "items" AS i0 WHERE (i0."description" LIKE $1)
DETAIL:  parameters: $1 = '%priceless%'
LOG:  execute ecto_918: SELECT i0."id", i0."store_id", 
  i0."title", i0."description"
  FROM "items" AS i0 WHERE (i0."description" LIKE $1)
DETAIL:  parameters: $1 = '%priceless%'

This output was generated during a run of some automated tests. On subsequent runs, I saw the same query with a different name - eg, ecto_1573. This was without dropping the database or even restarting the PostgreSQL process. The docs say that

If successfully created, a named prepared-statement object lasts till the end of the current session, unless explicitly destroyed.

So these statements have to be recreated on each session, and probably my test suite has a new session on each run.

How can I log `PREPARE` statements in PostgreSQL?

2 Answers2