Эффективное использование журнала регистрации и технологического журнала 1С в решении вопросов производительности

Эта статья носит своей целью продемонстрировать другой подход в анализе проблем производительности в системах 1С:Предприятие с применением технологического журнала (ТЖ) и журнала регистрации (ЖР).

Напомню, что ЖР логирует действия пользователей — кто, когда в каком объекте внес изменения, с какого компьютера, каким сеансом и т. п. ТЖ — это средство для логирования уже самой платформы. Он может регистрировать огромное количество событий платформы: ошибки, управляемые блокировки, взаимодействие с СУБД, утечки памяти и многое другое. По умолчанию включен, но настроен на минимальный сбор дампов. А его неправильная/неосторожная настройка очень быстро приводит к распуханию логов — они занимают десятки и сотни гигабайт, и свободное место на диске (а по умолчанию это системный диск) не менее быстро заканчивается. Стоит заметить, что размер ТЖ обычно затрудняет его анализ и затягивает процесс.

Для расследования проблем производительности информация из журналов очень полезна, и пользуются ими чуть меньше, чем все. Создано множество средств для парсинга и визуализации записей ТЖ и ЖР. Но хочу отметить интересный факт, думаю, вы согласитесь с ним, что при расследовании инцидентов по производительности (не действий пользователей) весь массив данных журналов не нужен, а нужная информация занимает от силы 1% от общего объема. И основное время уходит на ее поиск, сопоставление с другими метриками и счетчиками мониторинга. Как не крути, а чтобы перелопатить гигантские ТЖ от разных rphost»ов, сопоставить данные, сессии с данными от sql‑сервера, включая трассы — это довольно кропотливая работа, отнимающая немало времени. У кого‑то процесс займет десятки минут, у кого‑то часы.

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

Вот! В этом как раз вся «соль» идеи.

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

Начнем с этого журнала. Поскольку мониторинг Perfexpert изначально содержит информацию по длительному выполнению сеансами 1С своих операций (фоновые задачи, регламенты, расчеты пользователей) в режиме реального времени, то целесообразно именно для этих ситуаций анализировать ЖР, и дополнять картину происходящего сведениями из ЖР. Таким образом получается огромная экономия времени по анализу происходящего в вашей информационной системе. Для любых выполняемых операций вы видите в мониторинге почти в режиме реального времени (задержка до 1 минуты) выполняемую бизнес‑логику в произвольный период времени.

В окне с сессиями 1С можно отсортировать данные по «Врямя вызова текущее» и сразу увидеть сессии, которые интересны для анализа — на рисунке первые две строчки, выделенные желтым.

Ячейка с данными журнала регистрации кликабельна и выбранную сессию пользователя/фонового задания можно открыть в собранном журнале и посмотреть детали:

Еще раз акцентирую внимание, что в мониторинг попадает не весь(!) ЖР, а только события, которые потенциально могут быть полезны при расследовании проблем производительности. Отбирается информация по сеансам 1С, которая уже есть в мониторинге и как фильтр накладывается на ЖР.

Довольно распространенный подход для оптимизации/ускорения обработки ЖР — это загнать его в отдельную внешнюю БД (я не про SQlite) или, например, разместить на RAM‑диске. Но в любом случае сам подход к обработке его записей не меняется — берутся ВСЕ записи, дальше фильтруются, группируются, сопоставляются и т. д. А в Perfexpert реализован другой подход — из исходного ЖР изначально подгружаются только те записи, которые при расследовании инцидентов производительности могут быть интересны как администраторам, так и разработчикам 1С.

Без этой возможности PerfExpert вам необходимо потратить время на выяснение нужного сеанса 1С или группы сеансов, определить временной интервал происходящих инцидентов, осуществить поиск по данным ЖР даже с учетом его линейного ускорения. И самое главное, необходимо повторять эти работы для разных временных периодов. По грубой оценке — это уже десятки минут. Имея все данные уже рассчитанными в мониторинге, вы тратите секунды на понимание происходящего.

Технологический журнал

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

Perfexpert и ранее собирал информацию об управляемых блокировках, но она носила больше количественный характер с подсказками кого искать. А чтобы узнать «где/в каком модуле» эта блокировка накладывается (интересует участок кода), нужно сначала найти по PID и времени блокировки правильный файл ТЖ, соответствующий нужному rphost, далее отфильтровывать в нем данные по сеансу и пользователю, и после этого вытащить из них контекст 1С.

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

Поэтому аналогично ЖР мониторинг парсит на лету еще и файлы ТЖ, собирает все события TLOCK длительностью более 200 мс (настройки в logcfg.xml.). При этом на счетчиках мониторинга отображаются только длительные блокировки, попавшие в 10 секундный интервал опроса сервера 1С.

То же самое, только покрупнее:

Ссылки, как и в случае с ЖР, кликабельны, можно открыть собранный ТЖ с фильтрацией по нужному событию:

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

Итого, что на выходе

Осуществляя «на лету» парсинг как ЖР, так и ТЖ, мониторинг сразу накладывает эти данные на остальные свои счетчики. Тем самым на порядок повышается эффективность расследования инцидентов и оптимизации. Вместо нескольких инцидентов в день можно разобрать в разы больше и минимизировать срок простоев системы. Что, в свою очередь, позволит правильно и оперативно принимать управленческие решение по восстановлению работоспособности и улучшению производительности.

В качестве спойлера

В будущих релизах мониторинга Perfexpert запланировано отображение информации из ЖР и ТЖ также и в трассах sql‑сервера. Информация ведь уже есть, собрана. Можно будет с гораздо большей точностью сопоставить sql‑запрос с операциями в информационной системе, а ошибки — с данными технологического журнала.

Кроме того, функционал с ЖР и ТЖ уже готовится к переносу на редакцию мониторинга для PostgreSQL.