An image of clocks and universe

According to special relativity, time is relative, meaning it depends on the speed of the observer. 

My PostgreSQL database instance, storing purchase history, would also agree that the timestamps it stores are relative, even though it is sitting still inside a well-cooled Data Center, not moving an inch.

Even more so, my Postgres instance would absurdly agree that the arrow of time can be reversed, and things can be deleted even before they are created. 

Source of truth 

I know you don’t believe me – I didn’t believe my own eyes when I first looked at the data in my tables. Staring back at me was an events table claiming that a shopping cart was purchased (deleted) even before it was created and filled with shopping items.

That cannot be, since for it to be purchased, a shopping cart must be referenced by its ID, the one that comes into existence only after the shopping cart is created in the first place. 

For something that should be a source of truth, this database was pretty insincere. 

Code doesn’t lie 

We decided to take a step back and investigate. There must be a reasonable explanation. We probably have some well-disguised bug.  

We looked at the backend logic first. As soon as the user clicked “Purchase,” a request was sent to the backend to process the purchase. The backend opens a transaction, checks if the shopping cart already exists in the database, and creates it if it doesn’t. Afterward, the backend associates items the user selected with the newly created shopping cart. The last step of the transaction is for the backend to change the state of the shopping cart from CREATED to PURCHASED.  

All these inserts and updates to the shopping_cart table have a FOR EACH ROW trigger defined, which inserts those events into the shopping_cart_event table, together with the timestamp denoting when the trigger was executed.  

These events are periodically emptied and sent to another service for reporting purposes. Only the latest event for each cart is sent, which you might guess was problematic in this case, as the latest event wasn’t the PURCHASED event, but CREATED event. 

Does the SQL lie? 

Judging by the Java code, everything checked out. But maybe the tear in the space-time continuum could somehow have been caused by Postgres, or to be more exact, by our SQL code.  

We looked closely at the SQL procedures that are called upon creation and consequent trigger execution. By examining the procedures, we couldn’t spot anything suspicious. When we analyzed the triggers carefully, however, we noticed that calls which should retrieve the timestamp before events are inserted in the database are different. 

CREATE TRIGGER shooping_cart_insert
    AFTER INSERT ON shopping_cart
    REFERENCING OLD TABLE AS old_table
        NEW TABLE AS new_table
    FOR EACH STATEMENT
EXECUTE PROCEDURE on_shopping_cart_insert();

CREATE OR REPLACE FUNCTION on_shopping_cart_insert() RETURNS TRIGGER AS $$
BEGIN
    INSERT INTO shopping_cart_event (id, event_type, event_timestamp)
    SELECT id, 'CREATED', clock_timestamp()
    FROM new_table;

    RETURN NEW;
END; $$
LANGUAGE plpgsql;
CREATE TRIGGER shooping_cart_update
    AFTER UPDATE ON shopping_cart
    REFERENCING OLD TABLE AS old_table
        NEW TABLE AS new_table
    FOR EACH STATEMENT
EXECUTE PROCEDURE on_shopping_cart_update();

CREATE OR REPLACE FUNCTION on_shopping_cart_update() RETURNS TRIGGER AS $$
BEGIN
    INSERT INTO shopping_cart_event (id, event_type, event_timestamp)
    SELECT id, 'PURCHASED', now()
    FROM new_table
    WHERE purchased = true;

    RETURN NEW;
END; $$
LANGUAGE plpgsql;

The calls are: clock_timestamp() and now(). Hmm, let’s see what the official Postgres documentation tells us.

Oh, did you catch that subtle difference? One actually returns the current timestamp from the system, and the other takes the timestamp from the start of the transaction.  

INSERT trigger is calling clock_timestamp(), which returns the current system time, regardless of when the transaction began. But the UPDATE trigger is calling now(), which will return the time at the start of the current transaction.  

As we know, triggers are executed in the same transaction as the statement which triggered them. This means that even though the UPDATE trigger was executed after the INSERT trigger, its timestamp will be before the INSERT timestamp.  

And once the events are collected and prepared to be sent to the other service, only the latest event, which is INSERT according to the timestamps, will be sent to the service. We, too, were baffled when we realized this was the root cause of all our problems.  

The truth 

In the end, it seems that Postgres didn’t care about special relativity and wasn’t lying to us; it has done exactly what we told it to do. We were lying to ourselves, thinking that clock_timestamp and now() are working in the same fashion.  

And to be clear, the exact situation in our case was a bit more complex, and no web shops were involved, but carts were more illustrative than actual events.

In summary, always be careful and think twice before fetching the current timestamp. If you need the current timestamp to be the same throughout the transaction, use now(). But if you need the exact timestamp when a command was executed within the transaction, use clock_timestamp(). We’ve learned a valuable lesson here, and we hope that you do too.