Сервер приложений грузил процессор. Разложили нагрузку по процессам, нашли главного потребителя, назвали его причиной деградации.
Заказчик возразил одной фразой: этот процесс всегда работал столько же.
Один запрос к журналу регистрации показал, что запускается обмен ровно так же, как раньше. Дальше было ещё шесть мест, где расследование могло свернуть не туда, и каждое выглядело убедительно до проверки числом.
Материал про то, как искать. Про то, как починили, здесь не будет. Скажем это сразу, чтобы никто не дочитывал в ожидании развязки: метод довёл до конкретного объекта и до конкретного часового окна, а корневая причина в том разборе так и не была названа. Ниже - способ, которым это делалось, и шесть ловушек, в которые он не дал провалиться.
Стенд: двухузловой кластер серверов 1С на платформе 8.3.20, на узле восемь логических ядер, три базы, порядка 645 сеансов.
Первый диагноз и первая проверка
Разложение нагрузки показало фоновые задания обмена: они давали практически всё потребление на одном из служебных участков. Кандидат идеальный - тяжёлый, заметный, всем понятный.
Возражение заказчика было историческим. К технике оно не относилось вовсе: обмен всегда был высокочастотным, ничего в нём не меняли.
Проверили в лоб - построили ряд числа запусков по суткам за двенадцать суток. В разборе сохранились девять значений:
264, 271, 265, 267, 262, 269, 265, 272, 264 тысячи в сутки
Среднее около 266,6 тысячи, разброс ±1,9 процента, коэффициент вариации около 1,2 процента. Обмен не стал запускаться чаще.
Ровное число запусков снимает одну версию и не снимает другую. Оно закрывает "обмен стал запускаться чаще" и молчит про "каждый запуск стал тяжелее": код мог не меняться, а вырасти могли данные, которые он перебирает. Для второй версии нужен ряд длительностей или процессорного времени заданий, а его в разборе нет. Дальше именно это и предстояло проверить.
Правило, ради которого написан материал
Оно короткое.
Пока вы не построили временной ряд подозреваемого, у вас нет диагноза - у вас есть гипотеза.
Разложение нагрузки отвечает на вопрос "кто сейчас потребляет больше всех". Деградация - это вопрос "что изменилось". Это разные вопросы, и первый инструмент сам по себе на второй не отвечает: он работает вторым шагом, когда уже известен час перелома.
Практически: любой кандидат, прежде чем стать причиной, обязан показать на своём ряду перелом, совпадающий с началом проблемы. Нет перелома - нет причины, каким бы жирным ни был процесс.
Ряд по часам поймал момент
Применили то же самое правило к самой метрике деградации, только с часовым разрешением.
Девять суток ровно, потом скачок примерно в двадцать пять раз в конкретное часовое окно.
Это меняет постановку задачи целиком. Мы больше не ищем "что у нас тяжёлое" - мы ищем "что произошло в этот час". Список кандидатов сжимается с десятков процессов до того, что менялось в узком временном окне.
Практический вывод. Первое, что надо получить при расследовании деградации, - это момент начала с точностью до часа. Всё, что делается до этого, делается вслепую.
Шесть ложных следов подряд
Дальше шесть мест, где расследование могло свернуть не туда. Четыре из них - подозреваемые, отпавшие по числу, два - ошибки чтения самих данных. Привожу все: на каждом легко застрять надолго.
Мгновенный процент против накопленного времени
В той же раскладке по процессам, где менеджер кластера занимал 367 процентов ядра, строкой ниже стояла служба печати с 79 процентами. Почти целое ядро у процесса, которому на сервере приложений делать нечего, - второй подозреваемый напрашивается сам.
Накопленного времени у неё 0,1 процессорного часа за девять суток. Служба просыпалась на разовый всплеск печати, около сорока секунд работы в сутки, и раскладка попала ровно на них. У менеджера кластера за то же время накоплено 299 процессорных часов - это 1,38 ядра в среднем, и мгновенные 367 процентов выше этого фона всего в 2,7 раза.
Мгновенный процент отвечает на вопрос "кто шумит", накопленное время - на вопрос "кто работает". Деградацию не объясняет ни один из них, для неё нужен ряд. Строить его стоит по тем, кто работает.
Среднее вместо перцентилей
Вторая ловушка - в том, как читать длительности.
Средняя длительность вызова - 72 мс. Число здоровое, спорить не с чем.
Распределение при этом такое: медиана - ноль миллисекунд, девяносто пятая процентиль - 109 мс, девяносто девятая - 812 мс, максимум - 5,5 секунды.
Половина вызовов не занимает измеримого времени. Одна сотая часть тормозит на порядки. Среднее между этими двумя мирами не описывает ни один из них, и по нему невозможно заметить, что у вас есть подвисания.
Средняя длительность маскирует подвисания полностью. Работайте с медианой и хвостом; если у вас есть только среднее, вы не увидите самого интересного.
Медленный сосед
Третий кандидат: часть вызовов идёт с соседнего узла кластера, значит сеть добавляет задержку и виноват второй узел.
Разрезали по источнику вызова. Локальные вызовы - 23,2 мс. Сетевые с соседнего узла - 3,8 мс.
Ровно наоборот ожидаемому: удалённые быстрее локальных в шесть раз. Гипотеза не просто не подтвердилась, она развернулась.
Такие развороты - хороший знак. Они означают, что измерение живое. Подгонка данных под заранее выбранную версию сюрпризов не даёт: она возвращает ровно то, чего от неё ждали.
Старый отладочный код
Четвёртый кандидат был лучшим из всех: в журнале нашлось отладочное исключение с текстом в один символ. Кто-то бросил его в боевой базе и забыл, и оно срабатывало примерно шестнадцать тысяч раз в сутки.
Идеальный виновник. Легко объяснить руководству, легко исправить, все довольны.
Первое срабатывание нашлось за восемь месяцев до инцидента, всего 3,85 миллиона раз, в среднем около 668 в час. В двух сутках, которые смотрели по часам, ставка держалась от 524 до 862 в час, и средняя за всё время в этот коридор попадает.
Исключение срабатывало с той же скоростью задолго до проблемы, никакого перелома. Тот же довод, что и с обменом: ровная ставка причиной не становится.
По этой же логике отпал сосед по списку - откаты транзакций. По времени они с проблемой коррелировали хорошо, а внутри оказались пустыми: откатывать было нечего. Корреляция без содержимого причиной не становится.
Самый удобный кандидат проверяется первым и с тем же пристрастием, что и неудобные. Именно на удобных экономят проверку, и именно на них теряют недели.
Большой ввод-вывод без нагрузки на диск
Пятый: процесс показывал около 1 700 операций ввода-вывода в секунду, при том что логический диск - около 11.
Противоречие кажется невозможным, пока не вспомнить, что хранилище отображено в память: процесс честно выполняет операции, до физического диска почти ничего не доходит.
Счётчики процесса и счётчики диска считают разные вещи. Высокий ввод-вывод у процесса не означает нагрузки на дисковую подсистему, и наоборот.
Фильтр журнала, который ловит ноль
Шестой в кандидаты не годится: это способ обмануться на самой проверке.
Настроили сбор технологического журнала с фильтром по подозрительному событию. Файлы получились пустые. Естественный вывод: событие не происходит, версия закрыта.
На самом деле пустые файлы означали, что фильтр составлен неверно. Имя, по которому мы фильтровали, оказалось именем метода, а событие журнал писал под своим. Фильтр был синтаксически безупречен и промахивался мимо цели: каталоги создавались, сбор шёл, ловить было нечего. Рабочий вариант собрался по типу вызова плюс имя интерфейса.
Пустой результат - это не отрицательный результат, пока вы не проверили, что инструмент вообще способен что-то поймать. Простейшая страховка: сначала настройте фильтр так, чтобы он гарантированно ловил хоть что-то, убедитесь, что файлы не пустые, и только потом сужайте.
Как нашли нужный сервис без перезапуска
Отдельный приём, который стоит запомнить.
Процесс-менеджер работал зонтиком над двадцатью восемью сервисами, и снаружи это один процесс: по идентификатору их не развести. Все советы сводятся к одному - выделить менеджер под каждый сервис. Совет верный, цена у него неприятная: перезапускается агент, а вместе с ним ложатся все сеансы на узле. Продуктив ради диагностики никто не отдаст.
Обошли по-другому: сняли дельту размеров файлов по каталогам-кандидатам за интервал. Кто пишет, тот и растёт.
Результат оказался красноречивым. Сеансовые данные росли на 30 гигабайт в сутки, журнал - на 10. Ровно втрое.
При размере блока в 64 мегабайта тридцать гигабайт в сутки - это 480 новых блоков в сутки, около двадцати в час. Служба журнала регистрации из подозреваемых выбыла, и перезапуск агента не понадобился. До объекта метаданных сузил уже часовой ряд по журналу, дельта каталогов ответила на другой вопрос - какой из сервисов менеджера столько пишет.
Приём работает, пока сервисы пишут в разные каталоги. Если пишут в один, он бесполезен.
Ловушки при зачистке сеансов
Когда объект найден, начинается уборка, и тут легко ошибиться сразу в нескольких местах.
Убийство спящих сеансов не лечение. Убили 55 из 69, четырнадцать не убились вовсе. Общее число сеансов при этом сдвинулось с 645 до 649 - то есть за то же время создалось пятьдесят девять новых. Вы боретесь с потоком, а не с запасом. Четырнадцать несбиваемых - это осиротевшие: в списке сеанс есть, процесса за ним нет. Узнаются по двум признакам сразу: пустое имя пользователя и отсутствие реплики.
Счёт по блокам врёт. Один сеанс занимает несколько блоков, а уровень отказоустойчивости раздувает счёт ещё сильнее. Считать сеансы по числу блоков нельзя.
Формат журнала определяется по файлам, в которые пишут сейчас. У нас рекурсивный обход каталога подхватил файлы давно выведенной из эксплуатации базы, и рабочую базу на их основании объявили лежащей в другом формате. Целая версия выросла на мёртвых файлах. Единственный надёжный способ понять, как устроены данные, - смотреть на файлы, в которые пишут прямо сейчас.
И последнее, про цену самого измерения: технологический журнал в полном режиме весил 10,6 гигабайта в сутки. Инструмент диагностики сам стал заметной частью нагрузки - об этом стоит помнить, когда включаете подробный сбор на нагруженной системе.
Чем всё кончилось и чем не кончилось
Метод довёл до объекта метаданных и до часового окна, в котором всё началось.
Корневая причина не названа. Что именно изменилось в тот час - новый регламент, правка, изменение профиля работы - в разборе не установлено.
Пары "до и после" нет. Нагрузка не снята, лечение не описано, замера результата не существует.
Оставили как есть: ценность разбора не в развязке. Шесть проверенных мест, где расследование могло уйти не туда, - это и есть содержание работы.
Метод проверен на одном сервере. Он выглядит переносимым, но подтверждён на одном случае.
Открытый вопрос
Один вопрос остался без ответа. Шесть версий отпали по числам, и стоили эти проверки очень по-разному: ряд по журналу регистрации строится одним запросом, а сбор технологического журнала с последующим разбором - совсем другой порядок трудозатрат. Точного замера времени в разборе нет, а для плейбука цена проверки - первое, что спросят.
Есть ли у кого-то практика заранее ранжировать кандидатов по стоимости проверки, а не по правдоподобию? Порядок, в котором брали их мы, похоже, был случайным.
Другие наши инструменты диагностики 1С:
- Журнал регистрации для нейросети - ошибки в сутки до изменения конфигурации и после, откаты транзакций по дням, штатным методом платформы. С такого ряда стоит начинать, прежде чем кого-то обвинять.
- Анализ нагрузки кластера 1С - процессорное время по пользователям рядом за период и часовой ряд по базе: разовый пик человека виноватым не делает.
- Разбор технологического журнала - сам включает и выключает журнал и показывает, сколько уже собрано: пустой сбор виден до выводов, а логи прошлых включений удаляются одной кнопкой.
- Чек-ап сервера 1С - выделен ли менеджер под каждый сервис и какой уровень отказоустойчивости у кластера: от первого зависит, разводятся ли сервисы по процессам, от второго - двоится ли список сеансов.
- Чек-ап СУБД под 1С - когда сервер приложений ни при чём: настройки SQL Server и PostgreSQL с вердиктом по каждой проверке.
Вступайте в нашу телеграмм-группу Инфостарт