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 раз меньше. Оставшиеся — от соседней задачи, которая раз в минуту ищет свежие сессии всех абонентов; она читает таблицу один раз за запуск, и это мы тоже доведём до индекса.

Что видно теперь: панель «Нагрузка сервера»

В тот вечер виновника искали руками: снимали счётчики дважды с интервалом, выписывали активные запросы. Это работает, когда человек уже у сервера, но ничего не говорит о том, что было час назад, — индикатор показывает только текущую минуту. Поэтому на следующий день мы сделали из этого ручного разбора инструмент.

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

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

Отдельный блок — «Читались целиком чаще всего» за выбранный период. Большая таблица, которая там держится постоянно, почти всегда означает запрос без нужного индекса.

И он сразу пригодился. Таблица сессий из топа ушла, а на первое место вышла таблица учёток абонентов: в ней всего 6,5 тысячи строк, но база перебирает её целиком сотни раз в минуту — 3,7 миллиона строк. Это пока не нагрузка, а копейки: таблица маленькая. Но именно так выглядела и история с сессиями, пока таблица не выросла. Разберём её следующей.

Тексты запросов в панели обезличены — все значения заменены знаком «?», поэтому данных абонентов там нет. Видят панель только суперпользователь и администраторы.

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

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

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

Нужна история, а не только текущая минута. Индикатор сказал «сейчас плохо», но не «с какого времени» и «что было до». Минутные замеры за трое суток отвечают на оба вопроса без ручного разбора.

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

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

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

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

Клик по треугольнику — или по строке нагрузки в подвале — открывает панель «Нагрузка сервера»: графики за выбранный период, пики выше порога с тем, что было в самую тяжёлую минуту, таблицы, которые читались целиком, и запросы к базе, которые выполняются прямо сейчас.

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