Как исчерпание JDBC-пула превращается в HTTP 502

Контекст задачи

Клиенты начали сообщать об ошибках HTTP 502. Примерно в то же время приложение записало Unexpected error occurred in scheduled task.

На первый взгляд эти события относятся к разным частям системы.

HTTP 502 создаёт gateway, а сообщение о scheduled task появляется внутри Spring-приложения.

Возможным связующим звеном оказался общий ресурс — пул соединений с PostgreSQL.

В этой заметке я разберу, что удалось подтвердить по stack trace и метрикам.

Затем покажу, как scheduled-задачи могут повлиять на HTTP-запросы и что нужно мониторить для доказательства причины.

С чего началась диагностика

В stack trace была важна не верхняя строка, а исходное исключение HikariCP:

HikariPool-1 - Connection is not available,
request timed out after 34198ms
(total=10, active=10, idle=0, waiting=259)

Эта строка полностью описывает состояние пула в момент ошибки.

Поле	Значение	Смысл
total	10	Всего соединений в пуле.
active	10	Все соединения выданы приложению.
idle	0	Свободных соединений нет.
waiting	259	Столько потоков ждут соединение.

waiting=259 не означает, что PostgreSQL открыл 259 сессий.

Это очередь внутри приложения: 259 операций хотят получить одно из десяти JDBC-соединений.

После ожидания около 34 секунд очередная операция получила timeout.

Почему ошибка появилась у scheduled-задачи

Исключение возникло в DomainEventOutboxRelay. Эта задача переносит события из outbox в event store и защищена распределённой блокировкой ShedLock.

Однако stack trace не доказывает, что проблема находится в SQL самого relay.

ShedLock хранит состояние блокировок в PostgreSQL.

Перед запуском задачи он должен получить JDBC-соединение и открыть транзакцию для обновления записи блокировки.

В данном случае соединение получить не удалось. Значит, тело relay() и SQL переноса событий ещё не начали выполняться.

Сообщение Unexpected error occurred in scheduled task оказалось внешней оболочкой. Непосредственная причина — исчерпание HikariPool.

Что показал Prometheus

В приложении уже опубликованы метрики через /actuator/prometheus. Во время проверки пул работал нормально:

HikariPool-1: total=10, active=2, idle=8, pending=0
HikariPool-2: total=3,  active=0, idle=3, pending=0

Первый пул обслуживает основную базу. Второй относится к отдельному datasource курсов и в рассматриваемой ошибке не участвовал.

Текущее состояние не воспроизвело исторический сбой. Счётчик timeout был равен нулю, а очередь ожидающих отсутствовала.

При этом метрики длительности показали аномально долгие scheduled-задачи:

Deal213ExposureProjector.projectDeals = 101.922 s
DealHistoryProjection.update          = 60.884 s
Hikari connection usage max           = 101.9 s

Практически точное совпадение 101.922s и 101.9s указывает, что projectDeals() удерживал JDBC-соединение на протяжении всего запуска.

В другом временном окне DealHistoryProjection.update выполнялся 40.812s, а максимальное удержание соединения составило 46.46s.

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

Откуда берутся долгие транзакции

Deal213ExposureProjector запускается раз в секунду и обрабатывает до 10 000 событий за один batch.

Весь batch выполняется в одной транзакции.

Для каждого события проекция читает текущее состояние сделки и при необходимости делает отдельный upsert или delete.

Один connection удерживается долго, а внутри транзакции выполняется большое количество последовательных запросов.

На событии конца операционного дня проекция дополнительно выбирает сделки с наступившей датой пересчёта.

Затем она обрабатывает их по одной.

DealHistoryProjection использует batch до 1 000 событий и тоже держит транзакцию на всём цикле.

Для первой встречи сделки в batch проекция восстанавливает её предыдущее состояние.

Затем каждое подходящее событие приводит к отдельному upsert в deal_history.

На границе операционного дня выполняется массовый INSERT INTO ... SELECT, переносящий активные сделки на следующую business date.

Обе задачи выполняют необходимую бизнес-работу.

Проблема возникает, когда её объём перестаёт соответствовать частоте запуска и размеру общего пула.

Как возникает очередь из сотен операций

В приложении включены virtual threads. Несколько event-sourcing проекций и relay запускаются с fixedRate = 1 second.

Долгая транзакция сама по себе занимает только одно соединение.

Но одновременно работают другие проекции, HTTP-запросы, Kafka-обработчики и фоновые операции.

Когда все десять соединений заняты, новые секундные запуски не исчезают. Они создают новые попытки получить connection.

Даже запуск, который ShedLock должен пропустить, сначала обращается к таблице блокировок.

