Всем привет! Очередная статья на тему «как мы улучшаем производительность». В данной статье я хочу показать, каким образом можно найти проблемы производительности и понять их причины, имея под рукой голую 1С, 2 руки и текстовый редактор.
0. Описание проблемы:
Итак, задача: наш сырный клиент, 1С:Молокозавод (на основе УПП 1.3), платформа 8.3.8, уровень изоляции транзакций Read committed snapshot . Множество ошибок превышения времени ожидания предоставления блокировки, взаимоблокировок. Особенно во время обменов данными по web-сервисам с некой WMS-системой. Клиент точно не может сказать, в какое время дня возникают проблемы. 1С:ЦУП отсутствует, к тому же, сбор данных ЦУП не желательно запускать более чем на 20 минут, т.к. замедляется работа исследуемой базы и сильно растёт файл данных для анализа, а мы не знаем, когда же нам поймать эти «20 минут». Поэтому мы будем использовать технологический журнал 1С.
1. Настройка технологического журнала
Для тех, кто не знает, на сервере 1С можно настроить логирование многих событий. Создаём специальный конфигурационный xml-файл, помещаем в папку conf сервера и сервер начинает запись логов. Подробнее останавливаться на этом не буду – в моём первом и втором «пятничном» вебинарах я подробно рассказывал о настройке технологического журнала 1С. Итак, включаю технологический журнал (далее – ТЖ) со следующими отборами: отбор по информационной базе, отбор по следующим событиям:
- EXCP – все исключительные ситуации, возникающие в работе исследуемой базы
- DBMSSQL — исполнение операторов SQL СУБД Microsoft SQL Server. Также, ставлю отбор на параметр «lkp» = 1, означающий, что процесс ожидал предоставления блокировки.
- TLOCK -управление транзакционными блокировками в управляемом режиме. Также, ставлю отбор на «WaitConnections» <> «», что означает, что процесс ожидал предоставления управляемой блокировки
- TTIMEOUT — превышение максимального времени ожидания транзакционной блокировки.
- TDEADLOCK – обнаружена взаимоблокировка в управляемом режиме.
События TTIMEOUT и TDEADLOCK появились только в версии 8.3.7 платформы.
Итак, запускаем сбор логов, ставим ограничение, скажем, на 48 часов – платформа будет хранить логи за последние 48 часов.
2. Анализ логов технологического журнала
Через день я начал смотреть, что же у нас получилось:
С 8 до 9 утра было зафиксировано множество событий TDEADLOCK, TTIMEOUT, TLOCK, EXCP.
Пару слов о механизме управляемых блокировок:
С версии платформы 8.1 у нас появился режим управления блокировкой данных «управляемый»
К механизму блокировок СУБД добавляется механизм блокировок на сервере 1С. Блокировки мы можем ставить руками в коде с помощью объекта «БлокировкаДанных», также управляемая блокировка автоматически ставится при любой записи и при чтении данных в объектной технике, т.е. не запросом, а при получении каких-то данных в коде. Подробнее о механизме блокировок 1С можно я рассказывал здесь и здесь.
Теперь давайте разберем события ТЖ подробнее. EXCP:
События EXCP были следующего вида:
EXCP,Usr=АдминистраторWMS,Descr='Конфликт блокировок при выполнении транзакции: Превышено время ожидания запроса на блокировку. ',Context=' WebСервис.ax_Exchange.Модуль : 1151 : ВыполнитьОтложенноеПроведениеДокумента(стрДок);
Ещё одно исключение для примера:
EXCP,Usr=АдминистраторWMS,Descr='Конфликт блокировок при выполнении транзакции: Неустранимый конфликт блокировок',Context=' WebСервис.ax_Exchange.Модуль : 1151 : ВыполнитьОтложенноеПроведениеДокумента(стрДок);
Я немного упростил лог. По этим строчкам видно, что возникали таймауты и дедлоки под пользователем АдминистраторWMS, в контексте отложенного проведения документов.
В нашей статье разберем взаимоблокировку. Смотрим событие TDEADLOCK:
TDEADLOCK,Usr=АдминистраторWMS,DeadlockConnectionIntersections='2896 2894 Seq31427.DIMS Exclusive Fld31428=79:a0b0000c6eb6752411db283f6c576d63,2894 2896 AccRg14235.DIMS Exclusive Account=4:80669393ef352fcb42964c7f786c877d Correspond=0 ExtDimension1=71:818b005056c0000811e2a819ec1a1fc2 ExtDimension2=114:a23600259037056711e2395da86502e1 Fld14236=79:a0b0000c6eb6752411db283f6c576d63 Fld14237=Null Period=[T"20160801000000":+] Splitter=0',Context=' WebСервис.ax_Exchange.Модуль : 1151 : ВыполнитьОтложенноеПроведениеДокумента(стрДок); WebСервис.ax_Exchange.Модуль : 3068 : Объект.Записать(РежимЗаписиДокумента.Проведение);'
Давайте разбирать этот жуткий текст. Взаимоблокировка, тот же пользователь АдминистраторWMS, далее идет информация о 2х блокировках, на которых и возник конфликт.
- 2896 2894 Seq31427.DIMS Exclusive Fld31428=79:a0b0000c6eb6752411db283f6c576d63
- 2896 – соединение, ожидающее блокировку
- 2894 – соединение, установившее блокировку
- SeqDIMS заблокированный ресурс. Имя таблицы начинается на Seq, значит это последовательность. Обработкой «Структура БД» по имени таблицы мы можем найти, какая именно последовательность.
- Exclusive – это тип блокировки «исключительная», такая ставится при записи
- Fld31428=79:a0b0000c6eb6752411db283f6c576d Сама блокировка на поле Fld31428. Это поле тоже можно «расшифровать в обработке «Структура БД»
- 2894 2896 AccRg14235.DIMS Exclusive
- Те же 2 сеанса, только наоборот. 2896 установил блокировку, 2894 – ожидает
- AccRgDIMS Exclusive. Эксклюзивная блокировка на таблице AccRg14235. Это РБ Хозрасчетный.
Итак, типичный случай взаимоблокировки «захват ресурсов в разном порядке». 1 сеанс заблокировал последовательность и ждет Хозрасчетный, второй сеанс заблокировал Хозрасчетный и ждет последовательность.
Теперь по номерам сеансов и датам событий мы найдем события TLOCK и посмотрим более детально, что происходило в каждом из этих сеансов.
TLOCK, t:connectID=2896,Usr=АдминистраторWMS,Locks='Seq31427.DIMS Exclusive Fld31428=79:a0b0000c6eb6752411db283f6c576d63',WaitConnections=2894,Context=' WebСервис.ax_Exchange.Модуль : 1151 : ВыполнитьОтложенноеПроведениеДокумента(стрДок); WebСервис.ax_Exchange.Модуль : 3068 : Объект.Записать(РежимЗаписиДокумента.Проведение);'
TLOCK, t:connectID=2894,Usr=АдминистраторWMS,Locks='AccRg14235.DIMS…',WaitConnections=2896,Context=' WebСервис.ax_Exchange.Модуль : 1151 : ВыполнитьОтложенноеПроведениеДокумента(стрДок); WebСервис.ax_Exchange.Модуль : 3068 : Объект.Записать(РежимЗаписиДокумента.Проведение); Документ.ОтчетПроизводстваЗаСмену.МодульОбъекта : 3634 : ОбщегоНазначения.УдалитьДвиженияРегистратора(ЭтотОбъект, Отказ); ОбщийМодуль.ОбщегоНазначения.Модуль : 5495 : УдалитьЗаписанныеДвиженияДокумента(ДокументОбъект, Отказ, ВыборочноОчищатьРегистры, РежимПроведенияДокумента); ОбщийМодуль.ОбщегоНазначения.Модуль : 5610 : ПолныеПрава.ЗаписатьНаборЗаписейНаСервере(ИмяРегистра, ДокументОбъект.Ссылка,, ТипРегистра); ОбщийМодуль.ПолныеПрава.Модуль : 1283 : Набор.Записать();'
Это 2 события TLOCK, на которых были ожидания блокировок. Мы видим наши номера сеансов connectID, а также WaitConnections – номера сеансов, которых ожидали. И контексты. В одном случае идет запись данных при проведении, а в другом – удаление записанных движений в начале проведения.
Проблему обнаружили. Теперь подумаем, что можно сделать для её решения и почему вообще она возникла.
Во-первых, и сеансы-виновники и сеансы-жертвы – это обмен с системой WMS. Таким образом получается, что обмен с WMS может проходить одновременно в несколько сеансов. Если по бизнес-логике в этом нет необходимости, можно исключить возможность параллельных обменов.
Во-вторых, блокировка при записи РБ Хозрасчетный. Даже если запись идет по одному набору измерений, ожиданий быть не должно, если включен режим разделения итогов.
Как видим, режим разделения итогов выключен. Необходимо включить.
И в-третьих, блокировка на последовательности при записи возможна только на одинаковом наборе измерений последовательности и если граница смещается при проведении. Находим нашу последовательность и смотрим свойства:
У данной последовательности 1 измерение «Организация». Соответственно, все документы, которые участвуют в последовательности, пытаются двигать её границу при проведении и ждут друг друга. Типовые последовательности двигают границу только назад, а вперед граница двигается специально обученной обработкой. В нашем случае необходимо анализировать логику работы и отказаться от оперативного перемещения границы, если есть такая возможность.
Остальные проблемы, а также настройку и работу с ТЖ смотрите на наших вебинарах.
Спасибо за внимание 🙂
События TTIMEOUT и TDEADLOCK появились только в версии 8.3.7 платформы?
разве не в 8.2.14?
В версии 8.3.7: Ссылка.
по ссылке 8.2.14, на практике в 8.3.1 уже работает описанное выше
Огромное спасибо! Статья очень помогла, тоже был затык между Последовательностью и Регистром бухгалтерии
Добрый день! В Вашем примере есть блокировка по полю Fld31428=79:a0b0000c6eb6752411db283f6c576d. Подскажите, пожалуйста, как по этой записи определить ссылку на объект? 79:a0b0000c6eb6752411db283f6c576d это же не ГУИД, правильно?