Thread: now() and statement_timestamp()

According to the documentation. now() should yield the timestamp of the current transaction, while statement_timestamp() should yield the timestamp of the current statement.

In case of Autocommit, both should be identical, in case of a running transaction, they should be different.

Funny enough, psql and executing the same statement from within an application yield different results. I tried a Tcl script and DBeaver.

Statement: SELECT now(), statement_timestamp();

psql: 2021-05-07 13:31:10.135851+02 | 2021-05-07 13:31:10.135851+02

DBeaver: 2021-05-07 13:31:00.633784+02|2021-05-07 13:31:00.633913+02

Tcl script: {now {2021-05-07 13:24:54.659837+02} statement_timestamp {2021-05-07 13:24:54.65985+02}}

So in psql now() and statement_timestamp() are identical when not in a transaction, while in the others the two values vary a little bit, roughly 100 microseconds.

How come the same statements aren't behaving identical. I'm using a current PostgreSQL server on a Linux machine.

-- 
Holger Jakobs, Bergisch Gladbach, Tel. +49-178-9759012

Holger Jakobs <holger@jakobs.com> writes:
> So in psql now() and statement_timestamp() are identical when not in a 
> transaction, while in the others the two values vary a little bit, 
> roughly 100 microseconds.

> How come the same statements aren't behaving identical. I'm using a 
> current PostgreSQL server on a Linux machine.

I'd try turning on log_statement = all to see what's actually
happening.  What seems somewhat likely is that the non-psql
cases are wrapping the command you gave in BEGIN/COMMIT,
or something along that line.

[ thinks for a bit ]  It could also be down to the wire protocol
used.  psql is just sending a simple Query message, but the
other two might well be sending Parse/Bind/Execute.  IIRC the
transaction must be started by Bind, but we may consider
the statement timestamp to be the start of processing Execute.

            regards, tom lane

Am 27.05.21 um 18:43 schrieb Tom Lane:
> Holger Jakobs <holger@jakobs.com> writes:
>> So in psql now() and statement_timestamp() are identical when not in a
>> transaction, while in the others the two values vary a little bit,
>> roughly 100 microseconds.
>> How come the same statements aren't behaving identical. I'm using a
>> current PostgreSQL server on a Linux machine.
> I'd try turning on log_statement = all to see what's actually
> happening.  What seems somewhat likely is that the non-psql
> cases are wrapping the command you gave in BEGIN/COMMIT,
> or something along that line.
>
> [ thinks for a bit ]  It could also be down to the wire protocol
> used.  psql is just sending a simple Query message, but the
> other two might well be sending Parse/Bind/Execute.  IIRC the
> transaction must be started by Bind, but we may consider
> the statement timestamp to be the start of processing Execute.
>
>             regards, tom lane

I turned on logging of statements, and found out that psql uses a simple
query, while the others us an extended query.

According to the documentation a simple query and a series of parse,
bind, execute are approximately equivalent (Note right above "Function
Call" in
https://www.postgresql.org/docs/13/protocol-flow.html#id-1.10.5.7.6)

So actually the "approximately equivalent" is the point here. The series
of parse, bind, execute doesn't call the two funtions now() and
statement_timestamp() at the same stage, so the timestamps vary.

I wasn't aware of this effect. Now it's clear that one can only use a
simple query in order to find out whether a session is within a
transaction or in autocommit mode. Maybe the Note in the documentation
should mention this clearly.


--

Holger Jakobs, Bergisch Gladbach, Tel. +49-178-9759012