Анализ отсутствующих событий в технологическом журнале «1С» или лаги в технологическом логе

Авторы

Медленное формирование отчета о KPI в системе для финансового консолидированного учета
1. Инфраструктура исследуемой системы
Поиск причин медленного формирования отчёта
Применение анализа лагов в логах технологического журнала у клиента
Межсобытийные лаги для поиска проблем в коде

Медленное формирование отчета о KPI в системе для финансового консолидированного учета

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

«1С-Рарус» представляет собой группу компаний в разных городах и странах из различных часовых поясов. Вследствие этого структура подразделений весьма большая, работа ведется в режиме, близком к 24/7. При этом система не предназначена для ведения оперативного учета, поэтому количество пользователей не критическое, порядка 200 человек. Основную часть времени большинство пользователей системы, которые являются руководителями разных уровней, уделяют финансовому анализу, формированию управленческой отчетности и бюджетированию.

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

Инфраструктура исследуемой системы

Операционная система: Ubuntu 18.04.
База данных: Postgresql 11.8-5.1C.
Версия сервера «1C»: 8.3.16.1063.
Процессор: Intel(R) Xeon(R) CPU E5-2637 v2 @ 3.50GHz.
Оперативная память: 96 Гб.

Поиск причин медленного формирования отчёта

Мониторинг в Zabbix

Предположение о недостаточной мощности инфраструктуры отпало сразу, так как на сервере настроен мониторинг и сбор параметров производительности при помощи Zabbix. Мониторинг не показывал проседание ни по одному из контролируемых параметров ни в момент формирования отчета, ни в какие-либо другие моменты времени. Нагрузка на ЦП в момент формирования отчета:

и доступность ОЗУ:

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

В основе отчета лежат механизмы СКД со сложными сочетаниями агрегатных функций ВЫЧИСЛИТЬ
ВЫРАЖЕНИЕ() и ВЫЧИСЛИТЬВЫРАЖЕНИЕ
СГРУППИРОВКОЙМАССИВ(). В одной из следующих статей мы планируем рассказать о практике их применения в этом отчете, так как это заслуживает отдельного разговора.

Мониторинг средствами «1С»

Следующая самая простая идея — сделать замеры производительности штатными средствами платформы «1С»:

Полученные замеры не дают ответов и вызывают удивление, так как основная часть времени (более 65%) формирования отчета относится на общую процедуру СформироватьОтчет
НаСервере(), при этом признак «Для вызова процедур и функций включать время выполнения» не установлен.

Попробуем его установить:

Время исполнения общей процедуры СформироватьОтчет
НаСервере() увеличилось до 30 секунд и составило 100% всего времени формирования отчета. Делаем предположение, что платформенный замер просто не может показать проблемный участок кода отчета, а время, потраченное на его исполнение, приходится на общую процедуру СформироватьОтчет
НаСервере().

Сбор логов технологического журнала

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

Отчет — это всегда запрос к БД, поэтому добавим события SDBL и DBPOSTGRS, а так как основная часть времени относится к серверной процедуре, то необходимы пара событий SCALL и CALL:

CALL — фиксирует входящий вызов, его длительность, контекст и сколько было потрачено памяти.
SCALL — фиксирует исходящий серверный вызов, собираем в паре с CALL для того, чтобы понять, кто был инициатором вызова.
SDBL — фиксирует исполнение запросов к модели базы данных системы «1С:Предприятие», собираем дополнительно для того, чтобы понять, сколько времени от общего времени серверного вызова (CALL) заняли запросы.
DBPOSTGRS — позволяет собрать все SQL запросы технологической платформы 1С к СУБД PostgreSQL.

Добавим следующие фильтры на все события:

ProcessName — отбирает события, связанные с указанной ИБ.
ComputerName — отбирает события, связанные с указанным ПК.

Интерактивный инструмент настройки тех. журнала не рекомендуется использовать, так как сложные настройки гораздо проще сделать в текстовом редакторе. Здесь инструмент приведен скорее в качестве альтернативного, а не основного. Текст настроек технологического журнала logcfg.xml поместим в каталог C:\Program Files\1cv8\conf, логи будем собирать в каталог «C:\logs»:

Анализ технологического журнала

Собранные логи тех. журнала бессмысленно анализировать визуально в связи с их огромным объёмом, поэтому воспользуемся скриптами на основе регулярных выражений.

Подробнее с ними можно ознакомиться для применения анализа логов ТЖ, посмотрев вебинар преподавателя «Учебного центра №1» Виктора Богачева.

Посмотреть вебинар

Попробуем поискать в логах события длительностью более 1 секунды при помощи следующего скрипта:

