gifts2017

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

Опубликовал Алексей Бочков (Aleksey.Bochkov) в раздел Администрирование - Журнал регистрации

В арсенале каждого уважающего себя 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"

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

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

См. также

Подписаться Добавить вознаграждение

Комментарии

1. aspirator 23 (aspirator23) 15.02.12 07:36
Ценная вещь. Жалко что к ней не приложена обработка для чтений журнала из MS SQL
Кроме того не все сидят на 8.2.14-15
2. Александр Степанов (stal76) 15.02.12 09:27
3. albochkov (Aleksey.Bochkov) 15.02.12 13:53
(1) aspirator23, думаю, что можно в это же приложение добавить просмотр загруженных событий с отбором по виду события и сортировкой по длительности.
(2) stal76, похожая, но не совсем. Отличия в том, что мое приложение может загружать любые события с любым составом свойств(но сохраняются, конечно, только те свойства, которые есть в структуре таблицы) в многопоточном режиме, а хранимая процедура squad'a заточена чисто на запросы, грузит в один поток + файлы читаются при каждом обращении.
4. Алексей Новиков (Новиков) 16.02.12 10:14
5. Игор Мудрицкий (Zas1402) 21.02.12 10:26
(4) Новиков,
так точно полезная вечь.
7. Babuin 24.02.12 10:58
хм, у меня падает при загрузке логов rphosta почему то
8. albochkov (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. albochkov (Aleksey.Bochkov) 24.02.12 12:57
(9) поправил. Скачай программу заново и попробуй еще раз.
11. Babuin 24.02.12 13:18
попробовал, на фрейм не ругается, но все равно падает.
Если грузить по одному файлу то нормально. Если все прогрузить по одному и потом опять скопом то тоже проходит.
Еще бы добавить функцию очищать таблицу, и сохранять путь подключения к базе было бы вообще супер!
12. albochkov (Aleksey.Bochkov) 24.02.12 13:23
(11) а можешь прислать файлы, при загрузке которых происходит падение и сценарий воспроизведения?
ок, сохранение и опциональную очистку таблицы на выходных сделаю.
13. Babuin 24.02.12 13:49
(12) к сожалению не могу, ладно буду грузить по одному.
14. Anatoliy (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. Alex Stasyuk (GreenFox) 28.03.12 00:16
Вещь конечно интересная - надо разбираться. Подобные обработки в области оптимизации интересовали раньше скорее как развлечение, но сейчас "припекло" и приходиться собирать все , что только можно найти в данной области. КИП пока что недоступен по цене, поэтому пользуемся тем что есть.
Для написания сообщения необходимо авторизоваться
Прикрепить файл
Дополнительные параметры ответа