How can I write `PREPARE` statements in PostgreSQL?

Question

I use a database tool (Elixir Ecto) that uses prepared statements for most PostgreSQL queries. I want to see how and when he does it.

I found the correct Postgres configuration file, postgresql.conf , by executing the SHOW config_file; in psql . I edited it to enable

 log_statement = 'all' 

as suggested by Dogbert here .

According to PostgreSQL 9.6 docs, this parameter should call PREPARE statements.

After rebooting PostgreSQL, I can tail -f its log file (the one specified with the value -r when executing the postgres executable), and I 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 matches the request (although it is executed using the binary protocol, I think), for example

 EXECUTE ecto_728('%foo%'); 

However, I do not see the original PREPARE that ecto_728 created .

I tried to reset and recreate the database. Subsequently, the same query is executed as ecto_578 , so it seems that the original prepared statement was deleted from the database and a new one was created.

But when I look at the PostgreSQL log for ecto_578 , I see that it is running, not being created.

How can I see PREPARE statements in a PostgreSQL log?

Answer 1

As you mentioned, your queries are prepared using the extended query protocol, which differs from the PREPARE statement. And according to the docs for log_statement :

For clients using the advanced request protocol, logging occurs when a Receive message is received.

(This means 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 the advanced request protocol, session duration Parse, Bind, and Execute are logged independently

Including both of these parameters together will give you two entries in the log for execution (one of log_statement when the message is received, and the other of log_min_duration_statement after completion).

Answer 2

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

Firstly, I managed to see three separate actions in the log: a parse to create a prepared statement, bind to specify parameters for it, and execute so that the database actually carries its results and results. This is described in the PostgreSQL docs for the "advanced 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 created during the launch of some automated tests. In subsequent runs, I saw the same request with a different name - for example, ecto_1573 . It was not dropping the database or even restarting the PostgreSQL process. Documents say that

If successfully created, the named entity of the finished statement lasts until the end of the current session, unless it is explicitly destroyed.

So, these statements need to be recreated in every session, and probably my test suite has a new session for each run.