Weird now() time difference with Postgres triggers

Question

In a Postgres 10.10 database, I have a table table1 , and an AFTER INSERT trigger on table1 for table2:

CREATE TABLE table1 (
    id SERIAL PRIMARY KEY,
    -- other cols
    created_at timestamp with time zone NOT NULL,
    updated_at timestamp with time zone NOT NULL
);

CREATE UNIQUE INDEX table1_pkey ON table1(id int4_ops);

CREATE TABLE table2 (
    id SERIAL PRIMARY KEY,
    table1_id integer NOT NULL REFERENCES table1(id) ON UPDATE CASCADE,
    -- other cols (not used in query)
    created_at timestamp with time zone NOT NULL,
    updated_at timestamp with time zone NOT NULL
);

CREATE UNIQUE INDEX table2_pkey ON table2(id int4_ops);

This query is executed on application start:

CREATE OR REPLACE FUNCTION after_insert_table1()
RETURNS trigger AS
$$
BEGIN
    INSERT INTO table2 (table1_id, ..., created_at, updated_at)
    VALUES (NEW.id, ..., 'now', 'now');
RETURN NEW;
END;
$$
LANGUAGE 'plpgsql';

DROP TRIGGER IF EXISTS after_insert_table1 ON "table1";

CREATE TRIGGER after_insert_table1
AFTER INSERT ON "table1"
FOR EACH ROW 
EXECUTE PROCEDURE after_insert_table1();      

I noticed some created_at and updated_at values on table2 are different to table1. In fact, table2 has mostly older values.

Here are 10 sequential entries, which show the difference jumping around a huge amount within a few minutes:

|table1_id|table1_created            |table2_created               |diff            |
|---------|--------------------------|-----------------------------|----------------|
|2000     |2019-11-07 22:29:47.245+00|2019-11-07 19:51:09.727021+00|-02:38:37.517979|
|2001     |2019-11-07 22:30:02.256+00|2019-11-07 13:18:29.45962+00 |-09:11:32.79638 |
|2002     |2019-11-07 22:30:43.021+00|2019-11-07 13:44:12.099577+00|-08:46:30.921423|
|2003     |2019-11-07 22:31:00.794+00|2019-11-07 19:51:09.727021+00|-02:39:51.066979|
|2004     |2019-11-07 22:31:11.315+00|2019-11-07 13:18:29.45962+00 |-09:12:41.85538 |
|2005     |2019-11-07 22:31:27.234+00|2019-11-07 13:44:12.099577+00|-08:47:15.134423|
|2006     |2019-11-07 22:31:47.436+00|2019-11-07 13:18:29.45962+00 |-09:13:17.97638 |
|2007     |2019-11-07 22:33:19.484+00|2019-11-07 17:22:48.129063+00|-05:10:31.354937|
|2008     |2019-11-07 22:33:51.607+00|2019-11-07 19:51:09.727021+00|-02:42:41.879979|
|2009     |2019-11-07 22:34:28.786+00|2019-11-07 13:18:29.45962+00 |-09:15:59.32638 |
|2010     |2019-11-07 22:36:50.242+00|2019-11-07 13:18:29.45962+00 |-09:18:20.78238 |

Sequential entries have similar differences (mostly negative/mostly positive), and similar orders of magnitude (mostly minutes vs mostly hours) within the sequence, though there are exceptions

Here are the top 5 largest positive differences:

|table1_id|table1_created            |table2_created               |diff            |
|---------|--------------------------|-----------------------------|----------------|
|1630     |2019-10-25 21:12:14.971+00|2019-10-26 00:52:09.376+00   |03:39:54.405    |
|950      |2019-09-16 12:36:07.185+00|2019-09-16 14:07:35.504+00   |01:31:28.319    |
|1677     |2019-10-26 22:19:12.087+00|2019-10-26 23:38:34.102+00   |01:19:22.015    |
|58       |2018-12-08 20:11:20.306+00|2018-12-08 21:06:42.246+00   |00:55:21.94     |
|171      |2018-12-17 22:24:57.691+00|2018-12-17 23:16:05.992+00   |00:51:08.301    |

Here are the top 5 largest negative differences:

