Коротко. «Медленно» — сумма времени в браузере, в сервисах RX, в PostgreSQL и в лимитах подов или юнитов; разбор идёт сверху вниз: клиент против сервера, затем OData-метод в Kibana, затем запрос в pg_stat_statements. Сортировать по суммарному времени, а не по среднему: обычная причина — дешёвый запрос, вызванный тысячи раз. Результат — метод, запрос, план и разбивка времени; по ним видно, что чинится своими силами, а что нет.

«Медленно» — самая частая жалоба в эксплуатации Directum RX и самая нерезультативная: она одинаково описывает полминуты на открытии карточки и лишнюю секунду в списке. Время одного действия складывается на пяти участках, и пока оно не разложено по ним, неизвестно даже, на чьей стороне проблема. Разбираем, как превратить жалобу в конкретный метод, конкретный запрос и цифры.

Симптом

Для пользователей: «всё тормозит», «висит при сохранении», «карточка открывается полминуты». По формулировкам не видно, одна это проблема или три.

Для администратора: воспроизвести не получается, у себя всё открывается за секунду. Метрики инфраструктуры зелёные: процессор свободен, память есть, диски не заполнены, в PostgreSQL нет дедлоков.

Почему так

Один клик проходит пять участков: браузер, обратный прокси (nginx или ingress-nginx в Kubernetes), сервисы RX на .NET, PostgreSQL, диск. Часть операций уходит ещё и в RabbitMQ — к фоновому обработчику. Наблюдаемое время — сумма по всей цепочке, и узкое место редко там, где его ищут первым. Типичная картина: администратор идёт в базу, а PostgreSQL отвечает за десятки миллисекунд из нескольких секунд; остальное уходит на сборку модели в сервисе и разбор многомегабайтного JSON в браузере. Бывает и наоборот: запрос быстрый, но выполняется тысячу раз подряд.

Примеры дальше даны для RX в Kubernetes — там больше подвижных частей. Если RX развёрнут на виртуальных машинах под systemd, меняется только шаг 4: вместо лимитов подов смотрят ресурсы ВМ и параметры юнита. Остальные шаги от способа развёртывания не зависят.

Три класса жалоб, которые лечатся по-разному:

Класс Как выглядит Где искать
Медленно всегда и у всех операция долгая на любом рабочем месте объём данных, архитектура операции, SQL
Медленно у части людей у одних секунда, у других полминуты на том же объекте клиентское железо, тонкий клиент и RDP, сеть, права и фильтры
Медленно временами утром нормально, днём нет; после релиза хуже конкуренция за ресурсы, блокировки, фоновые задания, лимиты подов

Плюс размер объекта: операция над карточкой в двадцать строк и в две тысячи — разные операции, даже если кнопка одна.

Диагностика

Шаг 0. Свести жалобу к сценарию

Кто, что нажимает, на каком объекте и какого размера, сколько секунд по секундомеру, всегда или иногда и с какого дня. Половина жалоб на этом шаге распадается на две-три разные, а часть закрывается сразу.

Шаг 1. Разделить время на клиент и сервер

Панель разработчика браузера (вкладка Network) на живом сценарии: сколько прошло до первого байта ответа — TTFB — и сколько заняло остальное, разбор JSON и отрисовка. Упор в клиента, если:

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

Тогда дальше разбираются с объёмом выдачи: сколько колонок и связанных сущностей нужно на экране, можно ли грузить частями.

Шаг 2. Найти метод в логах RX

Сервисы RX пишут длительности операций в свои журналы. Когда логи собраны централизованно — Filebeat или Vector → Logstash → Elasticsearch, — получается индекс, где у каждого вызова есть имя OData-метода, общая длительность и время, проведённое в SQL. В Kibana оттуда берут:

  • p95 по методам, не среднее: жалуются на хвост;
  • топ по суммарному времени — где реально утекает время;
  • долю неуспешных вызовов: таймаут для пользователя выглядит как «зависло»;
  • разрез по версиям сборки — деградация после релиза видна сразу.

