Dozens of concurrent competing "SELECT ... FOR UPDATE" for the same row

There is a common pattern of executing dozens of concurrent SELECT .. FOR UPDATE for the same record in the internal_ids table:

$ ssh postgres-03-db-gprd.c.gitlab-production.internal 'sudo zcat "/var/log/gitlab/postgresql/@400000005bab42902f8eb49c.s" \
  | grep "LIMIT 1 FOR UPDATE"' \
  | less

Partial output:

2018-09-26_07:22:32.85191 2018-09-26 07:22:32 GMT [21109]: [4-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:36.44665 2018-09-26 07:22:36 GMT [15385]: [3-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:38.69762 2018-09-26 07:22:38 GMT [15389]: [9-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:42.64358 2018-09-26 07:22:42 GMT [14131]: [21-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:42.85165 2018-09-26 07:22:42 GMT [21109]: [7-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:42.85168 2018-09-26 07:22:42 GMT [15385]: [5-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:46.44650 2018-09-26 07:22:46 GMT [15385]: [8-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:46.44655 2018-09-26 07:22:46 GMT [15389]: [11-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:48.69748 2018-09-26 07:22:48 GMT [15389]: [14-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:48.69755 2018-09-26 07:22:48 GMT [14131]: [23-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:22:52.64342 2018-09-26 07:22:52 GMT [14131]: [26-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:36.88784 2018-09-26 07:23:36 GMT [21011]: [4-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:45.72741 2018-09-26 07:23:45 GMT [14111]: [17-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:46.88751 2018-09-26 07:23:46 GMT [21011]: [7-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:46.88770 2018-09-26 07:23:46 GMT [14111]: [19-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:51.88792 2018-09-26 07:23:51 GMT [14111]: [23-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:23:55.72718 2018-09-26 07:23:55 GMT [14111]: [26-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:24:00.72743 2018-09-26 07:24:00 GMT [22529]: [4-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:24:01.63539 2018-09-26 07:24:01 GMT [22529]: [7-1] STATEMENT:  SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:24:01.63540 2018-09-26 07:24:01 GMT [22529]: [8-1] LOG:  duration: 6189.201 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 174802 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.06678 2018-09-26 07:45:43 GMT [25642]: [1-1] LOG:  duration: 3824.841 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.07425 2018-09-26 07:45:43 GMT [32310]: [1-1] LOG:  duration: 2685.276 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.07919 2018-09-26 07:45:43 GMT [28440]: [2-1] LOG:  duration: 2677.428 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.08409 2018-09-26 07:45:43 GMT [31211]: [1-1] LOG:  duration: 2255.766 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.09301 2018-09-26 07:45:43 GMT [31243]: [1-1] LOG:  duration: 2376.719 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.12132 2018-09-26 07:45:43 GMT [31232]: [1-1] LOG:  duration: 2479.965 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.12818 2018-09-26 07:45:43 GMT [32791]: [1-1] LOG:  duration: 2403.425 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.13161 2018-09-26 07:45:43 GMT [32314]: [1-1] LOG:  duration: 2469.556 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.14984 2018-09-26 07:45:43 GMT [32321]: [1-1] LOG:  duration: 2720.291 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.15597 2018-09-26 07:45:43 GMT [31255]: [2-1] LOG:  duration: 2516.386 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.16240 2018-09-26 07:45:43 GMT [31222]: [1-1] LOG:  duration: 2493.655 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.16564 2018-09-26 07:45:43 GMT [31220]: [1-1] LOG:  duration: 2435.237 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE
2018-09-26_07:45:43.18674 2018-09-26 07:45:43 GMT [28403]: [1-1] LOG:  duration: 2528.595 ms  execute <unnamed>: SELECT  "internal_ids".* FROM "internal_ids" WHERE "internal_ids"."id" = 766872 LIMIT 1 FOR UPDATE

For example, for id = 766872:

$ ssh postgres-03-db-gprd.c.gitlab-production.internal 'sudo zcat "/var/log/gitlab/postgresql/@400000005bab42902f8eb49c.s" | grep "LIMIT 1 FOR UPDATE"' | grep 766872 | wc -l
416

SELECT .. FOR UPDATE locks the row, so only one query at a time succeeds, others need to wait until this lock is released. So we have a lot of queries competing to each other for lock on the same row.

This is a sign of some misdesign in the application code.

Edited Jul 21, 2022 by Anthony Fappiano