Без свободного соединения он тоже попадает в очередь.

Так система переходит от локального замедления к положительной обратной связи:

долгая транзакция
  → меньше свободных соединений
  → растёт время ожидания
  → следующие scheduled-запуски накладываются друг на друга
  → растёт очередь pending
  → начинаются connection timeout

Virtual threads позволяют дёшево создать много ожидающих потоков, но не увеличивают количество соединений с базой.

Узким местом остаётся HikariPool.

Как это связано с HTTP 502

HTTP-запросы используют тот же основной datasource.

Если контроллер или сервис пытается открыть транзакцию при заполненном пуле, он также ждёт свободное соединение.

Gateway не знает, что происходит внутри HikariCP. Он видит только медленный или оборванный upstream.

Возможная цепочка выглядит так:

Hikari active = 10
  → HTTP-запрос ждёт connection
  → приложение не отвечает вовремя
  → gateway завершает upstream-запрос
  → клиент получает 502 или 504

Прямой CannotCreateTransactionException обычно превратился бы в HTTP 500. Код 502 создаёт gateway при timeout, reset, недоступном pod или некорректном ответе upstream.

Поэтому совпадение во времени делает связь вероятной, но для доказательства нужны ingress-логи.

Особенно полезны upstream_status, request_time, upstream_response_time, адрес upstream, имя pod и общий trace или request ID.

Как мониторить пул соединений

Prometheus должен опрашивать каждый pod отдельно.

Scrape через балансируемый Service может каждый раз попадать в другой pod и скрыть проблему одного экземпляра.

Процент заполнения основного пула:

100 * hikaricp_connections_active{pool="HikariPool-1"}
    / hikaricp_connections_max{pool="HikariPool-1"}

Текущая очередь:

hikaricp_connections_pending{pool="HikariPool-1"}

Таймауты за пять минут:

increase(hikaricp_connections_timeout_total{pool="HikariPool-1"}[5m])

Максимальное время удержания connection:

max_over_time(
  hikaricp_connections_usage_seconds_max{pool="HikariPool-1"}[5m]
)

Практический ранний сигнал — заполнение выше 80% в течение минуты.

Наличие pending дольше 30 секунд и любой рост timeout требуют немедленного внимания.

Как мониторить scheduled-задачи

Самые долгие выполнения можно вывести отдельной панелью:

topk(
  10,
  max_over_time(tasks_scheduled_execution_seconds_max[5m])
)

Ошибки scheduled-задач:

sum by (code_namespace, code_function, exception) (
  increase(
    tasks_scheduled_execution_seconds_count{outcome!="SUCCESS"}[5m]
  )
)

Для задач с секундным интервалом выполнение дольше пяти секунд уже требует расследования.

Выполнение дольше 20–30 секунд стоит считать критическим.

Есть важное ограничение: duration-метрика обновится после завершения метода.

Зависшую прямо сейчас транзакцию быстрее обнаружат Hikari pending и PostgreSQL pg_stat_activity.

Что смотреть в PostgreSQL

Во время роста pending, но до connection timeout, нужно снять состояние сессий:

SELECT pid,
       application_name,
       state,
       now() - xact_start  AS transaction_age,
       now() - query_start AS query_age,
       wait_event_type,
       wait_event,
       pg_blocking_pids(pid) AS blockers,
       left(query, 500) AS query
FROM pg_stat_activity
WHERE datname = current_database()
ORDER BY xact_start NULLS LAST, query_start NULLS LAST;

Долгий active покажет медленный запрос. wait_event_type = 'Lock' укажет на блокировку, а pg_blocking_pids — на удерживающую её транзакцию.

Состояние idle in transaction означает, что приложение держит транзакцию открытой, хотя в этот момент не выполняет SQL.

Если соединения нельзя связать с конкретным pod, полезно передавать в PostgreSQL уникальный ApplicationName для каждого экземпляра приложения.

Что ещё нужно подтвердить

Метрики уже подтверждают долгие транзакции и ограничение пула десятью соединениями.

Stack trace подтверждает полное насыщение и очередь из 259 операций.

Пока не подтверждено, какая именно транзакция занимала каждое из десяти соединений в момент клиентских 502.

Для завершения расследования нужно собрать одно общее временное окно:

1. Рост 502 или 504 на ingress.
2. Hikari active = max и рост pending на конкретном pod.
3. Долгая scheduled-задача или HTTP-транзакция.
4. Соответствующий SQL, lock или idle in transaction в PostgreSQL.

Такая корреляция превратит правдоподобную гипотезу в подтверждённую причинную цепочку.