Каталог решений - Проблема производительности. Как может заблокировать работу в ERP один-единственный документ от 01.01.2099 года?

Скажу сразу — с такой проблемой можно столкнуться практически в любых версиях 2.4 конфигурации ERP и соответствующих УТ, КА. Чтобы прочувствовать эффект, нужно взять базу побольше, а дальше добавить один единственный документ.

В версии 2.5 по всей видимости с подобной ситуацией столкнулись и реализовали предупреждение при попытке провести документ дальним будущим, но «злобный» пользователь при желании все равно сможет наломать дров.

Кто виноват и почему так получилось, ищите ниже в статье.

План статьи:

1. Обнаружение проблемы
2. Поиск точки возникновения проблемы
3. Анализ найденной проблемы
4. Горячее исправление текущей ситуации
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. Пользователь Иванов проводит Этап. Его ждет пользователь Петров и Козлов. 
2. Потом в какой-то момент времени Петров дожидается и начинает проводить документ. Теперь его ждут Иванов и Козлов.
3. И так по кругу. Переходим на шаг 1, но уже с другим пользователем.

Иными словами, нет злосчастного зависшего сеанса. Предположение не подтвердилось. Давайте смотреть дальше.

Посмотрим по этому пользователю (которого мы анализировали выше) проблемные запросы. Помните, было ощущение, что время проведения подозрительно большое.

Открываем замер "длительные запросы" и видим интересную картинку (рисунок ниже). Берем ориентировочное время блокировки по этому пользователю и обнаруживаем продолжительный запрос. И не один, таких сразу несколько.

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

Дальше будем смотреть по контексту. Открываем его:

Судя по всему, выполняется проведение этапа. Получается, что стало происходить что-то необычное при проведении этапа, т.к. время проведения составило практически 60 с.  Это очень много.

Делаем предположение, что виной вот этот запрос. Модуль, в котором видна проблема — это ПроведениеСерверУТ. И функция — ВыполнитьКонтрольРезультатовПроведения. Отправная точка для начала поиска у нас есть. Теперь осталось найти зацепку для поиска текста запроса.

Давайте откроем запрос. Он хранится в замере (колонка SQL). И эта форма с текстом подозрительно долго открывается. 

В нем более 10 000 строк, Карл! Вот это запрос!!!

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

На рисунке вы можете увидеть дату от 3999 года. Но это нормальная ситуация, это дата бесконечности от компании 1С. На эту дату хранятся текущие итоги в таблице итогов регистра накопления (_AccumRgT).

Теперь ищем план. Это было непросто, но мы смогли, и он занимает 61 180 строк! Ради спортивного интереса мы попробовали его посмотреть, но, увы, слишком он здоровый. И мне так и не удалось его открыть в браузере. Не беда.

Кстати, посмотрите, как из-за этой проблемы вырос лог сервера PostgreSQL.

Размер запроса в строках (Сам запрос + План запроса), который выполняется практически при проведении каждого коммерческого документа, объясняет,  почему вырос лог с 13 МБ до 650 МБ. 

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

В самом модуле ПроведениеСерверУТ такой шаблон не встречается. Но мы видим, что текст запроса проверки собирается из частей. И мы понимаем, что этот запрос должен быть связан с товарами организаций.

После непродолжительного поиска был обнаружен вызов подходящей функции — ЗапасыСервер.ДобавитьКонтрольПоТоварамОрганизаций. Внутри которой встречается подобный текст. Это шаблон для запроса, и называется он ШаблонЗапросаОстаткаМесяца.