Водопад из Техжурнала 1С

Публикация № 1350553

Администрирование - Производительность и оптимизация (HighLoad)

Технологический журнал техжурнал график оптимизация ускорение

Строим визуализацию в виде waterfall-графика по данным событий технологического журнала.

Коллеги, любите ли вы Технологический Журнал Платформы 1С так, как люблю его я? Нет, я серьезно. Согласитесь, бесценный инструмент! Написано о нем уже немало и, казалось бы, добавить нечего. Рассказаны и показаны все способы работы с Техжурналом. Но я всё-таки попробую продемонстрировать еще один способ анализа.


Задача
 

Для примера предлагаю считать что мы анализируем длительную транзакцию при проведении документа. Уже собраны события DBMSSQL, содержащие все запросы, выполнявшиеся в рамках одного сеанса и одного серверного вызова. Найдено начало транзакции (Sql='... BEGIN TRANSACTION'), конец транзакции (Sql=COMMIT TRANSACTION). Всё лишнее, выполнявшееся до начала и после окончания интересующей транзакции, отброшено. Имеем несколько тысяч записей. Нужно понять, есть ли какие-то длительные запросы, которые можно оптимизировать. Или множество одинаковых запросов, говорящих о том, что выполняются в цикле. Или большие паузы между запросами, что может говорить о длительной передаче параметров или результата запроса, а также ожиданиях управляемых блокировок или выполнении кода 1С.

Самый первый взгляд на наличие длительных событий я обычно бросаю в Notepad++, выделив событие цветом (просто щелкнув на нем или присвоив стиль). Какое-то представление этот метод дает, но, согласитесь, он не очень-то информативен. Длительность, отличающаяся на порядок, будет на одну цифру длиннее. Заметить это глазами при пролистывании простыни текста, конечно можно, но достаточно сложно. Особенно с учетом 15-миллисекундных «всплесков» (о них чуть ниже, под спойлером).

 

 
 Про 15-миллисекундные всплески длительности

"Всплески" длительности, которые можно наблюдать в технологическом журнале для событий, обычно выполняющихся единицы или десятки микросекунд, всегда приблизительно равны 15-ти миллисекундам. Они могут быть чуть-чуть короче или чуть-чуть дольше, как видно на скриншоте выше, но всегда находятся в рамках 14-16 мс.
На самом деле эти события не выполняются дольше других. 15 миллисекунд - это дискретность используемого для технологического журнала счетчика времени в операционной системе Windows.
Механизм получения отметки времени для технологического журнала базируется на системном счетчике времени, значение которого изменяется с интервалом примерно 15 миллисекунд, и обеспечивает возрастающую последовательность отметок увеличением каждой следующей отметки времени на одну микросекунду от предыдущей.
На Linux используется другой метод (clock_gettime).
Источник: Партнерский форум


Я уже слышу, как некоторые из читателей хотят напомнить мне о том, что для подобных задач прогрессивные 1С-ники используют утилиты BASH, скрипты на Perl и прочие инструменты для обработки текстовых данных. Не сомневайтесь - всё это используется в полной мере. Но всё же обнаруженные таким образом длительные события не дают достаточно четкого понимания ситуации. Например, при такой выборке не видно окружения этих запросов, не видно собраны ли они в одном месте или разбросаны по коду, не видно пауз между запросами.

 
 bash-команда для выборки из общего файла только событий, длительностью более чем...

Пример получения из ТЖ списка событий, длительность которых превышает... Нет, не секунд и не микросекунд, а количество разрядов (цифр) в строке длительности. В примере - минимум 7 знаков, что соответствует длительности более 1 секунды.

cat КакойТоОбщийФайлСКучейСобытий.txt | \
grep -E -a "[0-9]{7,},"  \
> СобытияДольшеСекунды.txt


Каждый раз при анализе Техжурнала, меня посещала мысль: "Вот бы было здорово, если бы можно было визуально проанализировать последовательность событий ТЖ, так же как это доступно веб-разработчикам в браузерах". Но чего нет, того нет. Разработчики Платформы такого инструмента не предлагают. И о сторонних разработках в этом направлении я ничего не слышал.

