Paged query against timestamp populated by trigger missing items

Question

We're having a strange problem with a PostgreSQL 9.2 database that I've been racking my brain trying to figure out.

First some background. We have a "tombstone" table that is populated using a trigger when a row is deleted from a particular table. The trigger does this:

INSERT INTO tombstone (id, delete_timestamp) 
VALUES (OLD.id, statement_timestamp() AT TIME ZONE 'UTC');

There is a background service that runs every 30 seconds and checks for items in the tombstone table. The query used by the background service is like this:

SELECT
    id, 
    delete_timestamp
FROM
    tombstone
WHERE 
    delete_timestamp > @sinceUTC
    OR
    (delete_timestamp = @sinceUTC AND id > @id)
ORDER BY
    delete_timestamp asc, id asc
LIMIT @count;

This query is constructed with two goals: to find new tombstone entries since the last time it was run, and to page through the items if there is a large number. The last timestamp and ID are recorded after each execution of the query to use as the inputs to the next execution of the query. If no results are returned, the last timestamp and ID are not updated.

The problem we are having is this: every once in a while, the background service misses a large number of items in the tombstone table. Recently we had a 10-minute time span where the background service did not pick up any new tombstone items even though there were more than 200 created during that time. The logs for the service show it querying every 30 seconds during that time but finding no items.

I've come up with one scenario that could account for missing items, but it should only miss a few in a very small time window. The scenario I've identified is as follows:

D1 |st1....................|
D2       |st2......|
R                  |.......|

Consider two delete transactions, D1 and D2. D1 starts first. D2 starts and completes while D1 is still in progress. Since the trigger uses statement_timestamp, it will record a the start of D1 as ST1 and the start of D2 as ST2.

If a read (R) starts in the time between the commit of D2 and the commit of D1, then it will see D2 but not D1. It will record the "last timestamp" as ST2, but this is actually after ST1. So the next time the query executes, it will start at a time after ST1 and therefore will miss D1.

As I said, I can see this causing a few occasional misses, but not 10 minutes worth. Also, the missed items were in multiple transactions, not a single large transaction, so the likelihood of this accounting for what we are seeing seems even smaller.

Any ideas on what could cause this issue?

Answer 1

I think you found the main culprit alright. There are more ways to miss rows with this setup. Consider D3 I added to your time diagram:

D1 |st1....................|
D2       |st2......|
D3          |st3......|
R                |.......|
                   ^ -- read query starts here

Transaction D3 starts after D2, but since it's not committed when your read query in transaction R starts, it is invisible as well. It will be included in the next page, but it may still be confusing that it's missing this time. That's how the default transaction isolation level Read Committed is defined. You seem to be aware of it, but for the general public:

When a transaction uses this isolation level, a SELECT query (without a FOR UPDATE/SHARE clause) sees only data committed before the query began; it never sees either uncommitted data or changes committed during query execution by concurrent transactions. In effect, a SELECT query sees a snapshot of the database as of the instant the query begins to run.

There is more. Read the manual.

---

With concurrent access to the DB, various conflicts might stall a DELETE query - which will patiently wait until it can get an exclusive lock on the rows to delete. 10 minutes of missed rows would indicate a (possibly unrelated) problem, I agree with your suspicion. Transactions that remain "idle in transaction" are prime suspects. To diagnose, look for log long running statements or transactions. Some pointers:

• Set log_min_duration_statement in postgresql.conf.
• Some basics on Logging Difficult Queries in the Postgres Wiki.
• The statistics view pg_stat_activity. Related:
  • Postgres - estimate end time for a long update
• check_postgres provides helpful tools.
• Related blog.

Database design

You seem to be using data type timestamp. Your INSERT with statement_timestamp() AT TIME ZONE 'UTC' should work correctly for your purpose, but you shouldn't rely on INSERT statements to get this right. Rather move the logic to the table itself. Use the data type timestamptz (timestamp with time zone) for tombstone.delete_timestamp to begin with. This rules out any discrepancies with time zones or DST (daylight saving time). Details:

• Ignoring timezones altogether in Rails and PostgreSQL

Also don't rely on the INSERT statement to provide the correct time. Put the logic in the column default (or even in a trigger BEFORE INSERT to overwrite any provided timestamp).

CREATE TABLE tombstone (
  id int NOT NULL PRIMARY KEY  -- assuming PK
, delete_timestamp timestamptz DEFAULT statement_timestamp()
);

Since timestamps are not visible until the transaction is committed anyway, the cheaper current_timestamp (transaction timestamp) may be just as useful as statement_timestamp() - depends on unknown details.

The simpler INSERT statement in the trigger to go with the above:

INSERT INTO tombstone (id) VALUES (OLD.id);

Query

Your current SELECT query can be faster comparing row values, which is also index-backed in Postgres:

SELECT id, delete_timestamp
FROM   tombstone
WHERE  (delete_timestamp, id) > (@sinceUTC, @id)
ORDER  BY delete_timestamp, id
LIMIT  @count;

Details:

• Optimize query with OFFSET on large table

Secure alternative

All this aside, timestamps are just not completely reliable for queuing or paging in a multi-user environment. If you need it to be completely reliable, consider a different approach: Lock unread rows before retrieving and mark them as read. The new FOR UPDATE SKIP LOCKED in Postgres 9.5 may prove useful for this:

• Postgres UPDATE ... LIMIT 1

Or, if the reading is done by a single user, you don't need locks. Just mark rows you have read. A partial index for unmarked rows makes reading fast.

Upgrade to current Postgres

Postgres 9.2 is getting old. Upgrading to the current version might help for various reasons.