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?