Графическое представление технологического журнала, или Гант наглядности

Технологический журнал 1С, в дальнейшем ТЖ, представляет собой набор текстовых файлов, структурированных определённым образом. В дальнейшем будем иметь дело с одним файлом. Даже один файл, собираемый в варианте полного ТЖ (все события, но без специфических свойств), может занимать десятки гигабайтов.

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

Выберем из ТЖ события: SDBL, DBMSSQL, TLOCK, TDEADLOCK, TTIMEOUT. Сделать это можно либо посредством соответствующей настройки файла logcfg.xml, либо, обработав полный ТЖ скриптом, к слову, скриптами воспользоваться всё равно пришлось, хотя бы для того, чтобы привести файл ТЖ к виду, когда каждое событие занимает одну строку.

Итак, как же изобразить полученный ТЖ?

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

Так выглядит ТЖ, собранный при выполнении нагрузочного тестирования.

Немного о том, как эта диаграмма была построена. Анализом ТЖ занимался код, написанный на python, а непосредственная визуализация была доверена одной из его библиотек - plotly.

Почему plotly?

Главным образом потому, что она интерактивна, позволяет масштабировать диаграмму.

Получаем выделенный фрагмент.

Что же из этого можно понять?

Договоримся об обозначениях. Рассмотрим одну транзакцию одного пользователя.

Как видно, состояние одного пользователя характеризуется двумя линиями (прямоугольниками) верхней и нижней. Нижняя показывает транзакцию, как правило она зелёного цвета, верхняя – ожидание (жёлтого или оранжевого цвета, в зависимости от того, дождались или нет) или выполнение запроса (синего цвета).

Рассмотрим фрагмент диаграммы

Транзакция выделяется жёлтым цветом, если она является виновником ожидания. Хорошо видно, что в момент времени, когда закончилась «жёлтая» транзакция, закончилось ожидание в транзакции пользователя Админ_ТЦ0000004_1482. Кроме свойства интерактивности библиотека plotly позволяет передавать произвольные данные в диаграмму, а после просматривать, наведением курсора на заинтересовавшую линию (событие). Для ожидания имеет смысл анализировать заблокированный ресурс и пользователя, чья транзакция его держит, что и отражено на представленной выше диаграмме.

Итак, посчитав количество «жёлтых» транзакций, получаем представление о количестве ожиданий на управляемых блокировках в системе.

Аналогичным образом дело обстоит с таймаутами с той лишь разницей, что ожидание не дождавшейся ресурса транзакции оранжевого цвета, как и транзакция-виновник.

Транзакция-жертва заканчивается вместе с прерванным ожиданием.

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

Для анализа запросов, кроме контекста, отображается длительность.

Обратимся к диаграмме ТЖ реальной базы, на качество работы которой есть жалобы со стороны пользователей.

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

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

За что зацепиться?

Просто просматривать контексты всех запросов довольно бессмысленное занятие, хотя и не отнимающее много времени. Но всё-таки есть несколько вещей, обращающих на себя внимание.

Во-первых, работа пользователя _93 (в красном прямоугольнике). Необычно то, что действия почти регулярны, и несмотря на то, что пунктиры выглядят маленькими, в действительности их длительность варьируется от 1,5 до 7 секунд, и кроме того, все эти события имеют схожий контекст.

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

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

Однако, вот что интересно, если подвергнуть файл ТЖ анализу скриптом, то результат будет выглядеть так:

Эти контексты уже попадали в поле нашего зрения…

Возможен и иной взгляд в рамках графической парадигмы. Будем отображать только событие DBMSSQL, но раскрашивать станем в соответствии с контекстом таким образом, что контекст первой в рейтинге суммарной длительности будет красный, второй – оранжевый, третий – зелёный, четвёртый – синий, пятый – фиолетовый, а все прочие контексты будут отмечены чёрным.

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

Этим вариантом графический подход не исчерпывается. В ТЖ ещё много событий, на которые было бы интересно посмотреть в развёрнутом во времени виде.

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