Сервер 1С грузит процессор: как найти причину и не обвинить не тот процесс

Загрузка ЦП на сервере 1С подбирается к ста процентам, в диспетчере задач сверху rmngr или rphost, и первая мысль - назначить виноватым того, кто сверху. Но диспетчер отвечает лишь на вопрос, кто занят больше всех в эту секунду. Если ещё недавно сервер справлялся, причину ищут по другому вопросу: что изменилось и в какой час.

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

rmngr или rphost сверху: что это за процессы

rphost - рабочий процесс кластера, в нём выполняется серверный код сеансов и фоновых заданий. Если сверху он, дальше вопрос про сеансы: кто съел процессорное время и в какие часы. Процессорное время по пользователям за период и часовой ряд по базе собирает анализ нагрузки кластера.

rmngr - менеджер кластера, внутри него работают сервисы: сервис сеансовых данных, служба журнала регистрации и другие, в разобранном случае их было 28. Для диспетчера задач это один процесс, и какой сервис в нём занят, снаружи не видно. Поэтому при rmngr наверху сначала ищут сервис, потом того, кто его нагружает.

Диспетчер задач считает процент от всех логических процессоров, скрипты часто от одного ядра: 367 процентов ядра у rmngr в разборе на восьми логических процессорах давали около 46 процентов машины.

Сначала час перелома, потом подозреваемые

На вопрос “что изменилось” отвечает только ряд по времени. Первым ищется час, когда началось, и подозреваемый становится причиной, только если на его ряду в тот же час виден излом.

В разборе первым заподозрили обмен: практически всю нагрузку на сеансовые данные давали его фоновые задания. Заказчик возразил, что обмен всегда запускался так часто, и суточный ряд запусков фоновых заданий это подтвердил: 264, 271, 265, 267, 262, 269, 265, 272 и 264 тысячи, в среднем 266,6 тысячи при разбросе ±1,9 процента.

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

Главное дал часовой ряд событий журнала регистрации, суженный до одного объекта метаданных: девять суток без изменений, затем за одно часовое окно рост примерно в 25 раз. Дальше искали только то, что менялось в этот час. По составу событий объекта это были одни изменения, без добавлений и удалений, все транзакции зафиксированы: записи штатно переписывались, а зацикленный повтор после ошибки оставил бы след в отменах.

Правило работает для деградации, когда было нормально и стало плохо. Если сервер перегружен всегда, изломов нет ни у кого, и правильный вопрос как раз “кто больше всех”. А процесс без излома снимается как причина перемены, но из нагрузки не уходит: на сервере у потолка и небольшая добавка поверх старого фона даёт деградацию.

Порядок проверок: что сколько стоит

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

Проверка	Что нужно	Что меняет на сервере
Время ЦП процессов	права администратора, минута	ничего
Ряд по журналу регистрации	запрос к выгрузке или чтение журнала	ничего
Перцентили и разрез по источнику	уже собранные длительности	ничего
Дельта каталогов кластера	доступ к каталогу, несколько часов	ничего
Технологический журнал	права на каталог настройки, место на диске	включает запись, её ведёт тот же процесс
Менеджер под каждый сервис	окно, когда можно оборвать сеансы	перезапуск агента, обрыв всех сеансов узла

Дешёвые проверки: на сервере ничего не включаем

Время ЦП процесса рядом с мгновенным процентом

Мгновенный процент говорит, кто занят в момент снимка, накопленное процессорное время - кто работал с самого запуска. В диспетчере задач его выводят отдельным столбцом на вкладке подробностей.

В разборе двадцатисекундный снимок показал строкой ниже rmngr службу печати с 79 процентами, почти целым ядром. За девять суток она набрала 0,1 процессорного часа, около сорока секунд в сутки: снимок попал на разовый всплеск печати. У rmngr за те же девять суток 299 процессорных часов, в среднем 1,38 ядра, и мгновенные 367 процентов выше этого среднего всего в 2,7 раза. Ряды дальше строим только по процессам с большим накопленным временем.

# Загрузка за 20 секунд и накопленное время ЦП. Только от администратора, иначе процессы
# служб, включая rphost и rmngr, молча выпадут. У разового всплеска YaderSredne около нуля.
$do = @{}; Get-Process | ForEach-Object { $do[$_.Id] = $_.TotalProcessorTime.TotalSeconds }
$t0 = Get-Date; Start-Sleep -Seconds 20; $sek = ((Get-Date) - $t0).TotalSeconds
Get-Process | Where-Object { $_.StartTime -and $do.ContainsKey($_.Id) } | ForEach-Object {
    [pscustomobject]@{
        Process = $_.ProcessName; PID = $_.Id
        YaderSeychas = [math]::Round(($_.TotalProcessorTime.TotalSeconds - $do[$_.Id]) / $sek, 2)
        CpuChasov = [math]::Round($_.TotalProcessorTime.TotalHours, 1)
        YaderSredne = [math]::Round($_.TotalProcessorTime.TotalHours / ((Get-Date) - $_.StartTime).TotalHours, 2)
    }
} | Sort-Object CpuChasov -Descending | Select-Object -First 15 | Format-Table -AutoSize

