CPU 132 %: один недостающий индекс и 800 миллионов строк каждые пять минут

В воскресенье вечером в шапке биллинга появился красный треугольник. При наведении он показывал: CPU 132.3%. Абоненты этого не почувствовали: интернет работал, платежи проходили, очереди обработки были пусты. Но индикатор не загорается просто так, и мы пошли выяснять, что съедает процессор рабочего сервера.

Что на самом деле значат 132 %

Индикатор считает не загрузку процессора в привычном смысле, а очередь: средняя нагрузка сервера за последнюю минуту (load average), делённая на число ядер. У рабочего сервера их шесть. 100 % — это когда в каждый момент ровно шесть процессов работают или ждут процессора. 132 % — около восьми: часть задач стоит в очереди. Порог тревоги — 90 %.

Первый взгляд на сервер дал понятную картину. Нагрузка за минуту уже снижалась, но фон держался около 4 — примерно 70 % от шести ядер, совсем рядом с порогом. Больше всего процессора брала база данных, следом — фоновый обработчик RADIUS-сессий. И ещё одна деталь: за несколько минут до тревоги мы выкладывали обновление, а перезапуск веб-сервера на минуту добавляет нагрузку, пока он заново загружается.

Можно было остановиться на «это перезапуск, само пройдёт». Но перезапуск лишь толкнул нагрузку через порог. Вопрос был в другом: почему обычный воскресный вечер сам по себе держит сервер на 70 %.

Как искали без специальных инструментов

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

• Счётчики по таблицам. Для каждой таблицы база помнит, сколько раз её читали целиком (полный просмотр) и сколько строк при этом перебрала. Сами числа накоплены за долгое время и мало что говорят. Зато разница между двумя замерами с интервалом в 20 секунд показывает, что происходит прямо сейчас.
• Список активных запросов. Если снимать его несколько раз в секунду и считать, какой текст запроса попадается чаще всего, получается грубый, но честный профиль нагрузки.

Первый замер попал в затишье, второй всё показал. Таблица RADIUS-сессий — история всех подключений абонентов, 1,6 миллиона строк — за 20 секунд была прочитана целиком 185 раз. Это 101 миллион строк, около пяти миллионов в секунду. Остальные таблицы рядом с этим были незаметны.

flowchart LR
  a1["Индикатор<br/>«CPU 132%»"] --> a2["Кто грузит?<br/>база данных"]
  a2 --> a3["Какая таблица?<br/>разница счётчиков за 20 с"]
  a3 --> a4["Какой запрос?<br/>снимки активных запросов"]
  a4 --> a5["Откуда?<br/>поиск по коду"]
  a5 --> a6["План запроса<br/>и индекс"]

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

Кто спрашивал так часто

Запрос нашёлся в служебной задаче, которая следит за тем, к какому оборудованию доступа (NAS) привязан абонент. Новый абонент сначала попадает на временный NAS-заглушку, а после первого настоящего подключения биллинг переносит его на тот NAS, через который он реально выходит в сеть, и выдаёт адрес из нужного пула. Чтобы перенос срабатывал быстро после ручных правок, отдельная задача раз в пять минут берёт абонентов, у которых недавно менялась RADIUS-учётка, и для каждого проверяет последнюю сессию.

Учётка обновляется почти при каждом подключении, поэтому под условие «менялась за 15 минут» вечером попадали около 3 800 абонентов. Задача брала первые 500 — свой предел — и для каждого читала таблицу сессий целиком.

500 запросов × 1,6 миллиона строк = около 800 миллионов строк за один запуск, и так каждые пять минут. База почти всё время была занята задачей, которая в итоге почти всегда отвечала «всё уже правильно».

flowchart TD
  t1["Раз в 5 минут"] --> t2["Абоненты с недавно<br/>изменённой учёткой<br/>(около 3 800, берём 500)"]
  t2 --> t3["Для каждого: последняя<br/>сессия абонента"]
  t3 --> t4{"Есть индекс<br/>по абоненту?"}
  t4 -- "был только по открытым<br/>сессиям" --> t5["Чтение всей таблицы:<br/>1,6 млн строк"]
  t4 -- "теперь есть" --> t6["Одна строка из индекса:<br/>0,1 мс"]

Почему этого не заметили раньше? Индекс по абоненту у таблицы был, но только по открытым сессиям: их около 3 800, и для учёта трафика больше и не нужно. Пока история сессий была небольшой, полный просмотр стоил копейки. Таблица росла месяцами — вместе с ней незаметно росла и цена каждого вызова. Ни одна строка кода при этом не менялась.

Лечение: один индекс за две секунды

Мы добавили индекс по абоненту и времени обновления сессии — ровно в том порядке, в котором запрос сортирует строки. Теперь база находит последнюю сессию абонента сразу, не перебирая таблицу.

Индекс создавали в режиме, который не блокирует запись в таблицу: RADIUS-сессии обновляются непрерывно, и остановить их даже на секунду нельзя. На таблице в 311 МБ это заняло две секунды. Тот же индекс записан в обновление структуры базы, так что на новых установках и на демо-стенде он появится сам.

Полных просмотров таблицы сессий стало примерно в 150 раз меньше. Оставшиеся — от соседней задачи, которая раз в минуту ищет свежие сессии всех абонентов; она читает таблицу один раз за запуск, и это мы тоже доведём до индекса.

Что мы из этого вынесли

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

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

Разница счётчиков — быстрый способ найти виновника. Два замера с интервалом 20 секунд и список активных запросов: без дополнительных расширений и без перезапуска базы. От тревоги до исправления прошло меньше получаса.

Индекс лечит симптом, логику задачи — отдельно. С индексом каждый вызов почти бесплатен, но 500 проверок каждые пять минут по-прежнему избыточны: большинство абонентов давно привязаны к правильному NAS. Пересмотреть отбор — следующий шаг.

Как это работает в СмИТ Биллинге

Индикатор нагрузки — часть шапки биллинга. Раз в минуту страница спрашивает у сервера три числа: нагрузку на процессор (средняя нагрузка, делённая на число ядер), занятую память и занятое место на диске. Если любое из них выше 90 %, в шапке появляется красный треугольник, а подсказка называет, что именно перегружено. Те же три числа всегда видны мелким шрифтом в подвале страницы — по ним удобно смотреть, как нагрузка меняется в течение дня.

Подробные показатели — объём базы, подключения, кеш, фоновые задачи — собраны в разделе «Настройки системы → Скорость». Там же настраиваются параметры, от которых зависит производительность сервера.