Две ловушки. Если открывающая и закрывающая половины спана пишутся отдельными записями, счётчик вызовов задваивается — фильтровать по завершённым. И смотреть длительность вместе с временем в SQL: если доля SQL мала, в базу спускаться незачем, узкое место в коде сервиса. Метрики среды выполнения .NET (GC, потоки, память) снимаются рядом через dotnet-monitor и отвечают на вопрос, не в сборке ли мусора дело.

Шаг 3. Спуститься в SQL

Только если предыдущий шаг показал заметную долю времени в базе. Инструмент — расширение pg_stat_statements, включённое заранее.

-- куда уходит время в сумме: total, а не mean
select calls,
       round(total_exec_time::numeric)            as total_ms,
       round(mean_exec_time::numeric, 2)          as mean_ms,
       round(100 * total_exec_time / sum(total_exec_time) over (), 1) as pct,
       queryid,
       left(regexp_replace(query, '\s+', ' ', 'g'), 120) as query
from pg_stat_statements
order by total_exec_time desc
limit 20;

Колонки total_exec_time и mean_exec_time — это PostgreSQL 13 и новее; на старых версиях total_time и mean_time.

Главная ошибка — сортировать по среднему. Запрос на восемь миллисекунд, вызванный двести тысяч раз, дороже трёхсекундного, вызванного дважды, и обычно он и есть причина: признак поштучной обработки, когда на каждый элемент коллекции идёт отдельный поход в базу. Полезны ещё два среза: по числу вызовов и по blk_read_time — второй выводит на запросы, которые не помещаются в shared_buffers и читают с диска.

Что происходит прямо сейчас:

select pid, state, wait_event_type, wait_event,
       now() - xact_start  as xact_age,
       now() - query_start as query_age,
       application_name,
       left(regexp_replace(query, '\s+', ' ', 'g'), 120) as query
from pg_stat_activity
where backend_type = 'client backend' and state <> 'idle'
order by xact_age desc nulls last
limit 20;

Отдельный признак — транзакция, долго открытая, но большую часть времени в состоянии idle in transaction: PostgreSQL ждёт приложение, которое в цикле обрабатывает элементы. Снаружи выглядит как «медленная база», лечится только в прикладном коде — пакетной обработкой вместо поштучной и короткой транзакцией.

Дальше по таблицам: seq_scan на больших таблицах, доля мёртвых строк и не отстаёт ли autovacuum, неиспользуемые индексы в pg_stat_user_indexes. Найденный запрос раскрывают по queryid и снимают EXPLAIN (ANALYZE, BUFFERS) — на копии, не на продуктиве. Нужный индекс создают через CREATE INDEX CONCURRENTLY и фиксируют в миграциях прикладной части: добавленный руками живёт до первого обновления платформы.

Блокировки как отдельная причина «зависло» — в статье «Дедлоки 40P01 в PostgreSQL под Directum RX».

Шаг 4. Проверить ресурсы

Делается параллельно и регулярно обнуляет предыдущие выводы.

  • Лимит CPU у пода. На узле процессор свободен, а процесс внутри стоит в очереди, упёршись в свою квоту. Видно только по счётчикам принудительных пауз в cgroup самого контейнера:
# растёт nr_throttled — упор в CPU limit, метрики узла при этом зелёные
cat /sys/fs/cgroup/cpu.stat                                   # внутри контейнера
cat /sys/fs/cgroup/system.slice/<юнит>.service/cpu.stat       # для systemd-юнита на ВМ
  • Память впритык — зазор в проценты от limits.memory даёт OOMKill и перезапуски под нагрузкой.
  • Одна реплика фонового обработчика. Тяжёлые операции RX уходят через RabbitMQ воркеру; если он в одном экземпляре, его пропускная способность и есть потолок. Проверяется до оптимизации запросов.
  • Занижённые requests — планировщик Kubernetes переподписывает узлы, а HPA живёт в потолке и перестаёт быть регулятором.
  • Задержки диска под PostgreSQL — если диск отвечает за десятки миллисекунд вместо единиц, медленно будет всё сразу.

