07.10.2024 13:51
Kilor 6 11000 Источник

Сегодняшняя тема посвящена нелегким взаимоотношениям клиентского приложения и сервера PostgreSQL: как на ровном месте, неудачной архитектурой приложения, можно обеспечить себе хронические проблемы производительности.

Рассмотрим классические ситуации, когда разработчики начинают жаловаться на производительность БД - а виновата-то и не она!

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

Комментарии (6)


  1. rinace
    07.10.2024 14:06
    #27388368

    в логе сервера 

    Обычно лог продуктивной СУБД это мегабайты . Как искать проблемную строку?

    И самое главное .

    Query Text: SELECT 1

    Это ведь искусственный пример. В реальности так не бывает.

    Как искать проблемный запрос ?


    1. Kilor Автор
      07.10.2024 14:06
      #27388382

      Мы разработали для себя и предлагаем другим вот такую штуку - можно потрогать демку.


  1. SamDark
    07.10.2024 14:06
    #27389670
    +2

    Про ORM не согласен. Да, запросы вида SELECT id; SELECT * WHERE id IN (1,2,3) — они не самые оптимальные, но, как правило, далеко не критично влияют на производительность. При этом такое поведение ORM даёт то, что можно выбирать ID из одной базы, а данные из другой:

    1. Иногда это сильно упрощает жизнь при разрезании монолита на несколько частей по-честному (то есть без общей базы). У меня такое было.

    2. Это позволяет выбирать ID из одной базы, а данные из другой. Например, ID из ElasticSearch, а данные из основной базы. У меня сейчас так работает на нескольких проектах.


    1. Kilor Автор
      07.10.2024 14:06
      #27389696
      +1

      Кто понимает, зачем использует ORM, его сильные и слабые стороны, - молодец.

      Увы, приходилось видеть генерированные запросы с тысячами ID-параметров, гуляющих в рамках одной базы между сервером и клиентом. Впрочем, и для разных баз можно обойтись без проброса через клиента - с помощью FDW, например.


    1. rinace
      07.10.2024 14:06
      #27390014

      ORM не согласен. Да, запросы вида SELECT id; SELECT * WHERE id IN (1,2,3) — они не самые оптимальные, но, как правило, далеко не критично влияют на производительность

      А если IN ( 1,2,3.... 1000, 1001)?

      Я такие запросы и удивление разрабов - "ну почему ваш postgres так медленно работает ? " - видел.


      1. SamDark
        07.10.2024 14:06
        #27391078

        Так уже хуже, конечно.