Сегодняшняя тема посвящена нелегким взаимоотношениям клиентского приложения и сервера PostgreSQL: как на ровном месте, неудачной архитектурой приложения, можно обеспечить себе хронические проблемы производительности.
Рассмотрим классические ситуации, когда разработчики начинают жаловаться на производительность БД - а виновата-то и не она!
Начнем с самого простого - с организации примитивной тестовой программы для Node.js, которая умеет подключаться к серверу PostgreSQL (модуль pg) в несколько соединений, включать "параноидальный" режим анализа запросов с помощью модуля auto_explain и этот самый запрос выполнять:
const pg = require('pg');
const {Client} = pg;
const connInfo = {
user : 'postgres'
, password : 'postgres'
, host : 'localhost'
, port : 5432
, database : 'postgres'
};
const jobs = 1; // количество одновременных соединений
(async () => {
const clients = await Promise.all(
Array(jobs).fill().map(async () => {
// подключаемся к базе
const client = new Client(connInfo);
await client.connect();
// активируем auto_explain
await client.query(`
LOAD 'auto_explain';
SET auto_explain.log_analyze = 'on';
SET auto_explain.log_buffers = 'on';
SET auto_explain.log_min_duration = 0;
SET auto_explain.log_nested_statements = 'on';
SET auto_explain.log_timing = 'on';
SET auto_explain.log_triggers = 'on';
`);
return Promise.resolve(client);
})
);
// одновременно выполняем на каждом из них необходимые запросы
const rows = await Promise.all(
clients.map(async client => {
const res = await client.query('SELECT 1');
return Promise.resolve(res.rows);
})
);
// закрываем все соединения
await clients.forEach(client => client.end());
})();Если все было сделано правильно, то в логе сервера мы увидим примерно такую запись:
2024-10-07 13:37:13.173 MSK [29048] LOG: duration: 0.015 ms plan:
Query Text: SELECT 1
Result (cost=0.00..0.01 rows=1 width=4) (actual time=0.004..0.007 rows=1 loops=1)С помощью визуализации на explain.tensor.ru мы сразу видим, что время непосредственного выполнения запроса сервером - 0.007ms, а примерный объем возвращенных данных - 4 байта (actual rows=1 x width=4):
Напомню, что вставлять план для анализа можно сразу целым блоком...
... а сервис сам его разделит на запрос и план:
В отличие от actual time, duration - время полного выполнения запроса, включая передачу результата клиенту - получилось уже 0.015ms, то есть сама передача ответа "стоила" нам 0.008ms.
Размер resultset
TL;DR: Минимизируйте объем результата, получаемого от БД.
Типы столбцов
Давайте теперь нагрузим сервер какой-то относительно реальной работой - пусть он отдает нам все числа от 1 до миллиона:
SELECT i FROM generate_series(1, 1e6) iВ таком варианте столбец i будет иметь тип numeric, возвращаемый из generate_series, и занимать 32 байта для каждой записи, поскольку передается блоками цифр, общий размер resultset при этом составит немалые 31MB:
numeric... LOG: duration: 737.459 ms plan:
Query Text: SELECT i FROM generate_series(1, 1e6) i
Function Scan on generate_series i (cost=0.00..10.00 rows=1000 width=32) (actual time=225.135..362.437 rows=1000000 loops=1)
Buffers: temp read=2073 written=2073Средняя задержка передачи при этом составила 360ms.
Поскольку мы точно знаем, что первый миллион "умещается" в integer, давайте попробуем возвращать значение именно этого типа:
SELECT i::integer FROM generate_series(1, 1e6) iПрикладной результат ровно тот же ("числа до миллиона"), но из-за фиксированной "ширины" integer в 4 байта, общий возвращаемый сервером объем трафика сокращается в 8 раз, а среднее время передачи снижается до 312ms.
Обратите внимание, что в наших тестах это "локальный", а не сетевой трафик. А если сервер БД стоит где-то "далеко" от клиентского приложения, то множество одновременно "ломанувшихся" на сервер клиентов легко "завалят слона" если не по производительности CPU, то по пропускной способности сети, которая может закончиться гораздо раньше.
Давайте прикинем: numeric-запрос "на миллион" в среднем выполнялся сервером 360ms и еще 360ms длилась передача 31MB результата - то есть мы передали [минимум] 244Mb за 0.72s = ~340Mbps.
Логика далеко от данных
Обычно проблемы такого рода возникают либо от тотального непонимания принципов работы с БД, вроде рассматривавшихся в статье "PostgreSQL Antipatterns: навигация по реестру" вариантов "сначала все получу, потом отсортирую":
cur.execute("SELECT * FROM events;")
rows = cur.fetchall();
rows.sort(key=lambda row: row.ts, reverse=True);
limit = 26
print(rows[offset:offset+limit]);Второй вариант - неудачный ORM, используемый на проекте (или неумеющий его грамотно применять разработчик), который вместо вложенного запроса, оперирующего с данными в пределах сервера БД, "вытаскивает" их всегда на сторону клиентского приложения:
ids <- SELECT id FROM doc WHERE owner = 'Alice';
SELECT sum(qty) FROM doc_item WHERE doc_id IN (${ids.join(',')});
vs.
SELECT sum(qty) FROM doc_item WHERE doc_id IN (
SELECT id FROM doc WHERE owner = 'Alice'
);Синхронность выполнения
TL;DR: Принудительно десинхронизируйте выполнение запросов.
Получается, что всего 3 таких клиента (или 300, которые одновременно будут спрашивать всего-то по 10K integer) легко "положат" и гигабитную сеть. Если в реальных условиях у вас не 300 клиентов, так и записи у вас не по 32 байта, а побольше...
Давайте теперь перенесем нагрузку на сторону сервера, и считать будем сумму всех тех чисел до миллиона:
SELECT sum(i) FROM generate_series(1, 1e6) i... LOG: duration: 507.984 ms plan:
Query Text: SELECT sum(i) FROM generate_series(1, 1e6) i
Aggregate (cost=12.50..12.51 rows=1 width=32) (actual time=507.969..507.970 rows=1 loops=1)
Buffers: temp read=2073 written=2073
-> Function Scan on generate_series i (cost=0.00..10.00 rows=1000 width=32) (actual time=223.259..348.167 rows=1000000 loops=1)
Buffers: temp read=2073 written=2073Мы получаем в ответ теперь всего одну запись, поэтому тип столбца нам не столь важен, задержки на передачу все равно минимальны.
Если провести несколько последовательных тестов, мы получим среднее время выполнения порядка 508ms.
А теперь давайте запустим наш тест на 16 подключениях одновременно (jobs = 16 в нашей программе) при выделенных серверу 4 ядрах CPU:
2024-10-07 15:30:19.565 MSK [28936] LOG: duration: 1767.403 ms plan: ...
2024-10-07 15:30:19.642 MSK [20360] LOG: duration: 1859.703 ms plan: ...
2024-10-07 15:30:19.678 MSK [41036] LOG: duration: 1947.635 ms plan: ...
2024-10-07 15:30:19.686 MSK [12032] LOG: duration: 1938.924 ms plan: ...
2024-10-07 15:30:19.686 MSK [18300] LOG: duration: 1939.397 ms plan: ...
2024-10-07 15:30:19.699 MSK [40900] LOG: duration: 1917.059 ms plan: ...
2024-10-07 15:30:19.711 MSK [12728] LOG: duration: 1965.203 ms plan: ...
2024-10-07 15:30:19.759 MSK [38540] LOG: duration: 2027.971 ms plan: ...
2024-10-07 15:30:19.777 MSK [40276] LOG: duration: 1992.891 ms plan: ...
2024-10-07 15:30:19.796 MSK [18644] LOG: duration: 2064.386 ms plan: ...
2024-10-07 15:30:19.825 MSK [22932] LOG: duration: 2043.790 ms plan: ...
2024-10-07 15:30:19.850 MSK [41732] LOG: duration: 2087.980 ms plan: ...
2024-10-07 15:30:19.855 MSK [38024] LOG: duration: 2093.014 ms plan: ...
2024-10-07 15:30:19.872 MSK [32480] LOG: duration: 2141.214 ms plan: ...
2024-10-07 15:30:19.872 MSK [32544] LOG: duration: 2109.777 ms plan: ...
2024-10-07 15:30:19.880 MSK [38348] LOG: duration: 2118.152 ms plan: ...Легко заметить, что с каждым новым запросом, встающим на выполнение, итоговое время для него становится все больше и больше, дойдя до 4-кратного замедления относительно "однопоточной" версии. Это вполне объяснимо тем фактом, что мы одномоментно захотели получить "семь шапок" - выполнить 16 CPU-активных процессов на 4 ядра.
Чтобы не получить такого эффекта, достаточно ввести некую рандомизированную задержку при старте обработки события (запуска пула процессов, получения сигнала, ...), хотя бы даже так:
client.query('SELECT pg_sleep(random() * 4)'); // разбежка до 4 сек
const res = await client.query('SELECT sum(i) FROM generate_series(1, 1e6) i');2024-10-07 16:12:23.203 MSK [23228] LOG: duration: 579.658 ms plan: ...
2024-10-07 16:12:23.374 MSK [30036] LOG: duration: 572.722 ms plan: ...
2024-10-07 16:12:23.483 MSK [33332] LOG: duration: 617.321 ms plan: ...
2024-10-07 16:12:23.521 MSK [35592] LOG: duration: 630.321 ms plan: ...
2024-10-07 16:12:23.827 MSK [38368] LOG: duration: 611.399 ms plan: ...
2024-10-07 16:12:23.883 MSK [10440] LOG: duration: 582.978 ms plan: ...
2024-10-07 16:12:23.929 MSK [35468] LOG: duration: 562.947 ms plan: ...
2024-10-07 16:12:23.959 MSK [30792] LOG: duration: 552.995 ms plan: ...
2024-10-07 16:12:24.398 MSK [19448] LOG: duration: 539.472 ms plan: ...
2024-10-07 16:12:24.575 MSK [21936] LOG: duration: 525.542 ms plan: ...
2024-10-07 16:12:24.607 MSK [40748] LOG: duration: 533.656 ms plan: ...
2024-10-07 16:12:25.479 MSK [32416] LOG: duration: 538.157 ms plan: ...
2024-10-07 16:12:25.566 MSK [11204] LOG: duration: 531.848 ms plan: ...
2024-10-07 16:12:25.690 MSK [27716] LOG: duration: 561.769 ms plan: ...
2024-10-07 16:12:26.128 MSK [34596] LOG: duration: 550.124 ms plan: ...
2024-10-07 16:12:26.165 MSK [29528] LOG: duration: 533.798 ms plan: ...Понятно, что в реальных условиях "ждать" лучше не с помощью соединения до БД, а в коде приложения.
Перегрузка клиента
TL;DR: Ресурсы могут кончаться не только на сервере, но и на клиенте - а видно все равно в логе сервера.
Поменяем в последнем "параллельном" тесте с "разбежкой" запрос на исходный, который возвращал "весь миллион":
client.query('SELECT pg_sleep(random() * 4)'); // разбежка до 4 сек
const res = await client.query('SELECT i FROM generate_series(1, 1e6) i');Мы же помним, что запрос выполнялся у нас что-то порядка 500-700ms, и...
2024-10-07 16:31:38.570 MSK [13836] LOG: duration: 855.744 ms plan:
actual time=..409.293 ...
2024-10-07 16:31:39.201 MSK [19448] LOG: duration: 1383.853 ms plan:
actual time=..413.909 ...
2024-10-07 16:31:40.321 MSK [38264] LOG: duration: 1515.595 ms plan:
actual time=..435.973 ...
2024-10-07 16:31:40.366 MSK [41512] LOG: duration: 1560.709 ms plan:
actual time=..447.622 ...
2024-10-07 16:31:42.032 MSK [24476] LOG: duration: 2600.114 ms plan:
actual time=..579.276 ...
2024-10-07 16:31:42.124 MSK [41900] LOG: duration: 2692.630 ms plan:
actual time=..549.336 ...
2024-10-07 16:31:44.588 MSK [39248] LOG: duration: 3350.654 ms plan:
actual time=..773.811 ...
2024-10-07 16:31:44.878 MSK [40748] LOG: duration: 3617.941 ms plan:
actual time=..893.361 ...
2024-10-07 16:31:45.411 MSK [35176] LOG: duration: 4359.566 ms plan:
actual time=..801.552 ...
2024-10-07 16:31:45.505 MSK [12416] LOG: duration: 4453.663 ms plan:
actual time=..863.834 ...
2024-10-07 16:31:45.693 MSK [23112] LOG: duration: 4455.087 ms plan:
actual time=..863.590 ...
2024-10-07 16:31:46.128 MSK [36044] LOG: duration: 4890.108 ms plan:
actual time=..947.209 ...
2024-10-07 16:31:49.449 MSK [38768] LOG: duration: 6888.474 ms plan:
actual time=..696.957 ...
2024-10-07 16:31:49.541 MSK [35268] LOG: duration: 6980.557 ms plan:
actual time=..667.114 ...
2024-10-07 16:31:49.632 MSK [18764] LOG: duration: 7071.027 ms plan:
actual time=..698.535 ...
2024-10-07 16:31:49.720 MSK [28356] LOG: duration: 7135.465 ms plan:
actual time=..690.181 ...Наш клиентский код на JavaScript хоть и асинхронен, все равно ограничен ресурсами одного потока выполнения. Поэтому даже когда сервер уже все сделал за 700ms, он вынужден тратить в 10 раз больше времени на ожидание, пока клиент "переварит" предыдущие полученные ответы и заберет до конца этот - и в его логе мы можем это увидеть.
Размеры тела запроса и параметров
Повторяться отдельно в этот раз не буду, каждый желающий может легко воспроизвести эффект от "гигантских" запросов и параметров к ним - просто сошлюсь на прошлую статью "PostgreSQL Antipatterns: «слишком много золота»", где подробно разобраны примеры возникновения такой беды и способы борьбы с ней.
rinace
Обычно лог продуктивной СУБД это мегабайты . Как искать проблемную строку?
И самое главное .
Это ведь искусственный пример. В реальности так не бывает.
Как искать проблемный запрос ?
Kilor Автор
Мы разработали для себя и предлагаем другим вот такую штуку - можно потрогать демку.