I would like to build a queue of Articles where each article has a last_seen_at.
User arrives on web page, server ORDERs Articles by last_seen_at ASC, selects the first and returns to the browser. The server updates last_seen_at to be NOW() before returning to the browser.
In this way an Article is moved as last in the queue if it was just delivered.
For this I use FOR UPDATE SKIP LOCKED.
The problem is that under heavy load and concurrent request in a few milliseconds we return the same article to two different users.
The query is
SELECT * INTO rec
FROM articles
ORDER BY last_seen_at ASC NULLS FIRST
LIMIT 1
FOR UPDATE SKIP LOCKED;
UPDATE articles SET last_seen_at = NOW() WHERE id = rec.id;
and the way to reproduce it is by running this script. It simulates 10 different clients that are executing requests with psql. Actual servers have more, so I tried to bring the script to bash, psql and SQL.
The idea is that 10 clients will request from the table of 20 records at almost the same time and each client should receive a unique article to read. There should be no duplicates.
#!/bin/bash
# Define database variables
DB_NAME="article_db"
DB_USER="...fill here..."
DB_HOST="localhost" # Adjust as needed
DB_PORT="5432" # Adjust as needed
# Drop the database
echo "Dropping database: $DB_NAME"
psql -U $DB_USER -c "DROP DATABASE IF EXISTS $DB_NAME;" postgres
echo "Database $DB_NAME has been removed."
# Create the database
echo "Creating database: $DB_NAME"
psql -U $DB_USER -c "CREATE DATABASE $DB_NAME;" postgres
psql -U $DB_USER -c "
CREATE TABLE articles (
id SERIAL PRIMARY KEY,
title VARCHAR(255),
content TEXT,
last_seen_at TIMESTAMPTZ,
created_at TIMESTAMPTZ DEFAULT NOW(),
updated_at TIMESTAMPTZ DEFAULT NOW()
);
INSERT INTO articles (title, content, last_seen_at)
VALUES
('Article 1', 'This is the content of article 1.', NOW()),
('Article 2', 'This is the content of article 2.', NOW()),
('Article 3', 'This is the content of article 3.', NOW()),
('Article 4', 'This is the content of article 4.', NOW()),
('Article 5', 'This is the content of article 5.', NOW()),
('Article 6', 'This is the content of article 6.', NOW()),
('Article 7', 'This is the content of article 7.', NOW()),
('Article 8', 'This is the content of article 8.', NOW()),
('Article 9', 'This is the content of article 9.', NOW()),
('Article 10', 'This is the content of article 10.', NOW()),
('Article 11', 'This is the content of article 11.', NOW()),
('Article 12', 'This is the content of article 12.', NOW()),
('Article 13', 'This is the content of article 13.', NOW()),
('Article 14', 'This is the content of article 14.', NOW()),
('Article 15', 'This is the content of article 15.', NOW()),
('Article 16', 'This is the content of article 16.', NOW()),
('Article 17', 'This is the content of article 17.', NOW()),
('Article 18', 'This is the content of article 18.', NOW()),
('Article 19', 'This is the content of article 19.', NOW()),
('Article 20', 'This is the content of article 20.', NOW());
" $DB_NAME
echo "" > output.txt
echo $(psql --version) >> output.txt
for i in {0..15}; do
echo "Run $i" >> output.txt
x=0.01
y=0.2
sleep_time=$(awk -v min=$x -v max=$y 'BEGIN{srand(); print min+rand()*(max-min)}')
sleep $sleep_time # just so that NOW() returns different values and not close to each other
for n in {0..9}; do
psql -U $DB_USER -c "
DO $$
DECLARE
rec RECORD;
BEGIN
-- Select and lock the row
SELECT * INTO rec
FROM articles
ORDER BY last_seen_at ASC NULLS FIRST
LIMIT 1
FOR UPDATE SKIP LOCKED;
UPDATE articles SET last_seen_at = NOW() WHERE id = rec.id;
-- Return the result after commit
RAISE NOTICE 'ID: %, Title: %, Last: %', rec.id, rec.title, rec.last_seen_at;
END $$;
" $DB_NAME 2>> output.txt &
done
wait
echo "Run $i done"
done
When you run the script what happens is
psql (PostgreSQL) 12.12
Run 0
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:55.191153+03
Run 1
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:55.191153+03
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:55.191153+03
Run 2
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:55.357+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:55.357631+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:55.360134+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:55.366221+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:55.369527+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:55.370643+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:55.379598+03
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:55.38012+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:55.380929+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:55.381026+03
Run 3
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:55.529283+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:55.531521+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:55.53443+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:55.539379+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:55.544098+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.545991+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.889783+03
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:55.552443+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:55.55334+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:55.553517+03
Run 4
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:55.553575+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:55.704585+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:55.706418+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:55.709828+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:55.711804+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:55.714998+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:55.720595+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:55.72123+03
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:55.721629+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:55.721857+03
Run 5
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:55.721988+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:55.871198+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:55.871329+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:55.878223+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:55.873865+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:55.881956+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.890476+03
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:55.890876+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:55.892448+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:55.892666+03
Run 6
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:56.045753+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:56.046676+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:56.053627+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:56.049792+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:56.059395+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:56.062333+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:56.064246+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:56.064377+03
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:56.064599+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:56.06874+03
Run 7
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:56.303647+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:56.304069+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:56.310685+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:56.314391+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:56.314454+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:56.315747+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:56.8011+03
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:56.317306+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:56.317362+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:56.317796+03
Run 8
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:56.317888+03
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:56.546232+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:56.556373+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:56.549424+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:56.559143+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:57.028894+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:56.560479+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:56.561629+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:56.563405+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:56.564448+03
Run 9
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:56.565825+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:56.566152+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:56.783754+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:56.783821+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:56.791792+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:56.792547+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:56.79418+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:57.169286+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:56.801556+03
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:56.801921+03
Run 10
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:56.80328+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:56.803508+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:57.021593+03
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:57.02499+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:57.033416+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:57.036014+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:57.039942+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:57.043892+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:57.044432+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:57.295768+03
Run 11
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:57.046077+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:57.144911+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:57.045291+03
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:57.146934+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:57.151276+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:57.157833+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:57.163592+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:57.167025+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:57.169716+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:57.170998+03
Run 12
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:57.171116+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:57.275763+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:57.282054+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:57.289475+03
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:57.292438+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:57.294022+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:57.2951+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:57.295277+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:57.295999+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:57.29623+03
Run 13
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:57.393965+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:57.395886+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:57.398183+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:57.404+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:57.410518+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:57.419476+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:57.419919+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:57.420215+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:57.421694+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:57.421805+03
Run 14
NOTICE: ID: 18, Title: Article 18, Last: 2024-10-03 23:07:57.522213+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:57.524602+03
NOTICE: ID: 19, Title: Article 19, Last: 2024-10-03 23:07:57.531331+03
NOTICE: ID: 20, Title: Article 20, Last: 2024-10-03 23:07:57.533905+03
NOTICE: ID: 17, Title: Article 17, Last: 2024-10-03 23:07:57.538787+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:57.53948+03
NOTICE: ID: 1, Title: Article 1, Last: 2024-10-03 23:07:57.540906+03
NOTICE: ID: 3, Title: Article 3, Last: 2024-10-03 23:07:57.540984+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:57.541091+03
NOTICE: ID: 5, Title: Article 5, Last: 2024-10-03 23:07:57.541513+03
Run 15
NOTICE: ID: 8, Title: Article 8, Last: 2024-10-03 23:07:57.642186+03
NOTICE: ID: 6, Title: Article 6, Last: 2024-10-03 23:07:57.645733+03
NOTICE: ID: 7, Title: Article 7, Last: 2024-10-03 23:07:57.6465+03
NOTICE: ID: 10, Title: Article 10, Last: 2024-10-03 23:07:57.654263+03
NOTICE: ID: 12, Title: Article 12, Last: 2024-10-03 23:07:57.659976+03
NOTICE: ID: 13, Title: Article 13, Last: 2024-10-03 23:07:57.661056+03
NOTICE: ID: 9, Title: Article 9, Last: 2024-10-03 23:07:57.661537+03
NOTICE: ID: 11, Title: Article 11, Last: 2024-10-03 23:07:57.662008+03
NOTICE: ID: 14, Title: Article 14, Last: 2024-10-03 23:07:57.663009+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:57.663025+03
We do 15 runs and in this 15 runs of requesting 10 articles in parallel, we get:
In run 3, article 16 was returned two times
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.545991+03
NOTICE: ID: 16, Title: Article 16, Last: 2024-10-03 23:07:55.889783+03
In run 7 article 15 was returned two times
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:56.315747+03
NOTICE: ID: 15, Title: Article 15, Last: 2024-10-03 23:07:56.8011+03
In run 8 article 4 was returned two times
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:56.549424+03
NOTICE: ID: 2, Title: Article 2, Last: 2024-10-03 23:07:56.559143+03
NOTICE: ID: 4, Title: Article 4, Last: 2024-10-03 23:07:57.028894+03
and so on.
It happens about 5-10 percent of the cases.
What I fail to understand is why FOR UPDATE SKIP LOCKED is not working the way I would expect it to work – lock a row and if others try to lock it they should move to a different row.
Thanks
2
Answers
In each run you’re deploying the 10 psql instances and pushing them to background, in sequence:
They do not start all at once so there’s a chance any two following workers catch the same row, one worker after another, just because the earlier one
commit
s before the later one even runs theselect
. Theselect..for update
gets you a transaction-level lock:That lock might be already lifted before the later worker arrives.
If at that point the row also just happens to still hold the earliest
last_seen_at
, even after bumping up its timestamp, the worker is forced to pick it:order by
demands it, and it’s no longer locked forfor update skip locked
to skip it.As a result, two workers can get the same row in the same run, but that does not mean they’re processing it at the same time, or that locks are somehow disregarded.
Note how the second row 16 has a mich higher timestamp than all others in its run:
id
last_seen_at
Same story with the other two "violators" – they arrived late enough to catch a row just released by an earlier, quicker commiter from that same run.
Tracking all this just based on the end result is tricky because:
now()
which is the current time as of the start of the transaction, andselect
update
RAISE NOTICE
to write this in the logcommit
at the end, when the lock’s liftednow()
before the 10th.now()
, but beats the 1st one to running theselect
and locking a row.update
may also be different.raise
might be different.NOTICE
messages to theoutput.txt
file might be different.commit
and close the session at different times.Watch it go back and forth in Run 6:
id
last_seen_at
To make sure, you can take snapshots of your whole target table and
pg_locks
each worker sees and also collect somewhat more currentclock_timestamp()
s in addition to the transaction-startingnow()
s for more context:You can also add a
pg_sleep()
in there before taking the lock and another before completion to emulate something closer to true concurrency, so that workers are weighed down a bit, preventing earlier ones from finishing before the final ones even start.I think you are seeing a result of this (from the docs):
So the ordering is applied with the old value of last_seen_at, but then when it goes to lock the first row, a new value has already been committed and it sees that post-commit value but doesn’t reapply the ORDER BY. (The doc description is in terms of blocking, which doesn’t literally apply here as it doesn’t actually block, instead finding the commit has already happened so no blocking was necessary)
But clearly there should be duplicates. You are applying 160 updates to only 20 rows, there has to be duplicates. The duplicates are not happening in the order you want them to, but that isn’t something you can control with the isolation level you are using. If you had actually prevented duplicates, like by setting a seen-already-flag in your UPDATE and including that flag test in your WHERE, then the mechanism would work to prevent duplicates.