Скрипты в статье рассчитаны на вставку в консоль PowerShell. Если сохраняете их файлом для Windows PowerShell 5.1, сохраните в UTF-8 с BOM: без него русские комментарии ломают разбор скрипта ещё до запуска.

Ряд по журналу регистрации

Если журнал регистрации выгружается во внешнее хранилище, часовой ряд по событиям и объектам метаданных строится одним запросом, так было и в разборе. Штатный журнал упирается в объём: при приросте 10 ГБ в сутки, как в разобранном случае, двенадцать суток всех событий последовательные файлы быстро не отдадут. Тогда сужайте отбор до одного события и нескольких суток, захватив и спокойные дни, и начало жалоб.

Сначала число событий по часам для базы целиком, потом по событию и объекту, потом свой ряд у каждого кандидата. Ряды ошибок и отмен транзакций штатным методом собирает обработка журнала регистрации для нейросети и показывает, где выборка усечена: усечённый ряд легко принять за спад.

Длительности: медиана и хвост вместо средней

Это правило чтения, оно бесплатно, если длительности уже собраны техжурналом или мониторингом. В разборе средняя длительность метода seanceParametersPresave в хранилище сеансовых данных была 72 мс, вроде бы умеренное равномерное торможение. Распределение показало другое: медиана 0 мс, 95-й перцентиль 109 мс, 99-й 812 мс, максимум 5,5 секунды.

Хранилище в основном отвечало мгновенно и изредка вставало на секунды, а средняя это прячет. Считайте медиану, 95-й и 99-й перцентили и максимум, в ряду по времени по каждому часу.

Разрез по источнику вызова

Когда часть вызовов идёт с соседнего узла, первой подозревают сеть, и проверяют это разрезом длительностей по источнику. В разборе локальные вызовы к хранилищу сеансовых данных дали 23,2 мс, вызовы с соседнего узла 3,8 мс, в шесть раз быстрее, и сеть со вторым узлом из подозреваемых выбыли. Выборка тут другая, чем у средней 72 мс, сводить эти числа нельзя. Резать стоит внутри одного метода, иначе разница может оказаться разницей в составе вызовов.

Дорогие проверки: сервис внутри rmngr и технологический журнал

Сначала сверьте симптом с известными ошибками платформы и сборкой, где их исправили: в разборе две похожие, про рост сеансовых данных и про загрузку rmngr службой журнала регистрации, были исправлены раньше установленной версии.

Прямой способ развести сервисы - флаг “Менеджер под каждый сервис” в свойствах рабочего сервера (dedicate-managers в выводе rac server info). Включение перезапускает агент и обрывает все сеансы узла, поэтому у нас это последний шаг. Если флаг уже стоит, сервисы и так в отдельных процессах: проверьте в консоли или чек-апом сервера 1С.

Дельта размеров каталогов вместо перезапуска

Сеансовые данные лежат в каталогах, чьё имя начинается с snccntx, внутри каталога кластера (srvinfo\reg_1541 при порте по умолчанию), журнал регистрации каждой базы в её 1Cv8Log. Снимите размеры файлов дважды с промежутком в несколько часов и сложите рост по каталогам. Скрипт запускается от администратора, и закрытый каталог тут правильный: в нём же лежит 1CV8Clst.lst с паролями СУБД всех баз кластера в извлекаемом виде. Если ваш снимок прошёл и без прав администратора, проверьте аудитом паролей СУБД, у каких баз пароль достаётся из этого файла.

# 1. Снимок размеров файлов, от администратора (путь поправьте под свой сервер)
$koren = 'C:\Program Files\1cv8\srvinfo\reg_1541'
Get-ChildItem $koren -Recurse -File | Select-Object FullName, Length |
    Export-Csv C:\temp\snimok.csv -NoTypeInformation -Encoding UTF8