Тем не менее, желание иметь такой инструмент обострялось у меня каждый раз, когда нужно было, например, проанализировать длительную транзакцию, выявить в ней аномально длительные запросы. А может быть вовсе и не запросы? Может быть это длительное получение результата запроса? Может быть это длительная передача параметров в запрос? Может быть это длительное ожидание установки управляемой блокировки? Может быть это выполнение какого-то кода сервером приложений в промежутке между запросами? То есть меня интересовало не только длительность самих событий (например запросов), но и время пауз между окончанием одного и началом следующего события.

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

Среди попыток было и построение графика с помощью Excel, и реализация с помощью диаграмм 1С. Но всё что пробовал, не устраивало качеством результата. Проблема в том, что событий в анализируемом периоде, составляющем всего лишь несколько секунд, обычно очень много – по несколько тысяч. Графики, сформированные испробованными способами, были либо нечитаемыми, либо просто не формировались из-за большого объема данных.

Браться за создание полноценного приложения, отрисовывающего всё так, как я представлял себе, не было ни желания, ни возможности. Хотелось получить график вот прямо такой же (или почти) как в Chrome. И не затратить при этом больших усилий.


Реализация
 

В процессе поисков решения выяснилось, что в браузерах есть возможность сохранить полученные данные трассировки для последующего анализа, в HAR-файл (HTTP Archive).

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

Ура! Решение, можно сказать, найдено! Получается, что можно трансформировать необходимые записи Техжурнала в формат HAR, и уже этот файл загрузить в какую-либо программу просмотра, или визуализатор (viewer).

Осталось дело за малым – понять как именно нужно сформировать HAR-файл.

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

Также, нашлась и XSD-схема формата, с которой можно было работать.

Очень кратко, формат основан на json и представляет собой описание событий http-сессии в текстовом виде. Набор параметров событий вполне подходит для задачи отображения событий Техжурнала.

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

В качестве инструмента для проведения своих опытов я выбрал расширение для Chrome "HTTP Archive Viewer". Для себя я счел удобным то, что окно расширения открывается отдельно от браузера, его можно расширить на весь экран, а также можно для этого веб-приложения создать ярлык как для обычного приложения. Весь код выполняется на клиентской стороне (javascript), без обмена с веб-сервером. Кроме того, существует возможность встраивания этого инструмента в свои решения (ссылки на документацию в конце статьи).

 
 Как сохранить ярлык веб-приложения

 На странице веб-приложения chrome://apps жмем правой кнопкой мыши на нужном приложении и выбираем "Создать ярлык..."


Теперь можно формировать свой файл. Принцип работы описывается буквально четырьмя пунктами:

•    Для каждой строки события вычисляем время начала события;
•    из XSD-схемы (которую всё-таки пришлось немного доработать) создаем XDTO пакет;
•    заполняем его разобранными данными Техжурнала;
•    выводим в json-формате.

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

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

Полученный json-текст копируем (или выгружаем-загружаем через файл) в HTTP Archive Viewer

Жмем "Load"...иииии... УРА! получилось!


Для дальнейшего анализа, события, которые вызывают особый интерес можно найти в файле ТЖ по подстроке "время-длительность".
 

Как использовать
 

События ТЖ должны быть склеены в одну строку. Любым способом. Я делаю это bash-командами.

 
 Пример bash-скрипта для вывода анализируемых событий, со склейкой строк

Пример конвейера bash-команд для поиска событий в архивированных файлах Техжурнала, с выводом каждого события одной строкой.
Значения OSThread, SessionID взяты из ранее найденного события длительной транзакции "SDBL,… ,Func=Transaction,Func=CommitTransaction".
Отбор по OSThread применен для того, чтобы собрать запросы, выполнявшиеся в рамках одного серверного вызова.

find /cygdrive/d/TechLogs*/ -regex ".*_DBMS_20201222_08.*\.zip" -print0 | \
xargs -0 -i -n 1 unzip -p {} '*/rphost*/*.log' 2>err.txt | \
awk -vORS= '{if(match($0, "[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print "<line>"$0;}' | \
grep -a ",DBMSSQL,.*OSThread=4768,.*SessionID=284752,"  \
> long_transaction_querries.txt

 

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

