Карта решений: от 504 до SQL.Decision map: from 504 to SQL.
Как по времени и журналам пройти цепочку из двух прокси, Apache, PHP и MariaDB, найти первый зависший запрос и не лечить тайм-аут увеличением тайм-аута.Tracing a timeout through two proxies, Apache, PHP and MariaDB, finding the first blocked request and avoiding the tempting fix of simply waiting longer.
Пользователь периодически получал 504 в административной части сайта, хотя главная страница продолжала отвечать. Я сопоставил сохранённые журналы Nginx и Apache, затем проверил время выполнения запроса в PHP и MariaDB.
Как я искал причину
01 · Зафиксировал запрос
Записал время, адрес и последовательность ответов. Начал с пассивной проверки: нужные записи уже находились в журналах, а состояние выполняющегося запроса можно было посмотреть без вмешательства.
02 · Проверил внешний путь
Начал с пограничного прокси и обычных страниц. Ошибок TLS, DNS и соединения с внутренним Nginx не было, главная открывалась. Запрос доходил до площадки, поэтому внешний участок я исключил.
03 · Нашёл границу ожидания
Во внутреннем Nginx связанные ошибки появлялись ровно через 200 секунд с записью upstream timed out. Это был настроенный предел ожидания, а не доказательство того, что завис сам Nginx.
04 · Сопоставил Nginx и Apache
По времени и адресу нашёл тот же запрос в журнале Apache. Клиент уже получил 504, а процесс Apache/PHP продолжал работать; целиком запрос занял около 65 минут. Nginx просто первым перестал ждать.
05 · Разделил запросы по сессиям
Соседние страницы из того же браузера стояли в очереди, хотя главная и другие сессии отвечали. После отчёта простые запросы закончились почти одновременно. Так обнаружилась блокировка PHP-сессии: она объясняла каскад ошибок, но не начинала его.
06 · Перешёл к MariaDB
Затем проверил список процессов и журнал медленных запросов. Один запрос отчёта вернул около 50 тысяч строк, просмотрев более 5 миллиардов. Здесь уже была причина долгой работы, а не очередное следствие.
07 · Проверил план доступа
EXPLAIN показал повторный проход по первичному ключу: существующий индекс по клиенту оптимизатор не выбирал. Тестовый составной индекс сам по себе план не изменил, а FORCE INDEX переключил его на точечный поиск.
08 · Выбрал постоянное исправление
После этого увеличивать тайм-аут уже не имело смысла. Ручной индекс тоже нельзя было оставлять как скрытую часть схемы. Исправление запроса, миграция и проверка плана должны выйти одним релизом.
A user intermittently received 504 responses in an administrative interface while the public page remained available. I correlated the stored Nginx and Apache logs, then checked the request duration in PHP and MariaDB.
How I narrowed it down
01 · Record the request
I recorded the time, URI and response sequence. The relevant records were already stored in the logs, and the active request could be inspected without changing its state.
02 · Check the external path
I started with the edge proxy and ordinary pages. There were no TLS, DNS or upstream connection errors, and the public page still opened. The request reached the site, so I ruled out the external path.
03 · Locate the wait boundary
Every related error in the internal Nginx appeared after exactly 200 seconds with upstream timed out. This was a configured wait limit, not evidence that Nginx itself had stalled.
04 · Correlate Nginx and Apache
I found the same URI in the Apache log by time. The client had already received a 504 while the Apache/PHP process kept running; the complete request took roughly 65 minutes. Nginx was simply the first component to stop waiting.
05 · Separate user sessions
Neighbouring pages from the same browser queued while the public page and other sessions still responded. The simple requests finished almost together after the report. That exposed the PHP session lock: it explained the cascade, but did not start it.
06 · Move to MariaDB
I then checked the process list and slow log. One report query returned about 50 thousand rows after examining more than 5 billion. This was the source of the long-running work rather than another downstream symptom.
07 · Verify the access plan
EXPLAIN showed repeated primary-key walks while the existing customer index was ignored. A test composite index did not change the plan on its own, but FORCE INDEX switched it to keyed lookups.
08 · Choose the permanent fix
At that point, extending the timeout no longer made sense. A hand-made index could not remain hidden production state either. The query change, migration and plan verification needed to ship in one release.
Карта отделяет место, где истекло ожидание, от места, где продолжалась работа. Движущиеся метки показывают запрос к базе и ответ 504, который возвращается раньше завершения SQL.The map separates the expired wait boundary from the component that remained busy. Moving markers show the database request and the 504 response returning before the SQL query completes.
Сначала — граница тайм-аута
Во внешнем прокси не было ошибок соединения, а внутренний Nginx каждый раз обрывал ожидание через одинаковый промежуток. В журнале стояло upstream timed out; TLS, DNS и передача запроса между площадками к этому моменту уже отработали.
Apache завершал тот же запрос значительно позже. Один отчёт работал около часа, тогда как Nginx ждал ответ 200 секунд. Поэтому 504 возникал на Nginx, но причиной не был сам Nginx: он лишь первым достиг своего предела ожидания.
200сграница ожидания Nginx до первого 504
≈65минвремя первого запроса в Apache и MariaDB
≈50тыс.строк вернул запрос отчёта
>5млрдстрок просмотрено по slow log
Почему тайм-аут получили даже простые запросы
Первый тяжёлый запрос удерживал PHP-сессию. Следующие обращения того же браузера вставали за её блокировкой: проверка состояния, переход на соседнюю страницу и даже запрос значка сайта. Когда долгий отчёт завершился, накопившиеся обращения закончились почти одновременно.
Это объяснило странную картину в журналах. Простые адреса не были медленными сами по себе; они принадлежали одной пользовательской сессии и ждали освобождения блокировки. Публичные страницы и запросы других посетителей могли продолжать работать.
Запрос, который держал цепочку
Отчёт выбирал клиентов и для каждого отдельно искал последний заказ. В упрощённом виде запрос выглядел так:
Форма проблемного запроса
report.sql
SELECT c.*,
(
SELECT o.created_at
FROM orders o
WHERE o.customer_id = c.id
ORDER BY o.id DESC
LIMIT 1
) AS last_order_at
FROM customers c
WHERE c.is_active = 1 OR c.order_count > 0
ORDER BY c.last_name;
На старой версии MariaDB коррелированный подзапрос повторял поиск для десятков тысяч клиентов. Журнал медленных запросов показал полное сканирование и сортировку на диске. Одиночный индекс по customer_id уже существовал, но оптимизатор выбирал первичный ключ и проходил по нему снова и снова.
Индекс без плана — ещё не исправление
Составной индекс (customer_id, id, created_at) подходил для поиска последней записи и мог покрыть подзапрос. Но контрольный EXPLAIN показал, что старая MariaDB не выбирает его автоматически. Подсказка FORCE INDEX меняла план на точечный поиск, однако связывала код с наличием индекса во всех новых и существующих схемах.
Постоянное исправление должно попасть в один релиз: миграция создаёт индекс, код использует проверенный план либо уходит от коррелированного поиска, а тесты проверяют и результат, и план. Временный индекс, созданный при проверке, не оставлялся как незадокументированная часть производственной схемы.
Что карта отбрасывает
Перезапустить всё. Это могло освободить занятый обработчик, но не объясняло причину и не меняло план медленного SQL-запроса.
Увеличить ожидание прокси. Пользователь ждал бы дольше, число занятых обработчиков росло бы, а запрос продолжал просматривать миллиарды строк.
Считать все 504 одним инцидентом. В общих журналах были другие тайм-ауты. К этому разбору относились только записи с совпадающими временем, сессией и цепочкой внутренних запросов.
Оставить ручной DDL. Постоянное изменение схемы относится к миграциям приложения; иначе следующая база или восстановление из шаблона вернёт старое поведение.
Порядок проверки после исправления
открыть тот же отчёт на данных сопоставимого объёма;
сверить EXPLAIN: точечный доступ по составному индексу вместо прохода по первичному ключу;
убедиться, что запрос не появляется в slow log и не удерживает PHP-сессию;
проверить отсутствие новых upstream timed out и рост занятых обработчиков;
закрепить порог времени отчёта и число просмотренных строк в наблюдаемости.
Результат разбора
504 был привязан к конкретной цепочке: долгий коррелированный SQL продолжал работать после 200-секундного тайм-аута Nginx, а блокировка PHP-сессии ставила за ним остальные запросы браузера. Постоянное исправление находится в запросе и миграции; увеличение тайм-аута в него не входит.
Start with the timeout boundary
The edge proxy showed no connection failures, while the internal Nginx ended every wait after the same interval. Its log contained upstream timed out; TLS, DNS and request forwarding between the two proxies had already completed.
Apache finished the same request much later. One report ran for roughly an hour, while Nginx waited 200 seconds. The 504 was emitted by Nginx, but Nginx was not the root cause: it was simply the first component to reach its configured limit.
200sNginx wait boundary before the first 504
≈65minlifetime of the first request in Apache and MariaDB
≈50krows returned by the report query
>5bnrows examined according to the slow log
Why even trivial requests timed out
The first expensive request held the PHP session. Later requests from the same browser queued behind that lock: status checks, neighbouring pages and even the favicon. When the report finally ended, the accumulated requests completed almost together.
This explained the misleading log pattern. The simple URLs were not inherently slow; they belonged to one user session and waited for its lock. Public pages and other visitors could continue to work.
The query that held the chain
The report loaded customers and performed a separate lookup for each customer's latest order. In simplified form, the query looked like this:
Shape of the problematic query
report.sql
SELECT c.*,
(
SELECT o.created_at
FROM orders o
WHERE o.customer_id = c.id
ORDER BY o.id DESC
LIMIT 1
) AS last_order_at
FROM customers c
WHERE c.is_active = 1 OR c.order_count > 0
ORDER BY c.last_name;
On an old MariaDB release, the correlated subquery repeated the lookup for tens of thousands of customers. The slow log showed a full scan and an on-disk sort. A single-column index on customer_id already existed, yet the optimiser chose the primary key and walked it repeatedly.
An index is not a fix until the plan uses it
A composite index on (customer_id, id, created_at) matched the latest-row lookup and could cover the subquery. A control EXPLAIN, however, showed that the old optimiser still ignored it. FORCE INDEX changed the plan to a keyed lookup, but also coupled the query to that index being present in every current and future schema.
The permanent change therefore belongs in one release: a migration creates the index, the query uses a verified plan or removes the correlated lookup, and tests cover both output and plan. A temporary index used during investigation was not left behind as undocumented production state.
What the map rules out
Restart everything. That might release the occupied worker, but it would neither explain the cause nor change the slow query plan.
Increase the proxy timeout. Users would wait longer, occupied workers would accumulate and the query would still examine billions of rows.
Treat every 504 as one incident. Shared logs contained unrelated timeouts. Only events with matching timestamps, sessions and backend request chains belonged to this case.
Keep manual DDL. A durable schema change belongs in application migrations; otherwise the next tenant schema or restored template silently reintroduces the old behaviour.
Verification after the fix
open the same report against a comparable data volume;
check EXPLAIN for keyed access through the composite index rather than a primary-key walk;
confirm that the query no longer enters the slow log or holds the PHP session;
check for new upstream timed out records and rising worker occupancy;
monitor report duration and examined rows as explicit signals.
Investigation result
The 504 was tied to one reproducible chain: a correlated SQL query continued after Nginx reached its 200-second limit, while the PHP session lock queued the browser's remaining requests. The durable fix belongs in the query and its migration; a longer proxy timeout is not part of it.