Différence d'heure bizarre now() avec les triggers Postgres

Question

Dans une base de données Postgres 10.10, je dispose d'une table table1 et un AFTER INSERT déclencher table1 para 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);

Cette requête est exécutée au démarrage de l'application :

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();      

J'ai remarqué que certains created_at y updated_at valeurs sur table2 sont différentes de table1 . En effet, table2 a surtout des valeurs plus anciennes.

Voici 10 entrées séquentielles, qui montrent que la différence a fait un bond énorme en quelques 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 |

Les entrées séquentielles présentent des différences similaires (majoritairement négatives/plutôt positives) et des ordres de grandeur similaires (majoritairement des minutes par rapport à majoritairement des heures) au sein de la séquence, bien qu'il y ait des exceptions.

Voici les 5 plus grandes différences positives :

|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    |

Voici les 5 plus grandes différences négatives :

|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|

Les différences négatives sont 10 fois plus nombreuses que les différences positives. Le fuseau horaire de la base de données est UTC.

table2.table1_id est une clé étrangère, il devrait donc être impossible d'insérer avant d'insérer sur table1 complète.

table1.created_at est défini par Sequelize, en utilisant l'option timestamps: true sur le modèle.

Lorsqu'une ligne est insérée dans table1 c'est fait à l'intérieur d'une transaction. D'après la documentation que j'ai pu trouver, les déclencheurs sont exécutés à l'intérieur de la même transaction, donc je ne vois pas de raison à cela.

Je peux résoudre le problème en changeant mon déclencheur pour utiliser NEW.created_at au lieu de "now", mais je suis curieux de savoir si quelqu'un a une idée de la cause de ce bogue ?

Voici la requête utilisée pour produire les tableaux de différences ci-dessus :

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

Alors que 'now' n'est pas une simple chaîne de caractères, il ne s'agit pas non plus d'une fonction dans ce contexte, mais d'une fonction entrée spéciale date/heure . Le manuel :

... simplement des raccourcis notatifs qui seront convertis en valeurs de date/heure ordinaires lors de la lecture. (En particulier, now et les chaînes connexes sont converties en une valeur temporelle spécifique dès qu'elles sont lues).

Le corps d'une fonction PL/pgSQL est stocké sous forme de chaîne, chaque commande SQL imbriquée est analysée et préparée lorsque le contrôle l'atteint pour la première fois. par session . Le manuel :

L'interpréteur PL/pgSQL analyse le texte source de la fonction et la fonction produit un arbre d'instructions binaire interne la première fois que la fonction fonction est appelée (dans chaque session). L'arbre d'instructions traduit entièrement structure de l'instruction PL/pgSQL, mais les expressions et les commandes SQL individuelles et les commandes SQL utilisées dans la fonction ne sont pas traduites. immédiatement.

Comme chaque expression et commande SQL est d'abord exécutée dans la fonction, l'interpréteur PL/pgSQL analyse la commande pour créer un fichier de type préparée, en utilisant la fonction d'analyse du gestionnaire SPI SPI_prepare fonction. Les visites ultérieures de cette expression ou commande réutilisent l'instruction préparée.

Il y a plus. Lisez la suite. Mais c'est suffisant pour notre affaire :

La première fois que le déclencheur est exécuté par session , 'now' est converti en l'horodatage actuel (l'horodatage de la transaction). Si vous effectuez d'autres insertions dans la même transaction, il n'y aura pas de différence entre les deux. transaction_timestamp() parce que c'est stable dans une transaction par conception. Mais chaque transaction ultérieure dans la même session insérera le même horodatage constant dans le fichier table2 tandis que les valeurs pour table1 peut être n'importe quoi (je ne sais pas ce que fait Sequelize à cet endroit). Si les nouvelles valeurs dans table1 sont l'horodatage actuel, ce qui entraîne une différence "négative" dans votre test. (Les horodatages en table2 sera plus âgé).

Solution

Les situations où vous voulez vraiment 'now' sont rares. Typiquement, vous voulez la fonction now() (sans guillemets simples !) - ce qui est équivalent à CURRENT_TIMESTAMP (SQL standard) et transaction_timestamp() . Relié (lecture recommandée !) :

• Différence entre now() et current_timestamp

Dans votre cas particulier, je suggère Valeurs par défaut des colonnes au lieu de faire un travail supplémentaire dans les déclencheurs. Si vous définissez la même valeur par défaut now() en table1 y table2 vous éliminez également toute absurdité que le INSERT a table1 pourrait ajouter. Et vous ne devez plus jamais mentionner ces colonnes dans les encarts :

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
$$;