От экспертов «1С‑Рарус»: «Мониторинг производительности» — RLS, анализ блокировок и сложных пакетных запросов. Часть 3
От экспертов «1С‑Рарус»: «Мониторинг производительности» — RLS, анализ блокировок и сложных пакетных запросов. Часть 3

От экспертов «1С‑Рарус»: «Мониторинг производительности» — RLS, анализ блокировок и сложных пакетных запросов. Часть 3

28.11.2024
80 мин
729

Оглавление

  1. Когда RLS не виноват
  2. Блокировки без образования таймаутов
  3. Анализ сложных пакетных запросов, получение полного текста пакетного запроса и воспроизведение в лабораторных условиях

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

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

Когда RLS не виноват

Недостаточно прав для исполнения операции в базе 1С:ЗУП

Поговорим про ещё один случай, расследованный с помощью «1С‑Рарус: Мониторинг производительности», и как важно с осторожностью использовать типовые методы.

Случай о котором мы расскажем, произошел в базе «1С:Зарплата и управление персоналом» (далее ЗУП). С использованием ЗУП и Общей управленческой базы организован Бизнес‑Процесс принятия к учету нового сотрудника. Выглядит он следующим образом:

  • Ответственный кадровый сотрудник в Общей управленческой базе создает карточку физического лица.
  • Далее регламентным заданием происходит обмен между Общей управленческой базой и базой ЗУП, через который в базу ЗУП попадают элементы справочника «Физические лица».
  • После этого ответственный кадровый сотрудник в ЗУП создает элемент справочника «Сотрудники», в котором выбирает физическое лицо из существующих в базе, тем самым принимая сотрудника уже в регламентированный учет.

К нам обратился пользователь, у которого программа выдавала ошибку при попытке записать элемент справочника «Сотрудники»:

Справочник «Сотрудник (создание)»

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

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

  • Отказ права — «Действие. Добавление».
  • Метаданные — «Справочник. Сотрудники».

Журнал регистрации

По метаданным «Справочник. Сотрудники» проверяем группы доступа пользователя. В группах «Руководитель подразделения» и «Старший кадровик-расчетчик» есть роль с правом на запись в справочник «Сотрудники».

В них указаны одинаковые ограничения по «Группам физических лиц» НН и Общая:

Нижний Новгород (Группа доступа)

Такой реквизит есть и в справочнике «Физические лица» и на форме элемента справочника «Сотрудники», может там указано неверно? Проверяем.

В физлице указана группа «Общая»:

Справочник «Физические лица»

При создании сотрудника она также заполняется значением «Общая», пользователь её меняет на нужную, в данном случае «НН», пытается провести и выпадает ошибка.

К обеим группам «НН» и «Общая» у пользователя есть доступ, что же не так?

На всякий случай даже смотрим в шаблон ограничений доступа в конфигураторе:

Справочник «Права доступа»

Там всё так же, ограничение по группам физ лиц:

Справочник «Все роли»

Уже не зная что делать, наощупь, сотрудник тех. поддержки изменил в физлице группу на «НН» и записал элемент. И после этого у обратившегося к нам пользователя удалось создать сотрудника!

Справочник «Физические лица»

Надо бы радоваться — боль пользователя снята.

Но мы же не знаем, в чем причина такого поведения, и так это оставлять нельзя.

Ищем вмешательство RLS в запрос на вставку в таблицу

Предполагаем, что проблема связана с механизмом RLS (Record Level Security). Но как найти зацепку?

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

Увидеть текст запроса СУБД можно в логе технологического журнала. Рассматриваемая база уже подключена к системе «1С‑Рарус:Мониторинг производительности», логи ТЖ выгружаются туда на регулярной основе. Поэтому анализировать мы будем с помощью этой системы.

Пройдем в программу и откроем обработку «Доска диаграмм»:

Мониторинг. Доска диаграмм

Доска для расследований

В Мониторинге уже есть поставляемая диаграмма по событиям запросов:

  • «Универсально. Суммарная количество DBPOSTGRS > N секунд по context. Круговая диаграмма».