Можно отсортировать события по началу выполнения (в ТЖ они записаны в порядке окончания выполнения). Это может быть полезным, если выборка сделана не по одному типу события, а по нескольким. Например, события SDBL и DBMSSQL. В ТЖ событие SDBL, обрамляющее всю транзакцию, будет отображено последним, хотя началось первым.

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


Примеры
 

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

Пример множества (несколько тысяч) одинаковых запросов, выполняемых за микросекунды - явное свидетельство выполнения в цикле. Если просто сложить время выполнения этих запросов, скажем, с помощью bash-команды awk, получим совсем немного - миллисекунды. И ошибочно решим, что они не составляют большой проблемы. Но ведь эти запросы сначала компилируются, передаются в СУБД, для них получается план запроса, после выполнения возвращается результат, производится какая-то работа сервером приложений. За счет всего этого набегает совсем не мало времени. Если пролистать к началу и к концу этого блока запросов, можно убедиться что цикл выполнялся десятки секунд!

 

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

 

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

Маленький бонус
 

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

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

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


Заключение
 

Статья не преследует цели "раскрыть тему" или предоставить готовую инструкцию по анализу ТЖ. Это скорее описание еще одного варианта, представленное в виде прототипа. Тем не менее, прототип вполне работоспособный и регулярно используется мною в реальной работе по расследованию проблем производительности и оптимизации систем на Платформе 1С.

 

Приложенный файл обработки протестирован на версиях Платформы 8.3.14, 8.3.16


Ссылки
 

Описание формата:
https://w3c.github.io/web-performance/specs/HAR/Overview.html#sec-har-object-types-entry

XSD-схема:
http://www.softwareishard.com/har/schema/HTTPArchiveV12.xsd

Еще описание спецификации:
http://www.softwareishard.com/blog/har-12-spec/

Инструменты:
http://www.softwareishard.com/blog/har-adopters/

Embedding HAR Viewer
https://github.com/janodvarko/harviewer/wiki/Customization#har-preview-embedding

HAR Viewer API:
https://github.com/janodvarko/harviewer/wiki/API

 

Другие статьи автора
 

PID процесса в сборщиках PerfMon
Способы проверки доступности TCP-портов
Загрузка-выгрузка файлов по RDP с докачкой
Массовое изменение режима поддержки объектов конфигурации
GitSync 3.0. Шпаргалка по использованию
Проброс IP-адреса клиента в http-сервис 1С. Реализация для IIS
Автономный сервер. Часть 1 - новый вариант сервера
Автономный сервер. Часть 2 - утилита управления

Скачать файлы

Наименование Файл Версия Размер
Водопад из Техжурнала 1С:

.epf 12,21Kb
3
.epf 12,21Kb 3 Скачать

Специальные предложения

Комментарии
В избранное Подписаться на ответы Сортировка: Древо развёрнутое
Свернуть все
1. rst_filippov 41 23.12.20 23:50 Сейчас в теме
очень познавательно. Спасибо
2. SerVer1C 369 24.12.20 10:16 Сейчас в теме
Интересное решение! Плюсую.
3. mikl79 112 24.12.20 11:55 Сейчас в теме
Я к сожалению пока не использовал тех.журнал, все руки не доходят.
Хотелось бы его изучить.
4. malikov_pro 640 24.12.20 13:33 Сейчас в теме
При фромировании JSON через XDTO из XSD схемы в результирующем файле артефакты специфичные для XML присутствуют?
Использую по возможности JSON Schema, интересно на сколько схемы между собой совместимы и конвертируемы.
5. VKislitsin 616 24.12.20 13:50 Сейчас в теме
(4)
При фромировании JSON через XDTO из XSD схемы в результирующем файле артефакты специфичные для XML присутствуют?

Александр, нет никаких артефактов. Используем в ряде проектов формирование JSON из XDTO по XSD-схемам, гораздо более сложным чем эта.
Тут с другой проблемой столкнулся. Платформа некорректно создает ФабрикуXDTO из схемы в режиме выполнения (в отличие от ФабрикиXDTO по включенному в конфигурацию XDTO-пакету). Отправлял описание и конфу для воспроизведения в 1С, зарегистрировали ошибку. Но в письме ответили что не относят её к критичным, и когда устранят - неизвестно.
Оставьте свое сообщение

