Скажу сразу — с такой проблемой можно столкнуться практически в любых версиях 2.4 конфигурации ERP и соответствующих УТ, КА. Чтобы прочувствовать эффект, нужно взять базу побольше, а дальше добавить один единственный документ.
В версии 2.5 по всей видимости с подобной ситуацией столкнулись и реализовали предупреждение при попытке провести документ дальним будущим, но «злобный» пользователь при желании все равно сможет наломать дров.
Кто виноват и почему так получилось, ищите ниже в статье.
План статьи:
- Обнаружение проблемы
- Поиск точки возникновения проблемы
- Анализ найденной проблемы
- Горячее исправление текущей ситуации
- Пути решения и дополнительное исследование
Исходные параметры рассматриваемой системы:
- Конфигурация ERP 2.4.
- Количество пользователей онлайн: 1000+.
- Платформа 1С: 8.3.19
- СУБД PostgreSQL 14
- Конфигурация "Мониторинг производительности"
- Zabbix
Итак, мы продолжаем делиться знаниями и опытом... 3. 2. 1. Поехали!
1. Обнаружение проблемы
Как всегда, проблема появилась внезапно. Начали появляться таймауты. Наш ИИ Лариса заметила нестандартную ситуацию и начала нагнетать обстановку. Потом подтянулись пользователи и начали жаловаться на затрудненность в выполнении некоторых операций в базе. База, конечно же, не встала, но работать стало некомфортно, даже можно сказать, значительно сложнее чем ранее.
Когда появились проблемы, "Who ya gonna call?" Конечно же надо сразу вызывать охотников за привидениями багами в базе 1С.
2. Поиск точки возникновения проблемы
Замеры есть, смотрим проблемы по блокировкам:
Ого-го! Блокировок достаточно много с обычными 3-4 в десять минут. Мы видим резкий рост проблем до нескольких сотен. Далее открываем журнал замера по блокировкам и начинаем его смотреть. В замер блокировок включаются события TTIMEOUT (ошибка по таймауту на управляемых блокировках) и TDEADLOCK (взаимоблокировки). Мы видим в основном только TTIMEOUT.
Смотрим контекст:
По контексту видно, что блокируются виды запасов по товарам. Иными словами, подбираются остатки видов запасов и на время проведения документа на них ставится блокировка, чтобы их не подъел кто-то другой.
Сначала у нас было предположение, что какой-то пользователь или регламент завис. И вот этот злодей блокирует работу остальных. Надо провести анализ. Его проводили по следующему алгоритму:
а) Мы взяли значение из поля WaitConnections:9680 из журнала блокировок.
б) Далее взяли срез данных консоли RAS на время 10:19
И нашли сеанс пользователя, который заблокировал. Это номер 12489.
в) Далее посмотрим, что за пользователь.
Во-первых, мы видим, что этот пользователь висит довольно долго — более 230 с.
Во-вторых, посмотрим, что он делает, через журнал регистрации. По журналу регистрации видно, что пользователь проводит документ Этап производства. Глаза зацепились за странный момент - время проведения этого документа какое-то большое, явно больше обычного, но об этом чуть позже.
После проверки нескольких пользователей в попытке найти зависший сеанс проявилась следующая картинка:
- Пользователь Иванов проводит Этап. Его ждет пользователь Петров и Козлов.
- Потом в какой-то момент времени Петров дожидается и начинает проводить документ. Теперь его ждут Иванов и Козлов.
- И так по кругу. Переходим на шаг 1, но уже с другим пользователем.
Иными словами, нет злосчастного зависшего сеанса. Предположение не подтвердилось. Давайте смотреть дальше.
Посмотрим по этому пользователю (которого мы анализировали выше) проблемные запросы. Помните, было ощущение, что время проведения подозрительно большое.
Открываем замер "длительные запросы" и видим интересную картинку (рисунок ниже). Берем ориентировочное время блокировки по этому пользователю и обнаруживаем продолжительный запрос. И не один, таких сразу несколько.
Следующим шагом проверим, были ли подобные запросы ранее. Для того чтобы решить данную задачу, нужно поставить отбор по пользователю (у нас уже стоит) и по контексту. За предыдущие дни таких запросов не было, может, и были, но они не смогли преодолеть 5 с фильтр (сейчас мы ловим только те, что более 5 с).
Дальше будем смотреть по контексту. Открываем его:
Судя по всему, выполняется проведение этапа. Получается, что стало происходить что-то необычное при проведении этапа, т.к. время проведения составило практически 60 с. Это очень много.
Делаем предположение, что виной вот этот запрос. Модуль, в котором видна проблема - это ПроведениеСерверУТ. И функция - ВыполнитьКонтрольРезультатовПроведения. Отправная точка для начала поиска у нас есть. Теперь осталось найти зацепку для поиска текста запроса.
Давайте откроем запрос. Он хранится в замере (колонка SQL). И эта форма с текстом подозрительно долго открывается.
В нем более 10 000 строк, Карл! Вот это запрос!!!
Наше подозрение подтверждается. Ищем теперь его внутри лога от PostgreSQL. Я искал по части строк и запроса «FROM _AccumRgT40229 T4». Находим первый, и он сразу похож на проблемный.
На рисунке вы можете увидеть дату от 3999 года. Но это нормальная ситуация, это дата бесконечности от компании 1С. На эту дату хранятся текущие итоги в таблице итогов регистра накопления (_AccumRgT).
Теперь ищем план. Это было непросто, но мы смогли, и он занимает 61 180 строк! Ради спортивного интереса мы попробовали его посмотреть, но, увы, слишком он здоровый. И мне так и не удалось его открыть в браузере. Не беда.
Кстати, посмотрите, как из-за этой проблемы вырос лог сервера PostgreSQL.
Размер запроса в строках (Сам запрос + План запроса), который выполняется практически при проведении каждого коммерческого документа, объясняет, почему вырос лог с 13 МБ до 650 МБ.
Давайте поищем, где формируется такой запрос внутри конфигурации. Выбираем какой-нибудь знаковый кусочек. Мы выбрали небольшой отрывок этого "шедевра", который часто повторяется. И, преобразовав запрос, мы начинаем искать, где встречается подобная штука.
В самом модуле ПроведениеСерверУТ такой шаблон не встречается. Но мы видим, что текст запроса проверки собирается из частей. И мы понимаем, что этот запрос должен быть связан с товарами организаций.
После непродолжительного поиска был обнаружен вызов подходящей функции - ЗапасыСервер.ДобавитьКонтрольПоТоварамОрганизаций. Внутри которой встречается подобный текст. Это шаблон для запроса, и называется он ШаблонЗапросаОстаткаМесяца.
Мы нашли точку формирования проблемы. И будем смотреть эту функцию дальше.
3. Анализ найденной проблемы
Итоговый текст запроса, который мы видели в логах, формируется именно в этой функции. Такое количество объединений у нас получается в цикле, который ниже.
Нам интересно понять - сколько итераций внутри этого цикла будет выполняться. И соответственно чему равны два параметра. Шаг итератора у нас равен 1 месяцу.
а) МинимальныйПериод определяется так:
1. Сначала выполняется запрос, в котором получается минимально возможный период.
ВЫБРАТЬ ПЕРВЫЕ 1
РезервыТоваровОрганизаций.Период КАК Период
ИЗ
РегистрНакопления.РезервыТоваровОрганизаций КАК РезервыТоваровОрганизаций
УПОРЯДОЧИТЬ ПО
Период
2. А потом выбирается дата не более 3 лет назад.
МинимальныйПериод = КонецМесяца(Мин(МинимальныйПериод, ДатаПервогоРезерва(МинимальныйПериод)));
КонецТекущегоМесяца = КонецМесяца(ТекущаяДатаСеанса());
// Больше трех лет не контролируем, чтобы не превысить количество таблиц в запросе.
ТриГодаНазад = КонецМесяца(ДобавитьМесяц(КонецТекущегоМесяца, -36));
Если МинимальныйПериод < ТриГодаНазад Тогда
МинимальныйПериод = ТриГодаНазад;
ИначеЕсли МинимальныйПериод > КонецТекущегоМесяца Тогда
МинимальныйПериод = КонецТекущегоМесяца;
КонецЕсли;
Т.е. получается, что разработчики подумали над тем, чтобы не лезть слишком глубоко в прошлое. Т.е. 3 года назад от текущей даты это будет не менее 01.01.2020 года. А что у нас со второй переменной - ОбрабатываемыйМесяц?
б) А вот обрабатываемый месяц находится через функцию ДатаПоследнегоДвижения (на рисунке выше выделено красной чертой). А внутри этой функции нас ожидает запрос:
ВЫБРАТЬ ПЕРВЫЕ 1
ТоварыОрганизаций.Период КАК Период,
ТоварыОрганизаций.Регистратор КАК Регистратор
ИЗ
РегистрНакопления.ТоварыОрганизаций КАК ТоварыОрганизаций
УПОРЯДОЧИТЬ ПО
Период УБЫВ
Чтобы определить значение этого параметра, нам необходимо выполнить его в консоли запросов. В результате получаем следующий результат (в уме держим, что полученный период еще минус 1 месяц):
Вот это поворот. У нас в базе есть документ фактически из следующего века.
Давайте посмотрим на документ, узнаем, как он появился - пользователь или какой-то регламент.
Он был создан пользователем. И это очевидная ошибка ввода данных. Мы нашли проблему!
Небольшое подведение итога по расследованию:
Алгоритм работает с максимального периода (2099 года) и движется назад к текущей дате с шагом 1 месяц. Фактически мы видим, что цикл работает от даты, которая хранится в переменной ОбрабатываемыйМесяц, и до даты МинимальныйПериод.
Если посчитать вручную, то это чуть больше 900 объединений. Вот таким образом и получается наш запрос монстр. В обычном режиме работы всего несколько объединений (может, десятка два), которые не влияют на производительность в целом.
А самое замечательное, что чуть ранее до выполнения контроля вызывается управляемая блокировка видов запасов по товарам организаций в большинстве случаев - функция ЗапасыСервер.ЗаполнитьЗапасыТоваровОрганизаций.
По результатам этого мини расследования мы можем кратко описать работу пользователей:
- Пользователь проводит документ.
- В какой-то момент устанавливается блокировка при вызове функции ЗапасыСервер.ЗаполнитьЗапасыТоваровОрганизаций.
- Выполняется контроль в функции ПроведениеСерверУТ.ВыполнитьКонтрольРезультатовПроведения, который занимает 60 с из-за тяжелого запроса контроля остатков. Блокировка все еще держится.
- Все остальные пользователи, кто решил провести данные по совпадающим аналитикам разреза блокировки, начинают ожидать и встают в очередь (очередь СУБД).
- Проведение завершается и блокировка снимается.
- Следующий
счастливчикпользователь из очереди начинает проводить свой документ. - Переходим в начало на шаг 1.
4. Исправление текущей проблемы
Мы понимаем, что проблема в этом документе, точнее в его дате. Если мы исправим ошибочную дату, то проблема должна уйти. Поэтому далее будем проверять это предположение.
Берем копию базы и на ней пробуем (в данной ситуации можно взять любой свежести и добавить новый документ будущей датой). Проводим тестирование по следующим шагам:
- Сначала проводим документ как есть, ловим 60-70 секунд при проведении и запрос монстр. Видим его в логах и замерах.
- Теперь изменяем дату на 2023 и проводим еще раз. О чудо. Проведение вернулось в район нескольких секунд. Логи ушли.
Оперативно передаем информацию администратору базы. И ждем исправления документа. После правки контролируем изменение ситуации.
- Графики должны вернуться в норму
- Блокировки в журнале блокировок должны уйти
- Пользователи должны начать работать штатно
Смотрим графики после исправления ситуации:
Применили исправление около 11 часов. Проблема ушла практически мгновенно и все вернулось в норму.
На графиках ниже приведены результаты замеров. Нам доступны следующие показатели (про них можно узнать подробнее в статье Анализ проблем производительности по динамике мониторинга RAS 1C):
- очередь к сервисам 1С (сколько обращений к службам в единицу времени),
- очередь к СУБД (сколько в единицу времени обрабатывает СУБД запросов),
- нагрузка на сервере 1С и СУБД.
Красная черта - это граница - экспертная оценка, которая считается верхней нормой, при которой работа считается нормальной. Также мы видим, что блокировки не нагружают сервер 1С. Это логично, т.к. он просто ждет и ждет, пока ему вернут результат запроса. А вот на СУБД ситуация противоположная и нагрузка достигает 50%, и пик явно выражен.
Для наглядности приведем еще график блокировок с данными за двое суток - проблемный и следующий день. Слева проблемный день, а справа тишь да гладь.
Резюме:
Вот таким образом незначительная ошибка в одном документе одного пользователя добавила серьезных проблем всем остальным.
5. Пути решения и дополнительное исследование проблемы
Что же, пожар потушен! Теперь можно более пристально взглянуть на ситуацию и подробнее разобрать, что произошло, почему и как исправить. Думаю, что так все поступают.
Прежде чем самостоятельно садиться и придумывать решение - как закрыть эту «дырку», давайте ответим на вопрос: «А что у нас в ERP 2.5?». Зачем что-то придумывать, если решение уже существует.
а) Сначала проверим наличие подобного контроля в товарах организаций этой версии конфигурации:
Ищем по ключевым фразам и находим. Данную функцию перенесли в общий модуль «ЗапасыСервер». И называется она сейчас «ИнициализироватьДанныеКонтроляИзменений». Сам подход ее остался тем же, т.е. ситуация в целом повторяема.
б) Теперь проверим/повторим наличие ошибки или найдем наличие исправления.
Попробуем сходу в демонстрационной базе создать новый документ и провести его будущей датой.
При попытке выполнить такую операцию нам выдается предупреждение о возможной ошибке. Данная ситуация обрабатывается. Видимо, подобного характера "особенность" встречалась еще у кого-то, и вендор добавил обработку ситуации. И поэтому в качестве отправной точки для собственной "заплатки" будем использовать предложенный подход.
На рисунке ниже приведен результат эксперимента с созданием документа будущей датой на демонстрационной конфигурации ERP версии 2.5.
в) Теперь давайте посмотрим, а почему собственно возникают такие проблемы? Возьмем базу с хорошим набором данных. У нас есть одна такая под рукой. И опять смоделируем ситуацию. Дату возьмем поменьше, т.к. слишком много текста.
В результате мы получили следующую картинку (приведена ниже). Еле заметная красная черточка на круге - это одно объединение. Из схемы следует, что как таковых перекосов нет, просто очень много объединений, которые равноценно вносят вклад в общее время.