Чтобы её не изменять, скопируем её в нашу доску для расследований и создадим диаграмму «События DBPOSTGRS по context». Получатся такие настройки:

  • Серия = «Контекст».
  • Значение = «Количество».
  • Вид диаграммы = «Круговая».
  • Период — возьмем близкий к дате сообщения об отказе в доступе в журнале регистрации +/- пару секунд:

    Доступ в журнале регистрации

Справочник «Диаграммы (создание)»

Отборы по полям будут следующие:

  • _event = «DBPOSTGRS» — отбираем только запросы к СУБД.
  • usr — указываем логин пользователя, под которым произошла ошибка.
  • sql — идея была посмотреть запросы на запись, поэтому ищем запросы содержащие лексему «INSERT».

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

Отборы по полям

Записываем настройки и формируем диаграмму:

Диаграмма «События DBPOSTGRS по contex»

Видим, что есть одно событие с контекстом «Форма.Записать : Справочник.Сотрудники.Форма.ФормаЭлемента», похоже, что оно нам и нужно. Переходим в его расшифровку:

Расшифровка: События DBPOSTGRS по contex

Как видим, в запросе на вставку в таблицу никаких «добавок» RLS нет. Как же платформа проверяет доступ на запись?

Иногда для понимания картины полезно взглянуть на соседние события ТЖ. Попробуем проанализировать, какие ещё события выполнялись в этом промежутке, может быть в них найдем ответ.

Для этого мы напишем свой шаг обработки строки расшифровки.

Создаём механизм поиска ближайших к возникновению ошибки событий технологического журнала

Формализуем условия:

  • Мы хотим выбрать некоторое заданное количество событий ДО и ПОСЛЕ текущего события.
  • При этом нам нужны события только того же вызова, поэтому выбирать их будем с тем же контекстом и номером соединения.

Добавим новый шаг обработки строки и назовем его «Ближайшие события ТЖ (t_connectid/context)»:

Расшифровка: Универсально. Суммарная длительность события DBPOSTGRS по contex. Круговая диаграмма

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