См. также

Еще один тест 1C: Postgres SQL 11 Pro Enterpise против MSSQL 14 под Windows 2012 Server R2 Промо

Производительность и оптимизация (HighLoad) v8 Абонемент ($m)

Проработав 15 лет с MSSQL в 2017 начал активно СУБД Postgres SQL. За два года успел поработать в 9 версии Postgres и в 10-ой. И пришел к выводу, что существуют реальное замедление работы баз после перехода на Postgres. Недавно вышла 11 версия Postgres Pro Enterpise, которая обещает почти 2-х кратное ускорение над 11 Pro Standart и 10-ой версией. Закупив лицензию Postgres 11 Pro Enterpise Это я и решил проверить на 1С.

1 стартмани

05.09.2019    16368    Indgo    107    

Zabbix: Мониторинг рабочих процессов

Zabbix v8 1cv8.cf Абонемент ($m)

Мониторинг памяти, потребляемой рабочими процессами, средствами Zabbix. Создание пользовательских LLD правил с помощью One Script

1 стартмани

07.02.2020    5694    EShchavleva    6    

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

Администрирование СУБД Нагрузочное тестирование Сервера v8 1cv8.cf Абонемент ($m)

Выполнил 3 разных теста для проверки серверного оборудования (тест 1С, тесты gilev) на возможное число 1С онлайн-пользователей одновременно работающих на нем и интерпретировал результаты тестов через легких, средних и тяжелых пользователей с помощью таблицы с профилями реальных пользователей.

3 стартмани

17.12.2019    12631    sapervodichka    3    

Кто круче: "ИЛИ" или "ОБЪЕДИНИТЬ ВСЕ" в запросе?

Производительность и оптимизация (HighLoad) v8 v8::СПР v8::Запросы ЗУП2.5 Абонемент ($m)

Реальный пример оптимизации запроса. Статья будет полезна людям, изучающим вопросы оптимизации запросов в 1С и для подготовки к экзамену "1С: Эксперт по технологическим вопросам", поскольку в статье описывается один их методов расследования причин неоптимальных запросов. UPD. Коллеги в комментариях заметили ошибку, она была исправлена и сейчас выложены данные с корректным решением.

1 стартмани

14.09.2019    5909    azazana    28    

Многопоточность. Универсальный «Менеджер потоков» (фреймворк) с отслеживанием зависимости объектов Промо

Практика программирования Математика и алгоритмы Универсальные функции Производительность и оптимизация (HighLoad) v8 1cv8.cf Россия Абонемент ($m)

Восстановление партий, расчет зарплаты, пакетное формирование документов или отчетов - теперь все это стало доступнее. * Есть желание повысить скорость работы медленных алгоритмов! Но... * Нет времени думать о реализации многопоточности? * о запуске и остановке потоков? * о поддержании потоков в рабочем состоянии? * о передаче данных в потоки и как получить ответ из потока? * об организации последовательности? Тогда ЭТО - то что надо!!!

26.05.2017    49999    DarkAn    86    

Менеджер потоков: реализация "любой" задачи в потоках

Производительность и оптимизация (HighLoad) Инструментарий разработчика v8 Абонемент ($m)

Менеджер потоков – один их новых инструментов, который упрощает работу разработчиков. Насколько легко с ним, на конференции Infostart Event 2018 Education показал начальник отдела автоматизации 1С Иван Филимонов компании «Трансстроймеханизация».

01.08.2019    10262    DarkAn    7    

Ловец дедлоков СУБД

Производительность и оптимизация (HighLoad) Практика программирования Разработка v8 Россия Абонемент ($m)

Анализ простейшего дедлока СУБД в рабочей базе с использованием ЦУП (центра управления производительностью) и profiler MS SQL (Microsoft SQL Server). Эта статья будет полезна людям, изучающим вопросы оптимизации работы 1С, или тем, у кого возникают дедлоки в рабочей базе. UPD 09.07.2019 добавлено воспроизведение блокировки в случае установки управляемой блокировки перед чтением набора записей регистра сведений. UPD 10.07.2019 добавлена тестовая база с примером.