egrep -i -r  "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-[0-9]{7}" log.log

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

Напишем соответствующий скрипт:

egrep  "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-[0-9]+" log.log  | awk -F\- '{print $1;}' | sed -e 's/\./:/g'  | awk -F\: '{ min = $1; sec=$2; mmsec=$3; event=$0; getline; print  ($1*60*1000000 + $2*1000000 + $3) - (min*60*1000000 + sec*1000000 +  mmsec)" : "event" - "$0;}' | sort -rnb | head

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

egrep "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-[0-9]" log.log команда egrep, представляющая собой расширенный аналог команды grep, в данном случае ищет все строки, которые начинаются (знак ^) со строк, состоящих из двух чисел [0-9][0-9], затем двоеточия (оно экранируется, чтобы не воспринималось как служебный символ, далее снова две цифры, далее точка с экранированием, далее от 1 до любого числа (знак +) цифр от 0 до 9, далее знак - и снова от 1 до любого числа цифр). Таким образом, мы получили часть для исчисления начала события и его продолжительности. То есть поток представляет собой строки типа 42:15.4234-2445
awk -F\- '{print $1;}' команда awk это целый отдельный язык программирования с возможностью организовывать условия, циклы, и конечно его надо изучать отдельно. В данном случае ключ -F\- велит разбить строку на части, используя в качестве разделителя знак -. И взять часть, приходящуюся на начало события {print $1;} В переменной $1 она и находится. То есть получится поток строк с таким типом 42:15.4234
sed -e 's/\./:/g' команда в основном используется для удаления и замены символов. В данном случае меняет точку на двоеточие. И получается поток со строками типа 42:15:4234
awk -F\: '{ min = $1; sec=$2; mmsec=$3; event=$0; getline; print ($1*60*1000000 + $2*1000000 + $3) - (min*60*1000000 + sec*1000000 + mmsec)" : "event" - "$0;}' здесь важно обратить внимание на наличие внутри awk команды getline. Она берет следующую за обрабатываемой строку. То есть что тут происходит: сначала в отдельных переменных запоминаются компоненты строки разделенные двоеточием (для этого на предыдущем шаге мы заменили точку на двоеточие), далее берется следующая строка. Время начала событий переводится в микросекунды, исчисляется разница между началом данного события и следующего
sort -rnb сортируется по убыванию этой разницы
head выводятся первые 10

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

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

Первая строка нашей таблицы выводит на 81 строку модуля формы отчета:

Однако строка является «типовым кодом» и подозрений не вызывает, будем двигаться дальше по таблице! Дальнейший анализ выводит на строки 521 и 557 модуля объекта рассматриваемого отчета:

Закомментируем подозрительный код:

и повторим замер производительности:

Отключение условного оформления дало 1 секунду вместо 20 у процедуры СформироватьОтчет
НаСервере(), а в целом отчет формируется за 3 секунды вместо 30, то есть улучшение производительности в 10 раз!

Будем ждать жалобы пользователей на отсутствие условного оформления, чтобы реализовать по-новой без ущерба для производительности, но забегая вперед — никто так и не пожаловался :)

Применение анализа лагов в логах технологического журнала у клиента

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

После выполнения запроса идет применение метода НайтиСледующий() в цикле. Посмотрим на замер производительности:

Основная часть времени уходит на многократное исполнение метода НайтиСледующий(). Проанализируем логи ТЖ на самые длительные интервалы между парными событиями скриптом, который уже использовали в предыдущем примере:

Найдем соответствующие события в ТЖ:

Видим, что самые длительные интервалы выводят на такие события, непосредственная длительность которых составляет всего 1 микросекунду, при этом временной интервал между ними составляет около 8 секунд. Эти события идут после выполнения запроса к БД и являются отражением метода НайтиСледующий() в технологическом журнале.

Межсобытийные лаги для поиска проблем в коде

Что можно сказать в заключении: отсутствие информации порой не менее ценная информация. Вот такой парадокс.

Существует два класса источников проблем, которые приводят к замедлению работы системы: проблемы в запросах и проблемы в коде. И в случае, если мы имеем дело со вторым классом, то обязательное условие воздействия на него — это добраться до контекста в «1С».

Именно в этом случае более чем применим подход, описанный в статье. Обнаружить межсобытийный лаг в логе ТЖ и понять, что система что-то делала в этот промежуток времени, проследовать в код «1С», ориентируясь на предыдущее залогированное событие и произвести поиск подозреваемых.

Вопросы замедления работы «1С» мы рассматривали в предыдущих статьях от экспертов «1С-Рарус»: