Re: BUG #19332: Sudden 330x performance degradation of SELECT amid INSERTs

The following bug has been logged on the website:

Bug reference:      19332
Logged by:          Sergey Naumov
Email address:      sknaumov@gmail.com
PostgreSQL version: 18.1
Operating system:   Linux (official docker image)
Description:       

I'm using Django to write to PostgreSQL and implemented data generator to
generate fake data to assess performance of queries.

Everything was good when I used initial data generator that issued only
INSERT statements + SELECT statements to quite small table.

But then I had to extend it with logic to perform SELECT of just generated
low-level entries (TestRun) to create related entries (1-to-1) in another
table:
TestRun.objects.select_related('test').filter(regression__run=run)

Generator starts to insert data with decent speed, something like 50
high-level entries (Run) per second, in a single thread, with Python taking
~85% of one CPU core, and PostgreSQL - remaining 15%. Then suddenly (at
random, doesn't depend on amount of data present in DB), performance
degrades to 1-3 high level entries per second, PostgreSQL takes ~96-99% of
CPU core and Python - remaining 1-4%.

I do not see any changes in queries issued by Django - they are just issued
in a loop with a bit different random data. If I comment out SELECT query to
low-level tables, the issue disappears.

 20%|██████████████████████████▌
| 2010/10000 [00:48<03:06, 42.74it/s]
(0.001) SELECT "tag"."id" FROM "tag" INNER JOIN "report_tags" ON ("tag"."id"
= "report_tags"."tag_id") WHERE "report_tags"."report_id" =
3402823669209384634651384521740769275...
(0.001) INSERT INTO "report_tags" ("report_id", "tag_id") VALUES
(340282366920938463465138452174076927509, 1),
(340282366920938463465138452174076927509, 4), (3402823669209384...
(0.000) INSERT INTO "run" ("report_id", "wall_time", "rtl_repo",
"rtl_commit", "tests_repo", "tests_commit", "scenario", "simulator") VALUES
(34028236692093846346513845217407...
(0.001) INSERT INTO "regression" ("run_id", "config_name") VALUES
(340282366920938463465138452174076927509, NULL) RETURNING "regression"."id";
args=(Decimal('3402823669209384...
(0.030) INSERT INTO "test_run" ("test_id", "regression_id", "status",
"wall_time", "seed") VALUES (16, 2011, 'Pass', 6677, 1), (113, 2011, 'Pass',
9545, 1), (195, 2011, 'Pass...
(0.001) SELECT "test_run"."id", "test_run"."test_id",
"test_run"."regression_id", "test_run"."status", "test_run"."wall_time",
"test_run"."seed", "test"."id", "test"."name" F...
(0.002) INSERT INTO "bench_run" ("test_run_id", "metrics") VALUES (247828,
'{"score": 6.952412837213508}'::jsonb), (247829, '{"execution_time_sec":
3440020.606986488}'::jsonb...
(0.000) INSERT INTO "report" ("id", "ts", "report_path", "table_name",
"type", "source") VALUES (340282366920938463465138452174130059518,
'2025-09-04 08:33:16+00:00'::timesta...
...
(0.000) SELECT "tag"."id" FROM "tag" INNER JOIN "report_tags" ON ("tag"."id"
= "report_tags"."tag_id") WHERE "report_tags"."report_id" =
3402823669209384634651384521741636876...
(0.000) INSERT INTO "report_tags" ("report_id", "tag_id") VALUES
(340282366920938463465138452174163687660, 1),
(340282366920938463465138452174163687660, 5), (3402823669209384...
(0.001) INSERT INTO "run" ("report_id", "wall_time", "rtl_repo",
"rtl_commit", "tests_repo", "tests_commit", "scenario", "simulator") VALUES
(34028236692093846346513845217416...
(0.000) INSERT INTO "regression" ("run_id", "config_name") VALUES
(340282366920938463465138452174163687660, NULL) RETURNING "regression"."id";
args=(Decimal('3402823669209384...
(0.002) INSERT INTO "test_run" ("test_id", "regression_id", "status",
"wall_time", "seed") VALUES (105, 2014, 'Pass', 667, 1), (85, 2014, 'Pass',
2196, 1), (112, 2014, 'Pass'...
(0.001) SELECT "test_run"."id", "test_run"."test_id",
"test_run"."regression_id", "test_run"."status", "test_run"."wall_time",
"test_run"."seed", "test"."id", "test"."name" F...
(0.001) INSERT INTO "bench_run" ("test_run_id", "metrics") VALUES (248094,
'{"score": 1.5836472962691261}'::jsonb), (248095, '{"score":
2.820649074490209}'::jsonb), (248096, ...
(0.000) INSERT INTO "report" ("id", "ts", "report_path", "table_name",
"type", "source") VALUES (340282366920938463465138452174182236095,
'2025-11-14 08:13:19+00:00'::timesta...
(0.000) SELECT "tag"."id" FROM "tag" INNER JOIN "report_tags" ON ("tag"."id"
= "report_tags"."tag_id") WHERE "report_tags"."report_id" =
3402823669209384634651384521741822360...
(0.000) INSERT INTO "report_tags" ("report_id", "tag_id") VALUES
(340282366920938463465138452174182236095, 11),
(340282366920938463465138452174182236095, 2), (340282366920938...
(0.000) INSERT INTO "run" ("report_id", "wall_time", "rtl_repo",
"rtl_commit", "tests_repo", "tests_commit", "scenario", "simulator") VALUES
(34028236692093846346513845217418...
(0.000) INSERT INTO "regression" ("run_id", "config_name") VALUES
(340282366920938463465138452174182236095, NULL) RETURNING "regression"."id";
args=(Decimal('3402823669209384...
(0.002) INSERT INTO "test_run" ("test_id", "regression_id", "status",
"wall_time", "seed") VALUES (217, 2015, 'Pass', 1886, 1), (11, 2015, 'Pass',
4893, 1), (173, 2015, 'Pass...
(0.336) SELECT "test_run"."id", "test_run"."test_id",
"test_run"."regression_id", "test_run"."status", "test_run"."wall_time",
"test_run"."seed", "test"."id", "test"."name" F...
(0.001) INSERT INTO "bench_run" ("test_run_id", "metrics") VALUES (248190,
'{"score": 1.186662265710201}'::jsonb), (248211, '{"score":
6.662192055037965}'::jsonb), (248199, '...
 20%|██████████████████████████▌
| 2015/10000 [00:49<05:44, 23.18it/s]
...
(0.000) SELECT "tag"."id" FROM "tag" INNER JOIN "report_tags" ON ("tag"."id"
= "report_tags"."tag_id") WHERE "report_tags"."report_id" =
3402823669209384634651384521766038035...
(0.000) INSERT INTO "report_tags" ("report_id", "tag_id") VALUES
(340282366920938463465138452176603803511, 2),
(340282366920938463465138452176603803511, 10), (340282366920938...
(0.000) INSERT INTO "run" ("report_id", "wall_time", "rtl_repo",
"rtl_commit", "tests_repo", "tests_commit", "scenario", "simulator") VALUES
(34028236692093846346513845217660...
(0.001) INSERT INTO "regression" ("run_id", "config_name") VALUES
(340282366920938463465138452176603803511, NULL) RETURNING "regression"."id";
args=(Decimal('3402823669209384...
(0.003) INSERT INTO "test_run" ("test_id", "regression_id", "status",
"wall_time", "seed") VALUES (187, 2022, 'Pass', 5664, 1), (242, 2022,
'Pass', 8810, 1), (205, 2022, 'Pas...
(0.329) SELECT "test_run"."id", "test_run"."test_id",
"test_run"."regression_id", "test_run"."status", "test_run"."wall_time",
"test_run"."seed", "test"."id", "test"."name" F...
(0.002) INSERT INTO "bench_run" ("test_run_id", "metrics") VALUES (249104,
'{"score": 13.311529074285398}'::jsonb), (249020, '{"execution_time_sec":
2229116.6002634834}'::jso...
 20%|██████████████████████████▋
| 2022/10000 [00:51<22:14,  5.98it/s]

Note that runtime of SELECT query suddenly increased ~330 times. As I said,
it happens randomly, even almost at the very start of data generation on
empty DB - in the case above it happens momentarily between 2014/2015 Run
entries generation, but in general could happen even at 100th entry.

This behavior is visible on both PostgreSQL versions I've tried - 16.10 and
18.1.