Технологический журнал крайне полезный инструмент для расследования различных проблем производительности и стабильности, но далеко не все о нем знают и умеют грамотно использовать.
В данной статье мы очень подробно рассмотрим этот инструмент — от описания до примеров использования.
В данной статье мы очень подробно рассмотрим этот инструмент — от описания до примеров использования.
Описание
Включение
Настройка
Логи
События
Фильтр
Примеры
Ошибки
Описание
Технологический журнал (далее ТЖ) – это средство для логирования работы платформы на низком уровне.
ТЖ предназначен для расследования ошибок, анализа и диагностики различных проблем в работе платформы 1С:Предприятие.
С помощью ТЖ можно выяснить какие запросы работают медленно и откуда они вызываются, при выполнении какого кода «падают» рабочие процессы сервера, куда «утекает» память и многое, многое другое.
Все инструменты анализа производительности платформы, используют ТЖ для получения информации. При желании и доскональном изучении вопроса с помощью ТЖ вы можете написать свой инструмент анализа производительности.
ТЖ можно собирать как для процессов сервера 1С, так и для клиентских приложений. Соответственно и набор событий которые можно фиксировать в ТЖ будет отличаться. Клиентские логи и дампы крайне редко вызывают интерес, поэтому в статье мы будем рассматривать ТЖ исключительно с точки зрения сервера. Тем не менее все что здесь написано, так же подходит и для клиентских логов.
С помощью ТЖ можно собирать логи и настраивать формирование дампов в случае аварийного завершения работы процесса.
Логи – это файлы с расширением log, где информация хранится в текстовом виде.
Дампы – это файл с расширением mdmp, который содержит в себе содержимое оперативной памяти процесса на момент «падения». Дамп бывает крайне необходим для расследования проблем стабильности платформы. Самостоятельно мы не можем анализировать дампы, т.к. у нас нет исходного кода платформы, но мы можем отправить их в техническую поддержку или на партнерский форум и получить решение нашей проблемы. Подробнее о том как можно использовать ТЖ и дампы для решения проблем стабильности я уже писал в этой статье.
Включение
По умолчанию технологический журнал включен и работает, но собирает очень ограниченный объем данных.
Под минимальным объемом данных подразумеваются 2 вещи:
1) Формирование дампов минимального размера в случае аварийного завершения работы процессов кластера 1С (ragent, rmngr или rphost).
По умолчанию дамп создается в каталоге:
%USERPROFILE%\Local Settings\Application Data\1C\1Cv82\dumps
Если вы используете Windows Vista и выше, то будет использоваться каталог:
%LOCALAPPDATA%\1C\1Cv82\dumps
Для 8.3 вместо каталога 1Cv82 используется 1Cv8.
2) Для 8.3 в минимальный ТЖ входит формирование логов с одним событием SYSTEM с уровнем Error.
Логи сохраняются в каталоге:
%USERPROFILE%\Local Settings\Application Data\1C\1Cv8\logs
Для Windows Vista и старше используется каталог:
%LOCALAPPDATA%\1C\1Cv8\logs
Данные логи по умолчанию будут хранится 24 часа, после чего платформа будет удалять файлы логов которые превышают этот порог.
Чаще всего информации из ТЖ по умолчанию не достаточно, и необходимо его настраивать вручную.
Чтобы произвести тонкую настройку ТЖ, необходимо создать файл logcfg.xml с определенной структурой в определенном месте.
Данный файл необходимо разместить в каталоге:
C:\Program Files\1Cv82\conf (для 8.3 каталог 1Cv8)
В этом случае настройки ТЖ будут действовать для всех версий 1С, которые установлены на данном компьютере и для всех пользователей. Этот вариант используется чаще всего и именно его я рекомендую использовать.
При настройках ЦУПа, облачных сервисов контроля производительности и прочих инструментов где надо указывать путь к logcfg, также лучше использовать именно этот каталог, иначе при обновлении платформы или изменении имени пользователя под которым запущена служба сервера 1С, описанные инструменты перестанут работать и придется менять настройку.
Тем не менее есть и другие варианты, хотя и используются они гораздо реже. Опишу лишь то, что с наибольшей вероятностью вам может понадобится.
Чтобы настроить ТЖ только для одной версии платформы, размещаем logcfg.xml в каталоге:
C:\Program Files\1Cv82\8.2.19.106\bin\conf
Где 8.2.19.106 это номер нужной вам версии.
Крайне редко, но все же, может возникнуть необходимость настроить ТЖ отдельно для каждого пользователя под которым запущена служба сервера 1С.
Тогда размещаем logcfg в каталоге:
%USERPROFILE%\Local Settings\Application Data\1C\1Cv82\Conf
Для ОС Windows Vista и старше:
%LOCALAPPDATA%\1C\1Cv82\Conf
Это может потребоваться если у вас например 1 служба сервера 1С используется как рабочая, а вторая для отладки. При необходимости можно запустить службы под разными пользователями и собирать ТЖ только для одной из них, чтобы не загружать второй сервер и не собирать в логах лишние данные, либо сделать для каждой из служб свои настройки ТЖ.
Настройки из logcfg считываются не моментально, а каждые 60 секунд, причем каждый из процессов кластера считывает файл настроек независимо от других процессов. Например, сначала могут появиться логи процесса rmngr, и только через 45 секунды логи rphost.
Для выключения ТЖ достаточно удалить или переименовать файл logcfg.xml.
Настройка
Как уже было сказано, для тонкой настройки ТЖ используется файл logcfg.xml, давайте подробно разберем структуру этого файла.
Например, мы разместили в каталоге «C:\Program Files\1Cv82\conf» файл logcfg.xml со следующим содержанием:
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
<log location="C:\1C_Info\Logs" history="1">
<event>
<ne property="name" value=""/>
</event>
<property name="all"/>
</log>
</config>
Давайте подробно рассмотрим каждую строку.
1
<config xmlns="http://v8.1c.ru/v8/tech-log">
Определяет начало настроек ТЖ и указывает на пространство имен xml, эта строка всегда идет первой и остается неизменной по содержанию.
2
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
Определяет, что в случае аварийного завершения одного из процессов сервера 1С, необходимо создать дамп в каталоге «C:\1C_Info\Dumps».
Если атрибут create=»0″ или create=»false», то дамп не будет создан.
Атрибут «type» определяет насколько полный дамп нужно создавать.
Значение «2», означает что в дамп будет записано содержимое всей памяти процесса. Рекомендую использовать именно его, т.к. для большинства случае этого достаточно. Можно поставить значение «0», тогда будет собран минимальный дамп, но для расследования содержащейся в нем информации может не хватить.
Для данного параметра возможен довольно большой перечень значений, подробнее о них можно почитать в руководстве администратора, но на практике другие значения почти никогда не используются.
Параметр «location» определяет в какой каталог будет записан дамп.
Если элемента <dump> нет, то будут созданы минимальные дампы и сохранены в каталог для дампов по умолчанию (см. раздел «Включение»)
3
<log location="C:\1C_Info\Logs" history="1">
Открывает раздел с настройками логов. Здесь настраивается каталог для хранения логов и время хранения в часах. В данном случае логи будут храниться только за последний час. Файлы логов старше указанного времени платформа удалит самостоятельно.
При выборе каталога надо учитывать, что там не должно быть ничего кроме файлов логов.
Разделов log может быть несколько, в каждом разделе могут быть свои события, время и каталог для хранения файлов.
4
<event>
Открывает раздел для фильтрации и настройки тех событий, которые мы будем собирать в логах ТЖ.
Разделов <event> также может быть несколько, по одному разделу на одно событие.
5
<ne property="name" value=""/>
Определяет какое именно событие мы будем фиксировать и в каком случае.
ne – это условие на не равенство (not equal), дословно строка читается так: если свойство события «Имя» не равно значению «», тогда записываем это событие в ТЖ.
А т.к. у любого события есть имя, то данное условие заведомо всегда будет выполняться, и мы будем фиксировать абсолютно все события технологического журнала.
Обычно такая настройка не используется т.к. сбор полного технологического журнала будет замедлять работу системы, логи быстро займут все свободное место на диске, да и разобраться в гигабайтах текстовой информации потом будет не просто. Поэтому обычно используют фильтрацию по событиям, об этом мы поговорим чуть позже.
6
</event>
Закрывает раздел event. После этого можно начинать новый раздел </event> если нужно фиксировать несколько событий.
7
<property name="all">
Здесь мы определяем какие свойства событий необходимо фиксировать. Обычно это значение остается по умолчанию в «all», т.е. записываем все свойства событий которые определены в разделе <event>.
8
</log>
Закрывает раздел log. После этого можно начинать новый раздел log.
9
</config>
Определяет конец настроек ТЖ.
На первый взгляд такая структура может показаться сложной, но поверьте это только на первый взгляд. На самом деле благодаря такому формату можно делать очень гибкие настройки, что очень облегчает работу по расследованию всяких непонятных ситуаций.
Логи
Давайте посмотрим что произойдет, если мы создадим файл logcfg.xml с указанной выше структурой и поместим его в каталог «C:\Program Files\1Cv82\conf»
Подождем 60 секунд и откроем каталог «C:\1C_Info\Logs», т.к. именно его мы указывали в 3 строке файла logcfg.
Если каталога 1C_Info на диске нет, то сервер 1С попробует его создать, но есть риск того что у пользователя под которым запущена служба 1С не будет прав. Поэтому рекомендуется создавать каталоги для логов вручную и проверять наличие прав у сервера 1С на запись в данный каталог.
В результате в каталоге мы видим 3 подкаталога.
Каждый процесс кластера создал каталог, в котором находятся логи только данного процесса, а т.к. у меня только 3 процесса, то и каталогов тоже 3.
Каталог создается по шаблону ИмяПроцесса_PIDПроцесса. PID нужен для того, чтобы отличать процессы с одинаковым именем.
Каждый час создается отдельный файл с логом.
Файл лога именуется по шаблону ГГММДДЧЧ.log.
Например, у меня первый лог за 6 апреля 2015 года 10 часов утра.
Если лог старше чем количество часов указанное в параметре history файла logcfg, то он автоматически удаляется платформой.
Давайте подробно разберем формат лога технологического журнала.
Событие записываются в лог только после того как оно завершилось, т.к. необходимо фиксировать длительность события.
Строка лога имеет формат: мм:сс.тттт-д, <ИмяСобытия>, <Уровень>, <Свойства>
Где:
мм – номер минуты в текущем часе.
сс – номер секунды в текущей̆ минуте.
тттт – номер десятитысячной доли текущей̆ секунды, для 8.3 здесь отображается номер миллионной доли.
д – длительность события в десятитысячных долях секунды, для 8.3 в миллионных долях.
<ИмяСобытия> – наименование события.
<Уровень> – уровень события в стеке текущего потока.
<Свойства> — свойства события разделенные запятыми, значения свойств проставлены через знак «=».
Разберем на примере.
Есть лог со следующим содержимым:
00:16 — это минуты и секунды окончания события. Дату и час события можно взять из названия файла лога. Событие завершилось 6 апреля 2015 года в 11 часов 00 минут 16 секунд.
8640 – для 8.2 это десятитысячные доли секунды, для 8.3 миллионные доли секунды момента завершения события.
1 – это длительность события. В 8.2 длительность указывается в десятитысячных долях секунды, в 8.3 в миллионных долях секунды. Если необходимо поставить фильтр на длительность, то можно использовать имя свойства «Duration».
DBMSSQL – это имя события, в данном случае выполнение инструкций СУБД MS SQL Server.
3 – уровень события.
Далее идут свойства события DBMSSQL, при этом у каждого события свой набор свойств. Полный список свойств для всех событий можно посмотреть в руководстве администратора. Здесь мы подробно рассмотрим свойства только для текущего события.
Process – это свойство есть у всех событий, описывает процесс для которого пишется данный лог. В моем случае это лог процесса rphost.
P:processName – имя информационной базы 1С, событие было сформировано в базе под названием Deadlock.
T:clientID — идентификатор соединения с клиентом по TCP.
T:applicationName – идентификатор клиентской̆ программы, т.е. кто именно вызвал событие, в моем случае это фоновое задание.
T:connectID – номер соединения с информационной̆ базой̆.
SessionID – номер сеанса, назначенный̆ текущему потоку. Если текущему потоку не назначен сеанс, то свойство не добавляется.
Usr – имя пользователя информационной̆ базы под которым выполняется данный поток. Если пользователь не определен, подставляется значение DefUser.
Trans – показывает открыта транзакция на момент начала события или нет. 1 – открыта, 0 – нет.
dbpid – номер соединения сервера 1С с сервером баз данных.
SQL – текст инструкции SQL. Чаще всего здесь содержится текст запроса SQL с параметрами.
Rows – количество строк, которые вернул запрос.
RowsAffected – количество строк, которые изменил запрос в базе данных.
Context – какая строка кода на языке 1С породила данное событие. Наверное самое интересное для нас событие.
События
Писать в ТЖ все что происходит в платформе не имеет большого смысла, мы сильно загрузим сервер 1С таким логированием, при этом будет сложно найти нужную информацию в гигабайтах текста, ну и диски у нас тоже не резиновые.
Для того чтобы записывать только нужную информацию существуют события ТЖ и фильтрация этих событий.
Например, когда возникает какая либо исключительная ситуация, то в ТЖ записывается событие EXCP. Если выполняется запрос к базе MS SQL Server, возникает событие DBMSSQL и т.д.
Рассмотрим некоторые события, которые чаще всего используются в работе.
EXCP – исключительные ситуации приложений системы «1С:Предприятие», которые штатно не обрабатываются и могут послужить причиной̆ аварийного завершения серверного процесса или подсоединенного к нему клиентского процесса.
EXCPCNTX – события, которые начались, но не закончились в момент возникновения нештатной̆ ситуации.
DBMSSQL – исполнение операторов SQL СУБД Microsoft SQL Server. Для каждой СУБД используется свое событие(DBPOSTGRS, DBORACLE, DB2, DBV8DBENG – файловый вариант)
ADMIN – действия администратора кластера в консоли кластеров.
PROC – события, относящиеся к процессу целиком и влияющие на дальнейшую работоспособность процесса. Например: старт, завершение, аварийное завершение и т. п.
CALL – входящий удалённый вызов (удалённый вызов на стороне приемника вызова). Например, если вы из клиента вызываете функцию на сервере, то в ТЖ на сервере будет записано событие CALL.
SCALL – исходящий удалённый вызов (исходящий вызов на стороне источника вызова). Например, если вы из клиента вызываете функцию на сервере, то в ТЖ на клиенте будет записано событие SCALL.
SESN – действия, относящиеся к сеансу работы. Например: начало сеанса, окончание сеанса и т. д.
TDEADLOCK – обнаружена взаимоблокировка в управляемом режиме блокировок.
TTIMEOUT – ошибка по таймауту на управляемых блокировках.
TLOCK – установка транзакционной блокировки в управляемом режиме блокировок.
Полный список событий можно посмотреть в руководстве администратора.
Фильтр
Допустим вы хотите видеть в ТЖ только ошибки и информацию о запросах к таблице AccRg105, которые длились более 3 секунд .
Тогда logcfg должен выглядеть следующим образом.
Между двумя <event> работает логическое ИЛИ, т.е. при возникновении любого из событий оно будет записано в ТЖ.
Внутри одного <event> работает логическое И, т.е. данное событие будет записано только в том случае, если будут выполнены все условия внутри одного <event>.
При такой настройке событие EXCP будет записываться всегда, а событие DBMSSQL только в том случае, если в любом месте текста запроса содержится строка «AccRg105» и при этом запрос выполнялся дольше 3 секунд.
Фильтр на длительность события, надо ставить в десятитысячных долях секунды независимо от версии платформы.
В данном примере мы используем несколько условий: eq, gt и like.
Можно использовать следующие условия:
eq – равно;
ne – не равно;
gt – больше;
ge – больше или равно;
lt – меньше;
le – меньше или равно;
like – соответствие маске.
Таким образом можно настроить фильтр практически под любые задачи.
Примеры
А теперь давайте попробуем со всем этим взлететь. Посмотрим как именно на практике можно применить технологический журнал.
- Необходимо зафиксировать все запросы к СУБД PostgreSQL, которые длились 10 или более секунд и отобразить планы этих запросов.
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
<plansql/>
<log location="C:\1C_Info\Logs" history="1">
<event>
<eq property="name" value=" DBPOSTGRS"/>
<ge property="duration" value="100000"/>
</event>
<property name="all"/>
</log>
</config>
Получение плана запроса включается параметром <plansql/>, план будет получен в текстовом виде и записан как свойство planSQLText.
Сбор планов работает для любой СУБД в том числе и для файлового варианта, но только если в ТЖ включен сбор одного из событий DBPOSTGRS, DBORACLE, DB2, DBV8DBENG или DBMSSQL.
- Необходимо создавать дампы в случае аварийного завершение, но логи собирать не нужно.
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
</config>- Необходимо фиксировать все события которые длились 15 или более секунд в базе «Test». Сбор дампов нужно отключить.
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="0" type="2"/>
<log location="C:\1C_Info\Logs" history="1">
<event>
<ne property="name" value=""/>
<ge property="duration" value="150000"/>
<eq property="p:processName" value="Test"/>
</event>
<property name="all"/>
</log>
</config>- Необходимо фиксировать все события которые длились дольше 5 секунд в базе Test под пользователем «Иванов».
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
<log location="C:\1C_Info\Logs" history="1">
<event>
<ne property="name" value=""/>
<gt property="duration" value="50000"/>
<eq property="p:processName" value="Test"/>
<eq property="usr " value="Иванов"/>
</event>
<property name="all"/>
</log>
</config>- Необходимо фиксировать все ошибки в каталоге C:\1C_Info\Logs\Excp, а все действия администратора в каталоге C:\1C_Info\Logs\Admin. Логи с действиями администратора надо сохранять за последние 2 дня.
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump location="C:\1C_Info\Dumps" create="1" type="2"/>
<log location="C:\1C_Info\Logs\Excp" history="1">
<event>
<eq property="name" value="EXCP"/>
</event>
<property name="all"/>
</log>
<log location="C:\1C_Info\Logs\Admin" history="48">
<event>
<eq property="name" value="Admin"/>
</event>
<property name="all"/>
</log>
</config>Ошибки
При настройке ТЖ довольно легко допустить ошибку, при этом платформа никак об этом не сообщает, она просто перестает писать логи без объяснения причин.
Самый простой способ избежать примитивных ошибок, это открыть logcfg.xml в браузере перед тем как копировать в каталог config.
Рассмотрим наиболее популярные ошибки при настройке ТЖ.
Рассмотрим наиболее популярные ошибки при настройке ТЖ.
1. Русские символы. Классика жанра — если в logcfg вы поставили русские символы в любом месте, кроме значений параметров, то ТЖ работать не будет.
2. Непечатаемые символы. Проблема может возникнуть если вы скопировали текст logcfg, а не набирали вручную.
3. Нарушена структура файла xml, например где-то не закрыли тэг или поставили лишний пробел.
4. Неправильно указаны каталоги. В каталоге с логами не должно находится ничего кроме логов, иначе логи записаны не будут.
Например, неправильно указывать такую настройку:
<dump location="C:\1C_Info\Logs\Dumps" create="1" type="2"/><log location="C:\1C_Info\Logs" history="1">
Также неправильно будет указать 1 каталог для дампов и логов.
<dump location="C:\1C_Info\Logs" create="1" type="2"/><log location="C:\1C_Info\Logs" history="1">При возникновении дампа логи перестанут записываться, т.к. в каталоге с логами будет создан посторонний элемент.
5. Используется кодировка отличная от UTF-8. При использовании других кодировок возможны проблемы.
Технологический журнал крайне полезный инструмент для расследования проблем производительности и стабильности.
Надеюсь, что после прочтения статьи у вас не осталось вопросов по его использованию.
Комментариев нет:
Отправить комментарий