user590028 user590028 - 6 months ago 13
SQL Question

PostgreSQL statement caching interfering with expected results

We've written a PL/pgSQL function to record timestamps to an audit table.
PostgresSQL statement caching however is not recalculating

now()
on each
invocation, which is causing stale (meaning old) timestamps to be recorded in our audit table.

We're running Postgres 9.2. According to the docs
http://www.postgresql.org/docs/9.2/static/plpgsql-implementation.html#PLPGSQL-PLAN-CACHING (scroll to bottom of their article), the recommendation is to rely on calls to
now()
.

This function does not work as expected:

CREATE OR REPLACE FUNCTION save(txd integer) RETURNS void AS $$
BEGIN
INSERT INTO audit (id, mtime) VALUES (txd,now());
END;$$


With a table defined as:

CREATE TABLE audit (
id integer NOT NULL,
mtime timestamp without time zone NOT NULL,
CONSTRAINT audit_pkey PRIMARY KEY (id)
)


A simple python 2.7 script using
psycopg2
can be used to demonstrate the problem:

import datetime, psycopg2, time
def tm():
# connect and clear contents
con = psycopg2.connect('dbname=postgres user=postgres')
cur = con.cursor()
cur.execute('TRUNCATE audit')

# Add a record, wait a second, add another
cur.execute('SELECT save(1)')
time.sleep(1.0)
cur.execute('SELECT save(2)')

# List the contents
cur.execute('SELECT * FROM audit')
for row in cur.fetchall():
print("modified %s" % row[1])
cur.close()
con.close()


If you run this script, you will notice that the two instances of modified times will report the exact same value, even though we inserted a small 1-second sleep between INSERTs

>>> tm()
modified 2016-05-10 11:05:21.766005
modified 2016-05-10 11:05:21.766005


Note: We have even tried the example provided by postgres in the linked
article. There is no difference in output using their example:

CREATE OR REPLACE FUNCTION save(txd integer) RETURNS void AS $$
DECLARE
curtime timestamp;
BEGIN
curtime = 'now';
INSERT INTO audit (id, mtime) VALUES (txd,curtime);
END;$$


Could someone set us straight on where we're going wrong here?

Answer

now() returns the timestamp at transaction begin; this will cause all clock readings within the transaction to yield the same values (which is often what you want).

If you want the actual time at sub-trransaction level you'll need clock_timestamp() http://www.postgresql.org/docs/9.5/static/functions-datetime.html