Исходная строка расшифровки получена из лога технологического журнала, поэтому в структуре ПоляСтроки будут доступны все возможные свойства событий, сбор которых настроен у нас в файле logcfg.xml. Полный список свойств мы здесь приводить не будем, с ними можно ознакомиться на ИТС (its.1c.ru/db/v8325doc#bookmark:adm:TI000000841).

Для нашей задачи понадобятся следующие свойства:

  • _time — дата события в текстовом формате с детализацией до микросекунд.
  • t_connectid — номер соединения.
  • context — контекст события.

Также сразу определим переменную «КоличествоСобытий» — она определяет сколько событий до и после мы хотим отобрать. В нашем случае поставим значение 5:

Ближайшие события ТЖ (по t_connectid/context) (Шаги сценария)

Далее формируем специальный текст запроса к базе ClickHouse, его идея в следующем — мы формируем объединение из двух запросов с условиями по номеру соединения и контексту:

  • В одном отбираем ПЕРВЫЕ N событий с датой меньше даты исходного события и с обратным упорядочением по времени.
  • Во втором ПЕРВЫЕ N событий с датой больше или равно дате исходного события и с прямым упорядочением по времени.

Тем самым мы выбираем заданное количество событий в обе стороны по оси времени. После этого сортируем полученные события по времени:

События

Для нашего примера получится такой запрос:

SELECT * FROM
   (SELECT TOP 5
 *
FROM
    default.tj_log
WHERE
    _time < '2024-10-16 14:29:31.305000'
    AND t_connectid = '144885'
    AND context = 'Форма.Записать : Справочник.Сотрудники.Форма.ФормаЭлемента'
ORDER BY _time desc
UNION ALL
SELECT TOP 6
 *
FROM
    default.tj_log
WHERE
    _time >= '2024-10-16 14:29:31.305000'
    AND t_connectid = '144885'
    AND context = 'Форма.Записать : Справочник.Сотрудники.Форма.ФормаЭлемента'
ORDER BY _time)
ORDER BY _time

Сохраняем шаг и возвращаемся в форму расшифровки.

Поиск ближайших к ошибке событий с RLS

Выделяем нашу найденную ранее строку события DBPOSTGRS с запросом INSERT, в поле «Шаг обработки текущей строки» выбираем наш шаг «Ближайшие события ТЖ (t_connectid/context)» и нажимаем кнопку «Обработать»:

Расшифровка: События DBPOSTGRS по contex

В результате получаем таблицу ближайших событий. По центру, как и предполагалось, исходный запрос на INSERT.

Также примечаем два события позже него:

  • DBPOSTGRS с текстом ROLLBACK, это откат транзакции.
  • EXCP — с сообщением о недостатке прав доступа.

Результат ближайших событий

Между запросом на INSERT и ROLLBACK есть запрос выборки, может быть в нём проверка RLS, после которой и происходит откат транзакции? Взглянем на него поближе.

В нём используются таблицы:

  • ТЧ «Пользователи» справочника «ГруппыДоступа».
  • Регистр сведений «СоставыГруппПользователей».

Проверка запроса

Но в этом запросе нет ничего связанного с группами физических лиц. С участвующими таблицами в базе всё в порядке. Получается в этом запросе ничего примечательного. А между INSERT и ROLLBACK больше ничего нет...

Медитируем над таблицей чуть больше времени и приходит озарение, мы вспоминаем, что в поле _time время события фиксируемое в ТЖ — это время окончания, а не начала события и запрос, который идет строкой ниже после запроса ROLLBACK, с учетом длительности _duration, на самом деле инициирован раньше него:

Результаты запроса

Проанализируем текст этого запроса.

Как только видим текстовые конструкции вида SDBL_DUMMY, понимаем, что это «добавка» RLS и то, что нужно:

Анализируем текст запроса

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

Справочники:

  • _Reference312 — Сотрудники.
  • _Reference90 — ГруппыДоступа.
  • _Reference124X1 — ИдентификаторыОбъектовМетаданных.

Регистры сведений:

  • _InfoRg20239 — ОрганизацииВКоторыхРаботалиСотрудники.
  • _InfoRg22721 — ТаблицыГруппДоступа.
  • _InfoRg18483 — ЗначенияГруппДоступа.
  • _InfoRg18490 — ЗначенияГруппДоступаПоУмолчанию.
  • _InfoRg17530 — ГруппыЗначенийДоступа.

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

И обнаружили, что в регистре «Группы значений доступа» в копии отсутствует запись по нашему физлицу:

Группы значений доступа

А в рабочей базе она есть.

Группы значений доступа

В рабочей базе запись в этом регистре появилась при ручной записи из формы элемента справочника, до этого элемент был записан только программно при обмене с Общей управленческой базой, что навело на мысль — проблема в контуре обмена.

Проверяем контур обмена между ЗУП и управленческой базой

Мы проанализировали блок обработчиков физических лиц при обмене и в конечном итоге наткнулись на код обработчика события «После записи» элемента справочника «Физические лица», в котором вызывается несуществующий метод ОбновитьГруппыЗначенийДоступа:

Код обработчика события

Как оказалось, некоторое время назад база ЗУП была обновлена с версии 3.1.29.38 на версию 3.1.30.15. При этом переходе изменились подписки на событие объекта справочника «Физические лица»:

  • В прежней версии была подписка на событие «При записи» с обработчиком ОбновитьГруппыЗначенийДоступа.
  • В новой версии эта подписка была удалена и вместо неё подписок стало две:
    • ОбновитьГруппыЗначенийДоступаПередЗаписью.
    • ОбновитьГруппыЗначенийДоступаПриЗаписи.

В блоке обмена при записи физического лица взводится флаг «ОбменДанными.Загрузка = Истина» и эти подписки штатным образом не отрабатывают. Поэтому уже после записи объекта был добавлен программный вызов обработчика подписки со снятым флагом.

Но при обновлении стандартной конфигурации изменения этих вызовов не заметили и обработчик в блоке обмена стал не рабочим.

Как результат, мы заменили обработчики в блоке обмена и с новыми объектами проблема больше не возникала:

Результат кода обработчика события

Наконец-то мы продрались через все хитросплетения и решили задачу. Во вступительном слове было отмечено, что порой кажущаяся простота таит в себе глубину. Что может быть невиннее просьбы пользователя разобраться, почему не удается запись элемент справочника? И вдруг приходится разобраться в не самом простом механизме БСП ограничение прав пользователя. Столкнуться с тем, что формально настроено все верно. Пройти сквозь мрак записей логов ТЖ, коих бывает сотни гигабайт, связав попутно это как‑то с логами журнала регистрации. Наконец, понять, что есть место позабытого переиспользования кода типового решения.

Блокировки без образования таймаутов

Зависания 1С при одновременной работе нескольких пользователей и специфика группового перепроведения документов на предприятиях общепита

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

Этот инцидент произошел на крупном предприятии общественного питания, где для автоматизации деятельности использовалась конфигурация «1С:УНФ 8. Управление предприятием общепита». В начале очередного месяца пользователи начали жаловаться на то, что работа с программой стала невозможной из-за задержек при проведении документов и ошибок при выполнении группового перепроведения, которые возникали в следствии блокировок:

Справочник «Все отчеты (Деньги)»

В предыдущих статьях мы уже упоминали, что периодическое выполнение группового перепроведения документов является штатным сценарием работы со складскими остатками на предприятиях общественного питания.

Одна из причин, по которой возникает такая необходимость, — это разница между временем оформления складских и производственных документов. Например, в понедельник на склад поступили ингредиенты, а бухгалтер для их правильного оформления приходит только по пятницам. Повару же нужно приготовить блюда из этих ингредиентов прямо сейчас и у него нет времени дожидаться их официальной приемки. Тем более к пятнице половина ингредиентов может уже испортиться. Соответственно, он готовит блюда из этих ингредиентов и отражает их документами «Выпуск блюд».

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

Сценарий работы со складскими остатками на предприятиях общественного питания

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

Проверяем общее количество блокировок в Мониторинге производительности

Что же тогда приводило к появлению блокировок и из-за чего система начинала притормаживать? Ответить на этот вопрос нам помогла конфигурация «1С‑Рарус: Мониторинг производительности», которая была настроена в инфраструктуре данного клиента.

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

Для этого запускаем конфигурацию «1С‑Рарус: Мониторинг производительности», открываем доску диаграмм и выбираем доску «Поставляемая доска универсальный монитор»:

Мониторинг. Доска диаграмм

После чего переходим на вкладку «Блокировки и ожидания». На данной странице есть две диаграммы: первая анализирует превышение максимального времени ожидания транзакционных блокировок (события TTIMEOUT), а вторая — блокировки с длительностью превышающие 10 секунд (события TLOCK с ограничением по длительности). Напомним, что по умолчанию период максимального времени ожидания транзакционных блокировок составляет 20 секунд:

Диаграмма слева анализирует превышение максимального времени ожидания транзакционных блокировок (события TTIMEOUT), справа — блокировки с длительностью превышающие 10 секунд (события TLOCK с ограничением по длительности)

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

Блокировки превышения максимального времени ожидания

Начнем с анализа превышения максимального времени ожидания. Для этого кликнем на столбец 12 часов диаграммы по таймаутам. После чего перейдем к расшифровке по кнопке «Подробная детализация»:

Подробная детализация

Убеждаемся, что на 12 часов дня было зафиксировано 2 события TTIMEOUT:

Расшифровка: Универсально. События TTIMEOUT

В поле «Шаг обработки текущей строки» выберем предопределенный шаг «Виновники блокировки» и нажмем обработать:

Шаги сценария

После обработки система найдет события, связанные с событиями TLOCK «жертвы» и «виновника»:

Вывод значения связанные с событиями TLOCK «жертвы» и «виновника»

Сразу обращаем внимание, что есть два сеанса, которые пересекаются на одном пространстве «AccumRg48970.DIMS». По контексту событий обнаруживаем, что виновник выполняет проведение выпуска блюд с розничной реализацией с формы документа, а жертва выполняет фоновое проведение. Из чего делаем вывод о нарушении рекомендации «Не проводить документы по разрезам аналитики аналогичным групповому перепроведению».

Контекст виновника:

Вывод значения: Контекст виновника

Контекст жертвы:

Вывод значения: Контекст жертвы

При этом состав накладываемых полей блокировок весьма схожий и во многих полях отличается лишь периодом. Жертва устанавливает точечную блокировку на 01.10, а вот виновник накладывает диапазоном от 01.09 до 01.10. Что и приводит к блокировкам:

Состав полей блокировок

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

Почему же в одном случае период был точечный, а в другом диапазоном?

Если вспомнить архитектуру объекта регистра накопления, то на уровне СУБД информация о нем размещается в трех таблицах: движений, итогов и настроек хранения (its.1c.ru/db/metod8dev/content/2726/hdoc). В таблице итогов хранятся остатки в разрезе всех измерений с периодичностью месяц на начало месяца. В таблице движений хранятся все записи регистра. В таблице настроек хранения располагается служебная информация по периодам итогов, использование текущих итогов и т. п.:

Служебная информация по периодам итогов, использования текущих итогов и т. д.

В момент записи движений регистра накопления, технологическая платформа устанавливает ряд управляемых блокировок по пространствам «РегистрНакопления.<имя>.НаборЗаписей» и «РегистрНакопления.<имя>» (its.1c.ru/db/v8325doc#bookmark:dev:TI000000535), которые будут влиять на таблицы движений и итогов соответственно. Для корректного хранения итогов система устанавливает блокировку по периоду, который будет необходимо пересчитать:

Запись движения регистра накопления

В связи с этим поведение при использовании текущих итогов и поведение при их отключении будет отличаться. Если текущие итоги отключены, то при фиксации движений до даты периода рассчитанных итогов система будет устанавливать блокировку от начала месяца движения до начала месяца периода итогов, а если после даты периода итогов, то на начало месяца даты движений. Например, период рассчитанных итогов 31.10.2024:

Регистр

Если фиксируется движение с периодом 20.06.2024, то система установит блокировку от 01.06.2024 до.01.10.2024:

Блокировка

Если же период 20.12.2024, то система установит блокировку на 01.12.2024:

Блокировка

В случае, когда использование текущих итогов включено, то система будет накладывать блокировку от начала месяца даты движения и до даты «текущих итогов» (3999 г). Т. е. если период 20.09.2024, то блокировка будет от 01.09.2024:

Регистр

Пример движений с периодом 20.09.2024:

Пример движений с периодом 20.09.2024

Пример движений с периодом 20.12.2024:

Пример движений с периодом 20.12.2024

Блокировки, превышающие 10 секунд

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

Диаграмма «Универсально. События TLOCK больше N секунд»

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

Расшифровка: Универсально. События TLOCK больше N секунд

Контекст же таких блокировок полностью аналогичен ранее указанным таймаутам.

Итоги анализа блокировок

Таким образом, с помощью «1С‑Рарус: Мониторинг производительности» были проанализированы собранные логи и обнаружены длительные блокировки, которые периодически выходили за максимальное время ожидания. Эти блокировки были связаны с параллельной работой пользователя в текущем периоде и групповым перепроведением документов за предыдущий месяц. А из-за их большого количества у пользователей возникало ощущение, что система работает медленно. Соответственно, общая рекомендация, которую мы еще раз предложили клиенту не выполнять параллельную работу при групповом перепроведении предыдущего периода.

Однако, учитывая, что бизнес‑процессы некоторых клиентов могут не позволять полностью отказаться от такой параллельной работы, были запланированы следующие механизмы развития:

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

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

А может быть тормозит не все? А может быть не всегда? А может быть не всегда так было? Все эти вопросы уместны и их, конечно, следует задавать. И не стоит забыть, что «все врут» ©. Поэтому «холодный» взгляд эксперта после или, лучше сказать, вместе с интервьюированием, помогает разобраться в ситуации. Что касается рассмотренной ситуации, то отметим позитивную сторону: хорошо, что не стали бороться с блокировками, меняя типовые 20 секунд ожидания на больший период (это, конечно, шутка, не делайте так).

Анализ сложных пакетных запросов, получение полного текста пакетного запроса и воспроизведение в лабораторных условиях

Пакетные запросы являются неотъемлемой частью кодовой базы типовых и отраслевых конфигураций 1С и обеспечивают возможность эффективной выборки данных из СУБД. Такие запросы могут быть действительно большими, тексты таких запросов могут занимать несколько тысяч строк и, конечно же, они используют данные во временных таблицах. Часто бывает, что большие и сложные запросы пишутся взамен алгоритмических вариантов решения задач для уменьшения количества обращений к базе данных и избегания запросов в цикле. Поэтому вопросы оптимизаций больших запросов стоят особняком при анализе проблем производительности, как в процессе разработки типовых и отраслевых решений, так и в процессе эксплуатации на крупных внедрениях.

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

Сложности при получении полного текста пакетного запроса

Запрос в 1С может содержать в себе несколько пакетов с созданием промежуточных временных таблиц и их дальнейшим использованием в последующих пакетах. При этом в событии лога технологического журнала DBMSSQL или DBPOSTGRS в свойстве SQL видно только часть этого самого пакетного запроса. Это происходит из-за того, что на каждый запрос в пакете будет зафиксировано отдельное событие в логе технологического журнала.

Чтобы иметь возможность получить текст запроса в терминах СУБД соответствующий исходному тексту выполняемого пакетного запроса в 1С, необходимо собрать все связанные между собой события обращения к базе данных относительно текущего, выстроить их в правильном порядке, а также провести дополнительные преобразования, чтобы иметь возможность выполнить такой запрос непосредственно в СУБД. При этом исходная точка поиска связанных событий должна быть любой — будь то событие DBMSSQL или DBPOSTGRS соответствующее созданию временной таблицы в середине пакетного запроса или же аналогичное событие, соответствующее финальной выборке данных в этом же запросе.

Рассмотрим следующий пример:

Текст запроса из технологического журнала 1С

Видим, что текст запроса из технологического журнала 1С делает вставку во временную таблицу tt26, используя при этом данные временных таблиц tt24 и tt25. Поэтому нам необходимо найти текст запроса создания и вставки данных в вышеуказанные временные таблицы. Если же они также используют другие временные таблицы, то их тоже и так далее. Также таблица tt26 может быть источником данных для вышестоящих запросов. Соответственно, чтобы нам увидеть полный текст пакетного запроса, необходимо получить тексты всех участвующих в нем одиночных запросов.

Чтобы реализовать такую математику, необходимо построить граф зависимостей запросов.

В решении «1С‑Рарус: Мониторинг производительности» мы загружаем накопленные логи технологического журнала 1С в специальную таблицу в СУБД ClickHouse. Подробней о концептуальной схеме решения мы рассказывали в первой части статьи. Такой подход позволяет выстроить граф зависимостей путем выполнения нескольких запросов к таблице ClickHouse с загруженными в нее логами, накладывая соответствующие отборы. Идея состоит в том, чтобы от исходного текста запроса, от которого мы запустили функцию восстановления, а также для всех последующих найденных текстов запросов реализовать следующий поиск:

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

    SELECT TOP 1
    _time,
    sql
    FROM
    default.chesdm_mon_demo_stand
    WHERE
    _time < '<Время текущего запроса>'
    AND dbpid = '<Идентификатор текущего соединения с СУБД>’
    AND sql LIKE '%CREATE TABLE #<Имя временной таблицы> %'
    ORDER BY
    _time DESC
  • Если создание временной таблицы было не в текущем сеансе, необходимо найти последнюю очистку временной таблицы до текущего запроса в рамках того же соединения с базой данных для ее использования в текущем запросе.

    Чаще всего, если 1С видит, что временная таблица с такой же структурой колонок, которая нужна в текущем сеансе уже создана, то она просто очищает ее при помощи TRUNCATE и использует не пересоздавая. Такое поведение технологической платформы 1С сделано для оптимизации количества созданий новых временных таблиц и его стоит учитывать при поиске.

    Найденный TRUNCATE будет сигнализировать о начале жизненного цикла временной таблицы для текущего пакета. Схематично запрос к ClickHouse будет следующим:

    SELECT TOP  1
    _time,
    sql
    FROM
    default.chesdm_mon_demo_stand
    WHERE
    _time < '<Время текущего запроса>'
    AND dbpid = '<Идентификатор текущего соединения с СУБД>’
    AND sql LIKE 'TRUNCATE TABLE #<Имя временной таблицы> '
    ORDER BY
    _time DESC
  • Далее нам необходимо найти все вставки во временную таблицу, которые происходили от момента последней очистки:

    SELECT 
    _time,
    sql
    FROM
    default.chesdm_mon_demo_stand
    WHERE
    _time BETWEEN '<Время последней очистки>' AND '<Время текущего запроса>'
    AND dbpid = '<Идентификатор текущего соединения с СУБД>’
    AND sessionid = '<Идентификатор сеанса>'
    AND sql LIKE 'INSERT INTO #<Имя временной таблицы> '
    ORDER BY
    _time
  • Далее, если текущий запрос — это временная таблица, то также необходимо найти все запросы в том же сеансе, в которых используется текущая временная таблица как источник данных и эти запросы выполнены после инициализации исходной временной таблицы:

    SELECT
    _time,
    sql
    FROM
    default.chesdm_mon_demo_stand
    WHERE
    _time > '<Время текущего запроса>'
    AND dbpid = '<Идентификатор текущего соединения с СУБД>’
    AND sessionid = '<Идентификатор сеанса>'
    AND sql LIKE ' %#<Имя временной таблицы> %’
    ORDER BY
    _time
  • Все найденные запросы добавляются в граф.
  • Алгоритм повторяется для каждого найденного запроса.

Вышеописанный алгоритм автоматизирован в решении в виде специального шага обработки строки расшифровки диаграммы. О его применении мы поговорим чуть ниже, а пока рассмотрим концептуальный пример, демонстрирующий работу данного шага.

Предположим, у нас есть проблемный запрос, который представляет из себя вставку во временную таблицу tt32 используя данные таблицы tt31:

Алгоритм запроса

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

Алгоритм запроса

Далее, найдем последнюю очистку временной таблицы tt32 (операция TRUNCATE):

Алгоритм запроса

Аналогично ищем создание и очистку временной таблицы tt31:

Алгоритм запроса

Найдем все вставки во временную таблицу tt31 с момента ее последней очистки (операция TRUNCATE):

Алгоритм запроса

Производим поиск использований таблицы tt32 далее по оси времени в других запросах, но не позднее ее очистки:

Алгоритм запроса

Видим, что был найден запрос на выборку данных из таблицы tt32, однако, он также использует данные другой временной таблицы tt25. Соответственно, строим аналогичную цепочку для таблицы tt25:

Алгоритм запроса

Видим, что временная таблица tt25 использует данные таблиц tt24 и tt23. Производим поиск для них:

Алгоритм запроса

В конечном итоге, по одному запросу мы нашли еще 15 запросов, которые выполняются в одном и том же пакете. Остается выстроить все узлы данного графа в хронологическом порядке и собрать все тексты воедино.

Однако, выполнить такой запрос непосредственно в СУБД все еще не получится. Чтобы полученный текст запроса был полностью готов к исполнению в MS Management Studio или psql необходимо произвести еще несколько действий:

  • Удаление временных таблиц после выполнения запроса:

    Алгоритм запроса

  • Замена имен временных таблиц для исключения пересечения их имен с уже существующими в системе таблицами:

    Алгоритм запроса

  • Подмена параметров в текстах запросов MSSQL с вопросительных знаков на значения параметров, которые фиксируются сразу после окончания текста запроса в свойстве SQL события DBMMSQL.

До преобразования в логах ТЖ события DBMSSQL видим знаки вопроса вместо значения параметров и сами значения записаны в конце свойства sql:

Текст запроса SQL

При таком тексте мы не сможем выполнить его напрямую в СУБД. Поэтому преобразуем и получаем следующий текст:

Текст запроса SQL

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

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

Тестовая информационная база и пакетный запрос на 7448 строк

При рассмотрении данного случая мы не будем использовать информационные базы с крупных внедрений, так как это не является значимым в контексте демонстрации работы функции сбора полного текста запроса в исследуемой информационной базе. Важным фактором является наличие в системе больших многокомпонентных запросов с большим количеством временных таблиц. Поэтому в качестве информационной базы, которая подвергается мониторингу, будем рассматривать демо-базу «1С:Управление предприятием общепита», в частности механизм формирования целевых документов по чекам общепита.

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

Пакетный запрос

Данный запрос состоит из 94 пакетов. Для отладки этого запроса в свое время был написан специальный инструмент, который выгружает результат выполнения вместе со всеми промежуточными таблицами в Excel. Мы не будем касаться деталей реализации вышеописанного запроса, так как это тема для отдельной статьи. Следите за обновлениями на сайте rarus.ru в разделе от экспертов.

Однако, что если нам необходимо получить план данного запроса, который СУБД использовала в момент его долгого выполнения на продуктивном контуре? Давайте посмотрим, как это можно сделать при помощи «1С‑Рарус: Мониторинг производительности».

Получаем полный текст пакетного запроса в Мониторинге производительности

О том, как настраивать сбор и отправку логов технологического журнала 1С на стороне продуктивного сервера, а также как настроить получение и обработку логов на стороне «1С‑Рарус: Мониторинг производительности» мы рассказали во второй части статьи.

Повторив действия, описанные ранее, только для демо‑базы «1С:Управление предприятием общепита», мы будем иметь доступ к данным по данной базе в универсальной доске эксперта производительности:

Диаграммы

С подробным описанием диаграмм на данной доске можно ознакомиться в первой части статьи.

Для воспроизведения ситуации, выполним создание целевых документов по чекам общепита на демо-данных:

Справочник «Создание целевых документов по чекам Общепита»

Сигналом об успешно выполненном создании целевых документов будет являться вывод специального отчета:

Список обработанных документов

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

Диаграмма «Универсально. События CALL дольше N секунд»

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

Расшифровка события

Однако, при помощи специальной функции обработки строки в «1С‑Рарус: Мониторинг производительности» мы можем получить состав событий найденного клиент-серверного вызова, которые уже будут содержать в себе контекст:

Шаг обработки текущей строки

Получим топ-100 событий найденного вызова, отсортированных по длительности. В полученной расшифровке нас будет интересовать время между событиями и контекст:

Результаты событий

Видим, что самое длительное событие, зафиксированное за время вызова, было запросом со вставкой данных во временную таблицу:

Вывод Значения

При этом по контексту понятно, что это тот самый пакетный запрос получения данных для создания целевых документов, о котором упоминалось ранее:

Вывод Значения

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

Вывод Значения

В итоге получим готовый текст для его выполнения на стороне СУБД по алгоритму, описанному ранее. Все выполняется автоматически, никаких дополнительных действий со стороны пользователя «1С‑Рарус: Мониторинг производительности» производить не требуется:

Вывод Значения

Ознакомиться с полным текстом собранного запроса можно по ссылке.

Для демонстрации работоспособности запроса попробуем получить его план. Выполним запрос в консоли MSSQL Management Studio с опцией «Include actual query plan»:

Выполним запрос в консоли MSSQL Management Studio с опцией «Include actual query plan»

Как видим, пакетный запрос выполняется. Все что остается сделать, это на вкладке Execution plan найти нужный нам запрос по части текста запроса и посмотреть его план.

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

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

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

Вы читаете статью из рубрики:
От экспертов «1С-Рарус»

Есть вопросы по статье? Задайте их нам!

Рассылка «Новости компании»: узнавайте о новых продуктах, услугах и спецпредложениях

Посмотреть все рассылки «1С‑Рарус»

Поле не должно быть пустым
Электронная почта указывается только латиницей, обязательно должен присутствовать знак @, доменное имя не может быть короче двух символов

Посмотреть все рассылки «1С-Рарус»

Иконка «Предупреждение» Отправляя эту форму, Вы соглашаетесь с Политикой конфидециальности и даете согласие на обработку персональных данных компанией «1С-Рарус»

Заинтересованы в сотрудничестве?
Нужна консультация?
Свяжитесь с нами!