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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

• Серия = «Контекст».
• Значение = «Количество».
• Вид диаграммы = «Круговая».

• Период — возьмем близкий к дате сообщения об отказе в доступе в журнале регистрации +/- пару секунд:

  

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Далее формируем специальный текст запроса к базе 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)» и нажимаем кнопку «Обработать»:

В результате получаем таблицу ближайших событий. По центру, как и предполагалось, исходный запрос на 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 секунд:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Видим, что текст запроса из технологического журнала 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:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Скачать Пример полного текста пакетного запроса

28.11.2024 TXT, 571.92 КБ

Скачать

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

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

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

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

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