Без Kubernetes те же вопросы задаются иначе: вместо лимитов пода — CPUQuota и MemoryMax у systemd-юнита (systemctl show <юнит>) и размер самой ВМ, вместо реплик и HPA — число запущенных экземпляров сервиса. Суть не меняется: сервис может упираться в собственную квоту, когда на узле ресурсы ещё есть.

Шаг 5. Собрать маршрут один раз

Четыре шага выше повторяются на каждой жалобе, поэтому проходить их вручную с секундомером и psql имеет смысл ровно один раз. Дальше это два дашборда на общедоступном стеке: метрики снимает Prometheus с postgres_exporter и sql_exporter, показывает и алертит Grafana с Alertmanager (связку часто называют GAP-стеком), логи и перф-трейсы сервисов собирает ELK.

Дашборд по приложению (Kibana поверх индекса перф-логов): p95 и суммарное время по OData-методам, доля неуспешных вызовов, доля времени в SQL, разрез по версиям сборки. Отвечает на «какой метод» и «с какого релиза».

Дашборд по базе (Grafana поверх метрик экспортёров): топ запросов по суммарному времени, вызовам и вводу-выводу, в двух срезах — за всё время и за последний час, потому что всплеск после релиза виден только во втором; таблицы с seq_scan и долей мёртвых строк; активные запросы с ожиданиями; выбранная таблица со своими индексами. Ключевое — провалиться от запроса к таблице, от таблицы к её индексам, не открывая консоль.

С ними разбор занимает минуты: найти метод в Kibana, посмотреть долю SQL, при заметной — открыть Grafana за тот же час. Бонус: на те же величины вешаются алерты, и деградацию после релиза замечают не пользователи.

Что сделать

Свести замеры в одну таблицу. Один сценарий, объект известного размера, разбивка: клиент, сервер, из них SQL.

Починить, что чинится своими силами. Индекс под найденный запрос, ресурсы и число реплик, свежая статистика и не отстающий autovacuum, разведение фоновых заданий и пиковых часов, урезание выдачи. Архитектурную часть это не снимает.

Довести разбор до пакета фактов — он закрывает вопрос независимо от того, кто будет чинить:

  1. Сценарий: роль, действие, объект и размер.
  2. Замер: всего, на сервере, в SQL, вес ответа; холодный и тёплый прогон отдельно.
  3. Метод, его p95 за период, доля неуспешных вызовов.
  4. Текст запроса, queryid, число вызовов на операцию, план EXPLAIN (ANALYZE, BUFFERS).
  5. Версии RX и PostgreSQL, номер сборки, с какой версии стало хуже.
  6. Что проверено и исключено: ресурсы, блокировки, состояние базы.

Зафиксировать базовую линию. Замер до правок и после — на том же объекте, рабочем месте и версии, иначе «стало лучше» не проверить.

Развести треки. Правки в своём прикладном коде и изменения в продукте вендора идут разными путями и сроками.

Поставить наблюдение на найденное. Метод стал медленнее или выросла доля неуспешных вызовов — это алерт, а не жалоба пользователя. Как не получить при этом шум — в статье «Мониторинг RX: что снимать и какие алерты не ложные».

Чего не делать

  • Принимать «медленно» как постановку задачи. Без сценария и размера объекта меряется не та операция.
  • Крутить shared_buffers и work_mem до того, как найден запрос. Поштучную обработку это не лечит, а понять потом, что помогло, мешает.
  • Оптимизировать по среднему времени запроса. Среднее прячет и хвост, и дешёвые высокочастотные запросы.
  • Считать первый прогон после развёртывания типичным. Холодный кеш даёт цифры, которых в обычный день нет.
  • Сравнивать замеры на разных версиях и рабочих местах. Разница окажется про версию и железо, а не про правку.
  • Считать свободный процессор на узле доказательством, что ресурсов хватает. CPU limit пода виден только изнутри.
  • Добавлять индексы пачкой. Каждый замедляет запись и растит WAL; ставится тот, что подтверждён планом запроса.
  • Делать вывод по одному замеру. Нужны хотя бы три прогона и понимание разброса.