PostgreSQL Antipatterns: Валим «слона» — highload на ровном месте07.10.2024 17:00

Сегодняшняя тема посвящена нелегким взаимоотношениям клиентского приложения и сервера 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

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

© Habrahabr.ru