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;