Mystical postgresql query timing issue

Question

I'm trying to log events in postgresql using this function:

CREATE OR REPLACE PROCEDURE admin.log_event(
    IN log_message character varying,
    IN param1 character varying DEFAULT NULL::character varying,
    IN param2 character varying DEFAULT NULL::character varying)
LANGUAGE 'plpgsql'
AS $BODY$
  declare ts timestamp;
  begin
    ts = now();
    insert into admin.event_log (dt, msg, param_1, param_2) values (ts, log_message, param1, param2);
  end;
$BODY$;

The usage pattern is:

• log event
• run query for several minutes
• log event
• ...

What I'm seeing in the event_log table is that all 24 entries for a query batch that lasted 35 minutes record the same timestamp, which is the time the batch was started.

Obviously I don't understand something about postgresql insert statements as I was expecting each row to reflect the timestamp for it's insertion into the request_log table.

Answer 1

As you can read in the now() documentation:

These SQL-standard functions all return values based on the start time of the current transaction:

So if you do an insert as part of a single transaction, they'll all get the same timestamp.

The library you use to connect to Postgres can have surprising transaction patterns. For example, Python's psycopg2 implicitly starts a transaction whenever you run an insert statement.