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








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

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

Для работы приложения необходим установленный NET Framework 2.0.

Для начала использования приложения требуется:
1) создать на сервере MS SQL новую пустую базу
2) заполнить строку соединения с сервером по шаблону:
для windows-авторизации Data Source=MSSQL1;Server=имя сервера;Database=имя базы;Integrated Security=true;
для обычной авторизации  Data Source=MSSQL1;Server=имя сервера;Database=имя базы;Password=Пароль;User ID=Имя пользователя;
3) нажать кнопку «Создать служебную таблицу», которая подключится к серверу и выполнит создание структуры таблицы для событий

Порядок загрузки файлов:
1) указать строку соединения как описано выше;
2) указать каталог, содержащий файлы тех.журнала с расширением *.log, вложенные каталоги обрабатываются рекурсивно;
3) указать число параллельных потоков, в которых программа будет обрабатывать файлы. Диапазон от 1 до 100, но ставить больше 20-30 нет особого смысла, хотя все зависит от конкретной машины, на которой выполняется запуск.
4) нажать кнопку «Заполнить список файлов» — программа найдет все файлы ТЖ в указанном каталоге и отобразит их список;
5) нажать кнопку «Запустить разбор» — программа начнет параллельное чтение файлов, их разбор и запись полученных событий в структурированном виде в базу данных.

Дополнительные вычисляемые данные

Чтобы сделать данные более полезными для анализа были добавлены 2 вычисляемых поля для событий DBMSSQL и SDBL.

Поле «ContextLastRow» — заполняется последней строкой вызываемого контекста. Позволяет сгруппировать строки кода, которые вызываются из разных мест. Без этой информации сложно получить достоверную картину о влиянии некоторых общих процедур и функций, вызываемых из разных участков конфигурации.

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

Чтобы подставить подобный контекст к правильным местам вызова и получить более объекивную картину — требуется выполнить следующий запрос в базе с загруженными данными:

---простановка контекста для DBMSSQL в пределах 50 миллисекунд
SELECT Context, ContextLastRow, DATEADD(ms, - 50, DateTime) as D1, DATEADD(ms, 50, DateTime) as D2, ProcessName, t_clientID, SessionID
INTO #ContextTable
FROM logs
WHERE (EventName = 'Context')

CREATE CLUSTERED INDEX ix_Main ON #ContextTable (ProcessName, t_clientID, SessionID)

SELECT DateTime, EventName, ProcessName, t_clientID, Moment, SessionID, Context, ContextLastRow
INTO #QueriesTable
FROM logs
WHERE (EventName = 'DBMSSQL' AND Context = '' AND ContextLastRow = '')

CREATE CLUSTERED INDEX ix_Main ON #QueriesTable (ProcessName, t_clientID, SessionID)

SELECT DateTime, EventName, ProcessName, t_clientID, Moment, SessionID, Contexts.Context, Contexts.ContextLastRow
INTO #NewData
FROM #QueriesTable AS Queries
OUTER APPLY (SELECT TOP 1 Context, ContextLastRow
FROM #ContextTable AS A
WHERE
(ProcessName = Queries.ProcessName)
AND (t_clientID = Queries.t_clientID)
AND (SessionID = Queries.SessionID)
AND (Queries.DateTime BETWEEN D1 AND D2)) AS Contexts
WHERE NOT Contexts.Context IS NULL AND NOT Contexts.ContextLastRow IS NULL

DROP TABLE #ContextTable
DROP TABLE #QueriesTable

