Сегодняшняя тема посвящена нелегким взаимоотношениям клиентского приложения и сервера 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: «слишком много золота»", где подробно разобраны примеры возникновения такой беды и способы борьбы с ней.
