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

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

Администрирование - Журнал регистрации

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

54
В арсенале каждого уважающего себя 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 2015 с поддержкой Visual Basic (кстати версия Visual Studio 2015 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.2015
* добавлена загрузка из тех.журналов 8.3 (увеличена точность времени события).
* добавлены исходники для Visual Studio 2013 на vb.net.

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

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

54

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

Наименование Файл Версия Размер
Исполняемый файл
.zip 262,12Kb
08.09.15
76
.zip 262,12Kb 76 Скачать

См. также

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

Комментарии
Избранное Подписка Сортировка: Древо
1. aspirator23 401 15.02.12 07:36 Сейчас в теме
Ценная вещь. Жалко что к ней не приложена обработка для чтений журнала из MS SQL
Кроме того не все сидят на 8.2.14-15
3. Aleksey.Bochkov 15.02.12 13:53 Сейчас в теме
(1) aspirator23, думаю, что можно в это же приложение добавить просмотр загруженных событий с отбором по виду события и сортировкой по длительности.
(2) stal76, похожая, но не совсем. Отличия в том, что мое приложение может загружать любые события с любым составом свойств(но сохраняются, конечно, только те свойства, которые есть в структуре таблицы) в многопоточном режиме, а хранимая процедура squad'a заточена чисто на запросы, грузит в один поток + файлы читаются при каждом обращении.
2. stal76 376 15.02.12 09:27 Сейчас в теме
4. Новиков 291 16.02.12 10:14 Сейчас в теме
5. Zas1402 21.02.12 10:26 Сейчас в теме
(4) Новиков,
так точно полезная вечь.
7. Babuin 24.02.12 10:58 Сейчас в теме
хм, у меня падает при загрузке логов rphosta почему то
8. Aleksey.Bochkov 24.02.12 11:29 Сейчас в теме
(7) с какой ошибкой падает? Если ругается на нехватку памяти, то уменьшите число одновременных потоков.
9. Babuin 24.02.12 12:01 Сейчас в теме
(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)
10. Aleksey.Bochkov 24.02.12 12:57 Сейчас в теме
(9) поправил. Скачай программу заново и попробуй еще раз.
11. Babuin 24.02.12 13:18 Сейчас в теме
попробовал, на фрейм не ругается, но все равно падает.
Если грузить по одному файлу то нормально. Если все прогрузить по одному и потом опять скопом то тоже проходит.
Еще бы добавить функцию очищать таблицу, и сохранять путь подключения к базе было бы вообще супер!
12. Aleksey.Bochkov 24.02.12 13:23 Сейчас в теме
(11) а можешь прислать файлы, при загрузке которых происходит падение и сценарий воспроизведения?
ок, сохранение и опциональную очистку таблицы на выходных сделаю.
13. Babuin 24.02.12 13:49 Сейчас в теме
(12) к сожалению не могу, ладно буду грузить по одному.
14. NOVOPRO 14.03.12 04:19 Сейчас в теме
У меня такаяже ошибка
от 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)
15. GreenFox 28.03.12 00:16 Сейчас в теме
Вещь конечно интересная - надо разбираться. Подобные обработки в области оптимизации интересовали раньше скорее как развлечение, но сейчас "припекло" и приходиться собирать все , что только можно найти в данной области. КИП пока что недоступен по цене, поэтому пользуемся тем что есть.
16. igor_gk 46 20.07.17 14:43 Сейчас в теме
Что за "текстовых файлов технологического журнала с расширением *.log" ?
17. Andreynikus 1237 26.09.18 12:39 Сейчас в теме
Хорошая вещь! А из 1С можно строить запросы к таблице с данными ТЖ, например через конструктор запросов? Или только прямые запросы к таблицам СУБД?
18. user626776_zhiglin 26.10.18 11:10 Сейчас в теме
Собрал логи ТЖ с настройкой
<?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)
Оставьте свое сообщение