# 2. Через несколько часов: рост по каталогам (удаления не вычитаются)
$do = @{}; Import-Csv C:\temp\snimok.csv | ForEach-Object { $do[$_.FullName] = [long]$_.Length }
Get-ChildItem $koren -Recurse -File | ForEach-Object {
    $rost = $_.Length - [long]$do[$_.FullName]
    if ($rost -gt 0) { [pscustomobject]@{ Katalog = $_.DirectoryName; Rost = $rost } }
} | Group-Object Katalog |
    Select-Object @{ n = 'RostMB'; e = { [math]::Round(($_.Group | Measure-Object Rost -Sum).Sum / 1MB) } }, Name |
    Sort-Object RostMB -Descending | Format-Table -AutoSize

В разборе сеансовые данные прирастали на 30 ГБ в сутки, журналы регистрации на 10 ГБ, и со службы журнала подозрение сняли без перезапуска агента.

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

Технологический журнал, который точно что-то ловит

Вызовы найденного сервиса меряет технологический журнал, и главная ловушка здесь пустой результат. В разборе первый фильтр искал seanceParametersPresave по имени события. Только это имя метода, в журнале оно лежит в свойстве MName, и фильтр ловил ноль: каталоги создавались, файлы оставались пустыми. Выглядело как “событий нет, версия закрыта”.

Рабочий фильтр для хранилища сеансовых данных на 8.3.20 собран по типу вызова и имени интерфейса:

<config xmlns="http://v8.1c.ru/v8/tech-log">
  <log location="D:\techlog\sessdata" history="24">
    <event><eq property="name" value="CALL"/><eq property="IName" value="ISeanceContextStorage"/></event>
    <event><eq property="name" value="SCALL"/><eq property="IName" value="ISeanceContextStorage"/></event>
    <property name="all"/>
  </log>
</config>

• Сначала фильтр, который заведомо что-то поймает, и проверка, что файлы растут. Сужать потом: пустой каталог при узком фильтре ничего не доказывает.
• history задаётся в часах. Файл logcfg.xml платформа перечитывает примерно раз в минуту, перезапуск не нужен.
• Выключайте сразу после окна, например переименованием logcfg.xml. Даже этот узкий фильтр со всеми свойствами набирал около 10,6 ГБ в сутки, и пишет эти события тот же подозреваемый rmngr.

План короткого сбора под один вопрос есть в статье про технологический журнал, а попало ли в сбор хоть что-то, показывает свод событий обработки разбора технологического журнала.

Что видите и чем проверить

Что видите	Что это может значить	Чем проверить
Старая ошибка срабатывает тысячи раз в сутки	фон, если ставка прежняя	срабатывания по часам до проблемы и после; в разборе первое нашлось за восемь месяцев до неё
Отмены транзакций совпали с проблемой	совпадение без содержания	что внутри; в разборе полсотни отмен были пустыми: ни изменений, ни ошибок
Тысячи операций ввода-вывода у процесса, диск почти стоит	счётчик процесса учитывает и сетевые операции	счётчики логического диска; в разборе 1 700 операций в секунду против 11
Поиск по каталогу кластера нашёл журнал в другом формате	файлы давно удалённой базы	дата записи: только файлы, в которые пишут сейчас
Зависания при свободном процессоре	ожидание на блокировках	кто блокирует базу
Тормозит одна операция, сервер спокоен	запрос или код операции	чек-лист диагностики
rphost растёт по памяти	утечка или нормальная работа под нагрузкой	наклон роста памяти

Зачистка сеансов: где легко сделать хуже

Когда объект найден, тянет почистить сеансы, и тут легко сбить себе счёт.

Спящие сеансы возвращаются. В разборе завершили 55 спящих из 69, а общее число сеансов за это время выросло с 645 до 649: новых появилось не меньше 59. Пока не найден источник, зачистка только занимает время.

Часть сеансов не завершается. Четырнадцать из 69 ответили ошибкой Не найдено ни одного сервера с размещенным сервисом SessionDataService. Это осиротевшие записи, их выдают два признака вместе: пустое имя пользователя и нет реплики на втором узле.

Список сеансов двоится. При уровне отказоустойчивости выше нуля контекст сеанса копируется на второй узел, и rac session list показывает почти каждый сеанс дважды. Считайте уникальные сеансы, а не записи в выводе.

Границы разбора

Порядок проверен на одном кластере, на других серверах мы его ещё не прогоняли.

Корневую причину тот разбор не назвал. Метод довёл до объекта метаданных и часа, когда начался скачок, дельта каталогов показала самый пишущий сервис. Что поменялось в тот час, не установлено, и связь всплеска изменений объекта с нагрузкой на сеансовые данные осталась гипотезой. Лечения и замера после него нет; когда правка появится, её эффект от шума нагрузки отделит чередующийся замер до и после.

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