1 стартмани

08.07.2019    11668    azazana    79    

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

Производительность и оптимизация (HighLoad) Практика программирования Разработка v8 Абонемент ($m)

Расскажем и покажем практически, как использовать искусственный интеллект на страже мониторинга производительности. У вас появится возможность создать собственного помощника Ларису, которая возьмет на себя вопросы по контролю и диагностике состояния обслуживаемой системы.

1 стартмани

01.07.2019    9685    ivanov660    28    

Заметочки про 1С:Предприятие 8 (редакция 22.06.2012) Промо

Производительность и оптимизация (HighLoad) Практика программирования v8 1cv8.cf Россия Абонемент ($m)

За время программирования на 8.х, накопилось пока немного материала, но как мне кажется очень интересного. Появились простые решения, которые в более сложной реализации встречаются в типовых конфигурациях и в некоторых публикациях на Infostart'е. Собственно в статье речь пойдет об этих решениях.

1 стартмани

01.06.2010    182787    alexk-is    413    

Короткое нагрузочное тестирование PostgreSQL простыми запросами

Производительность и оптимизация (HighLoad) v8::УФ Абонемент ($m)

Короткое нагрузочное тестирование PostgreSQL простыми запросами. Прилагаются результаты в файлах pgBadger и perfmon.

1 стартмани

10.12.2018    11192    vasilev2015    22    

PostgreSQL для 1С 8.3: ускоряем резервное копирование и восстановление для отдельной базы очень большого размера

Производительность и оптимизация (HighLoad) Тестирование и исправление v8 1cv8.cf Россия Абонемент ($m)

В этой статье разберем оптимизацию работы с моментальным снимком отдельной базы 1С в кластере PostgreSQL средствами pg_dump.exe, pg_restore.exe, psql.exe в среде Windows Server 2008,2012,2016. А также разберем проблемные ситуации и неожиданные ограничения при работе 1С в связке с PostgreSQL. Для Linux все аналогично.

1 стартмани

03.12.2018    29639    vsasav    69    

Скорость работы 1С8 файловой по сети

Производительность и оптимизация (HighLoad) v8 1cv8.cf Абонемент ($m)

Как я увеличил скорость работы файловой 1С8 по сети, изменив формат БД и размер страницы.

1 стартмани

01.11.2018    30136    Vlx    55    

Пересечение транзакций. Примеры

Производительность и оптимизация (HighLoad) v8 Абонемент ($m)

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

3 стартмани

03.09.2018    11013    vasilev2015    5    

Нагрузочное тестирование. В дни проведения ЧМ по футболу.

Производительность и оптимизация (HighLoad) v8 Абонемент ($m)

Нагрузочное тестирование. Подготовка к экзамену 1С:Эксперт. По мотивам доклада Виктора Богачева Инфостарт Event 2014. В дни проведения ЧМ по футболу.

1 стартмани

24.06.2018    10815    vasilev2015    9    

В «1С:ЗУП КОРП 3.1» тормоза (медленная работа) в журналах документов при использовании критериев отбора

Практика программирования Производительность и оптимизация (HighLoad) v8::Запросы ЗУП3.x Абонемент ($m)

Статья для тех, у кого: 1) используете RLS (ограничение доступа на уровне записей и полей), 2) много документов (более 100 тысяч в одном журнале), 3) используете «Журналы документов», 4) отборы в динамическом списке (по сотруднику). Скорее всего, Вы испытали на себе, как отбор происходит минутами (жутко тормозит) – тогда Вам сюда.

1 стартмани

04.01.2018    19077    Nykyanen    3    

1С:Предприятие 8.2. Управляемая Форма. Меняем иконку рабочего стола.

Сервисные утилиты Производительность и оптимизация (HighLoad) Практика программирования Работа с интерфейсом v8 1cv8.cf Россия Абонемент ($m)

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

1 стартмани

28.09.2012    29510    ghostaz    39