|table1_id|table1_created            |table2_created               |diff            |
|---------|--------------------------|-----------------------------|----------------|
|1427     |2019-10-15 16:03:43.641+00|2019-10-14 17:59:41.57749+00 |-22:04:02.06351 |
|1426     |2019-10-15 13:26:07.314+00|2019-10-14 18:00:50.930513+00|-19:25:16.383487|
|1424     |2019-10-15 13:13:44.092+00|2019-10-14 18:00:50.930513+00|-19:12:53.161487|
|4416     |2020-01-11 00:15:03.751+00|2020-01-10 08:43:19.668399+00|-15:31:44.082601|
|4420     |2020-01-11 01:58:32.541+00|2020-01-10 11:04:19.288023+00|-14:54:13.252977|

Negative differences outnumber positive differences 10x. The database timezone is UTC.

table2.table1_id is a foreign key, so it should be impossible to insert before insert on table1 completes.

table1.created_at is set by Sequelize, using option timestamps: true on the model.

When a row is inserted into table1, it's done inside a transaction. From the documentation I can find, triggers are executed inside the same transaction, so I can't think of a reason for this.

I can fix the issue by changing my trigger to use NEW.created_at instead of 'now', but I'm curious if anyone has any idea what the cause of this bug is?

Here is the query used to produce the above difference tables:

SELECT
    table1.id AS table1_id,
    table1.created_at AS table1_created,
    table2.created_at AS table2_created,
    (table2.created_at - table1.created_at) AS diff
FROM table1
INNER JOIN table2   ON 
    table2.table1_id = table1.id AND (
        (table2.created_at - table1.created_at) > '2 min' OR 
        (table1.created_at - table2.created_at) > '2 min')
ORDER BY diff;

Answer 1

While 'now' is not a plain string, it is also not a function in this context, but a special date/time input. The manual:

... simply notational shorthands that will be converted to ordinary date/time values when read. (In particular, now and related strings are converted to a specific time value as soon as they are read.)

The body of a PL/pgSQL function is stored as string, each nested SQL command is parsed and prepared when control reaches it the first time per session. The manual:

The PL/pgSQL interpreter parses the function's source text and produces an internal binary instruction tree the first time the function is called (within each session). The instruction tree fully translates the PL/pgSQL statement structure, but individual SQL expressions and SQL commands used in the function are not translated immediately.

As each expression and SQL command is first executed in the function, the PL/pgSQL interpreter parses and analyzes the command to create a prepared statement, using the SPI manager's SPI_prepare function. Subsequent visits to that expression or command reuse the prepared statement.

There is more. Read on. But that's enough for our case:

The first time the trigger is executed per session, 'now' is translated to the current timestamp (the transaction timestamp). While doing more inserts in that same transaction, there won't be any difference to transaction_timestamp() because that is stable within a transaction by design. But every subsequent transaction in the same session will insert the same, constant timestamp in table2, while values for table1 may be anything (not sure what Sequelize does there). If new values in table1 are the then current timestamp, that results in a "negative" diff in your test. (Timestamps in table2 will be older.)

Solution

Situations where you actually want 'now' are few and far between. Typically, you want the function now() (without single quotes!) - which is equivalent to CURRENT_TIMESTAMP (standard SQL) and transaction_timestamp(). Related (recommended reading!):

• Difference between now() and current_timestamp

In your particular case I suggest column defaults instead of doing additional work in triggers. If you set the same default now() in table1 and table2, you also eliminate any nonsense the INSERT to table1 might add. And you never have to even mention these columns in inserts any more:

CREATE TABLE table1 (
    id SERIAL PRIMARY KEY,
    -- other cols
    created_at timestamptz NOT NULL DEFAULT now(),
    updated_at timestamptz NOT NULL DEFAULT now()   -- or leave this one NULL?
);

CREATE TABLE table2 (
    id SERIAL PRIMARY KEY,
    table1_id integer NOT NULL REFERENCES table1(id) ON UPDATE CASCADE,
    -- other cols (not used in query)
    created_at timestamptz NOT NULL DEFAULT now(),  -- not 'now'!
    updated_at timestamptz NOT NULL DEFAULT now()   -- or leave this one NULL?
);

CREATE OR REPLACE FUNCTION after_insert_table1()
  RETURNS trigger LANGUAGE plpgsql AS
$$
BEGIN
   INSERT INTO table2 (table1_id)  -- more columns? but not: created_at, updated_at
   VALUES (NEW.id);                -- more columns?

   RETURN NULL;                     -- can be NULL for AFTER trigger
END
$$;