UPDATE T SET T.Context = OT.Context, T.ContextLastRow = OT.ContextLastRow
FROM [logs] T
INNER JOIN
(SELECT DateTime, EventName, ProcessName, t_clientID, Moment, SessionID, Context, ContextLastRow
FROM #NewData) OT
ON
T.[DateTime] = OT.[DateTime]
AND T.Moment = OT.Moment
AND T.EventName = OT.EventName
AND T.ProcessName = OT.ProcessName
AND T.t_clientID = OT.t_clientID
AND T.SessionID = OT.SessionID

DROP TABLE #NewData

 

Поле «TablesList» — заполняется физическими таблицами, участвующими в запросе, в порядке их следования. Это позволяет группировать однотипные по структуре запросы и получать более точную информацию о том, какие именно таблицы наиболее часто или долго участвуют в запросах. Без подобного поля группировка невозможна из-за случайных имен временных таблиц, разного количества параметров, разных псевдонимов и т.д.

Несколько примеров выборки данных

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

SELECT SUM([Duration]) [Общая длительность], AVG([Duration]) [Среднее], SUM(1) [Количество],
Min(DateTime) [Начало], Max(DateTime) [Окочнание], [ContextLastRow]
FROM [dbo].[logs]
where NOT [ContextLastRow] = '' AND EventName='DBMSSQL'
GROUP BY [ContextLastRow]
ORDER BY SUM([Duration]) DESC

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

 

Получить список комбинаций таблиц запросов, выполнение которых заняло наибольшее время:

SELECT SUM([Duration]) [Общая длительность], AVG([Duration]) [Среднее], SUM(1) [Количество],
Min(DateTime) [Начало], Max(DateTime) [Окончание], TablesList, ProcessName
FROM [dbo].[logs]
where NOT tableslist = '' AND EventName='DBMSSQL'
GROUP BY TablesList, ProcessName
ORDER BY SUM([Duration]) DESC

 

Исходные коды

Актуальная версия всегда доступна на github — https://github.com/alekseybochkov/tj_loader/

Для работы с исходными кодами требуется Visual Studio 2024 с поддержкой Visual Basic (кстати версия Visual Studio 2024 Community Edition бесплатна!).

Опубликовано по лицензии GNU GPL — https://ru.wikipedia.org/wiki/GNU_General_Public_License

 

UPD 18.02.2012
* добавлена возможность выполнения произвольных запросов к базе с событиями непосредственно из приложения;
* добавлена возможность выгрузки результатов запроса в Excel (проверялось только на русской версии Excel 2010);
* добавлена возможность просмотра структурированного плана запроса MS SQL и его выгрузка в Excel

UPD 08.03.2012
* добавлена галка «Очистить таблицу в СУБД перед загрузкой данных»
* при закрытии приложения происходит сохранение настроек в файле setting.ini. При запуске приложение считывает настройки из файла и использует их.

UPD 21.03.2024
* добавлена загрузка из тех.журналов 8.3 (увеличена точность времени события).
* добавлены исходники для Visual Studio 2013 на vb.net.

UPD 20.07.2024
* добавлено дополнительное вычисляемое поле «TablesList» для событий DBMSSQL, которое заполняется перечнем физических таблиц, участвующих в запросе. Это позволяет группировать однотипные по структуре запросы и получать более ценную информацию о проблемных местах. Без этого группировка невозможна из-за случайных имен временных таблиц, разного количества параметров, разных псевдонимов и т.д.

UPD 08.09.2024
* добавлено дополнительное вычисляемое поле «ContextLastRow»

17 Comments

  1. aspirator23

    Ценная вещь. Жалко что к ней не приложена обработка для чтений журнала из MS SQL

    Кроме того не все сидят на 8.2.14-15

    Reply
  2. stal76

    Была похожая публикация:

    http://infostart.ru/public/99989/

    Reply
  3. Aleksey.Bochkov

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

    (2) stal76, похожая, но не совсем. Отличия в том, что мое приложение может загружать любые события с любым составом свойств(но сохраняются, конечно, только те свойства, которые есть в структуре таблицы) в многопоточном режиме, а хранимая процедура squad‘a заточена чисто на запросы, грузит в один поток + файлы читаются при каждом обращении.

    Reply
  4. Новиков

    Плюсую! Нужная весчь!

    Reply
  5. Zas1402

    (4) Новиков,

    так точно полезная вечь.

    Reply
  6. Babuin

    хм, у меня падает при загрузке логов rphosta почему то

    Reply
  7. Aleksey.Bochkov

    (7) с какой ошибкой падает? Если ругается на нехватку памяти, то уменьшите число одновременных потоков.

    Reply
  8. Babuin

    (8) нет с памятью все ок, запускал с разными потоками (от 1 до 20)

    Какие то логи грузит, на каких то падает

    framework ругается

    System.ArgumentOutOfRangeException: Value of ’14’ is not valid for ‘Value’. ‘Value’ should be between ‘minimum’ and ‘maximum’.

    Parameter name: Value

    at System.Windows.Forms.ProgressBar.set_Value(Int32 value)

    at TechJournalLoader.Form1.Timer1_Tick(Object sender, EventArgs e)

    at System.Windows.Forms.Timer.OnTick(EventArgs e)

    at System.Windows.Forms.Timer.TimerNativeWindow.WndProc(Message& m)

    at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)

    Reply
  9. Aleksey.Bochkov

    (9) поправил. Скачай программу заново и попробуй еще раз.

    Reply
  10. Babuin

    попробовал, на фрейм не ругается, но все равно падает.

    Если грузить по одному файлу то нормально. Если все прогрузить по одному и потом опять скопом то тоже проходит.

    Еще бы добавить функцию очищать таблицу, и сохранять путь подключения к базе было бы вообще супер!

    Reply
  11. Aleksey.Bochkov

    (11) а можешь прислать файлы, при загрузке которых происходит падение и сценарий воспроизведения?

    ок, сохранение и опциональную очистку таблицы на выходных сделаю.

    Reply
  12. Babuin

    (12) к сожалению не могу, ладно буду грузить по одному.

    Reply
  13. NOVOPRO

    У меня такаяже ошибка

    от framework

    System.ArgumentOutOfRangeException: Value of ’14’ is not valid for ‘Value’. ‘Value’ should be between ‘minimum’ and ‘maximum’.

    Parameter name: Value

    at System.Windows.Forms.ProgressBar.set_Value(Int32 value)

    at TechJournalLoader.Form1.Timer1_Tick(Object sender, EventArgs e)

    at System.Windows.Forms.Timer.OnTick(EventArgs e)

    at System.Windows.Forms.Timer.TimerNativeWindow.WndProc(Message& m)

    at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)

    Reply
  14. GreenFox

    Вещь конечно интересная — надо разбираться. Подобные обработки в области оптимизации интересовали раньше скорее как развлечение, но сейчас «припекло» и приходиться собирать все , что только можно найти в данной области. КИП пока что недоступен по цене, поэтому пользуемся тем что есть.

    Reply
  15. igor_gk

    Что за «текстовых файлов технологического журнала с расширением *.log» ?

    Reply
  16. Andreynikus

    Хорошая вещь! А из 1С можно строить запросы к таблице с данными ТЖ, например через конструктор запросов? Или только прямые запросы к таблицам СУБД?

    Reply
  17. user626776_zhiglin

    Собрал логи ТЖ с настройкой

    <?xml version=»1.0″ encoding=»UTF-8″?>

    <config xmlns=»http://v8.1c.ru/v8/tech-log»>

    <dump create=»false»/>

    <log location=»f:logs_duration» history=»168″>

    <event>

    <ne property=»name» value=»»/>

    </event>

    <property name=»all»/>

    </log>

    </config>

    Процесс загрузки логов завершился, но в таблице в SQL ничего не появилось.

    Платформа 1С:Предприятие 8.3 (8.3.10.2650)

    Reply

Leave a Comment

Ваш адрес email не будет опубликован. Обязательные поля помечены *