Сазонов Алексей 15 января, 2019 - 19:54 Последняя редакция: 22 января, 2019 - 18:35 Автор редакции: Сазонов Алексей

Описание тонкостей при ведении логов

Общие сведения
Каждая запись в логе непременно сопровождается подробной информацией на момент возникновения события.
 
Пример лога:
 
ID потока Занимаемая/виртуальная память Дата / Время Тип события Событие
5984 55028/21032 KB   15.01.2019 16:37:21.002 TRY: TEventManager.DoEvent(4100, )
5984 55028/21032 KB 15.01.2019 16:37:21.002  TRY TEventManager.DoEvent.CallProc(4100, )
6700 55056/21116 KB 15.01.2019 16:37:21.002 TRY: TDebugThread.Execute.Start
5984 55056/21116 KB 15.01.2019 16:37:21.002    Thread TFreezeChecker (6632) Created
5984 55056/21116 KB 15.01.2019 16:37:21.002 DONE: TEventManager.DoEvent.CallProc(4100, )
5984 55064/21116 KB  15.01.2019 16:37:21.002  DONE:  TEventManager.DoEvent(4100, )

При корректном поведении для большинства событий "TRY" должно быть событие "DONE". В приведенном выше примере стартует поток, но метода "DONE" нет, т.к. он вызывается при завершении приложения.
Логирование запросов

8460  73232/46048 KB       15.01.2019 16:37:23.222 TRY:    1.2.TDatabaseConnector.CreateReadQuery.CrSect.Enter
8460  73240/46048 KB       15.01.2019 16:37:23.236 DONE:   1.2.TDatabaseConnector.CreateReadQuery.CrSect.Enter
8460  74084/50560 KB       15.01.2019 16:37:23.693 TRY:    1.7.SQL_OpenSession.CreateReadQuery
-----------------------------------------------------------
select session from SYS$OPENSESSION(0, 0, '&Computer=A-SAZONOV&LangCode=RU')
-----------------------------------------------------------
8460  74084/50560 KB       15.01.2019 16:37:23.693 DONE:   1.7.SQL_OpenSession.CreateReadQuery
8460  74084/50560 KB       15.01.2019 16:37:23.700         1.7.8686.Open [10 ms]
8460  74084/50560 KB       15.01.2019 16:37:23.700 TRY:    1.7.8686.Fetch
8460  74084/50560 KB       15.01.2019 16:37:23.700 DONE:   1.7.8686.Fetch [0 ms]
8460  74084/50560 KB       15.01.2019 16:37:23.700 TRY:    TDatabaseConnector.FreeQuery ReadTrans=False AssignedTransaction=False IsException=False
8460  74084/50560 KB       15.01.2019 16:37:23.701 TRY:    1.7.8686.Commit
8460  74084/50560 KB       15.01.2019 16:37:23.703 DONE:   1.7.8686.Commit.Result = 1
8460  74084/50560 KB       15.01.2019 16:37:23.703 TRY:    TDatabaseConnector.FreeQuery -> CrSectLeave OnCrSectLeave=False FCrSect=True
8460  74084/50560 KB       15.01.2019 16:37:23.703 DONE:   TDatabaseConnector.FreeQuery -> CrSectLeave
8460  74084/50560 KB       15.01.2019 16:37:23.703 DONE:   1.7.8686.FreeQuery [10 ms, 1 records, 52 B]
Стандартные поля описаны выше. Событие TDatabaseConnector.CreateReadQuery.CrSect.Enter следит за очередностью выполнения запросов. Если в логе есть подобное событие с типом "TRY", но нет "DONE", это значит, что какой-то другой запрос "завис", т.е. для него не было события TDatabaseConnector.FreeQuery.CrSect.Leave. Сам запрос из таблицы также исключаем.
 

ID подключения к БД Счетчик запросов Процедура / ID транзакции Действие
1 7 SQL_OpenSession CreateReadQuery
1 7 8686 Open [10 ms]
1 7 8686 Fetch
1 7 8686 Fetch [0 ms]
1 7 8686 Commit
1 7 8686 FreeQuery

 

Т.е. порядок действий таков:

• Пытаемся встать в очередь;
• Успешно встаем в очередь;
• Создаем экземпляр запроса;
• Выполняем запрос;
• Далее могут быть какие-то вложенные действия;
• Пытаемся зафиксировать запрос;
• Успешно его фиксируем;
• Пытаемся выйти из очереди;
• Успешно выходим из очереди;
• Уничтожаем экземпляр запроса;

При выполнении запроса в скобках указано время выполнения запроса (но не время его полной обработки).
При уничтожении запроса в скобках указано полное время на обработку запроса (включая все вложенные действия), кол-во полученных записей и их размер.
Счетчик запросов нужен для того, чтобы отличить один запрос от другого. Например, чтобы было видно, что начался вложенный запрос.
 
Логирование запросов из внешних модулей
 
Пример лога:
 
5984  96428/70048 KB       15.01.2019 16:38:16.089         SHELTER.DLL | Try: Core.Bootstrap
5984  96556/69980 KB       15.01.2019 16:38:16.090         SHELTER.DLL | Try: Save .ini = C:\Users\ALEXAN~1\AppData\Local\Temp\80693241
5984  96584/69980 KB       15.01.2019 16:38:16.090         SHELTER.DLL | Done: Save .ini = C:\Users\ALEXAN~1\AppData\Local\Temp\80693241
5984  96584/69980 KB       15.01.2019 16:38:16.090         SHELTER.DLL | Done: TIniFile.Create = C:\Users\ALEXAN~1\AppData\Local\Temp\80693241
5984  96584/69980 KB       15.01.2019 16:38:16.091         SHELTER.DLL | Start of Core.Bootstrap() with .ini-file = C:\Users\ALEXAN~1\AppData\Local\Temp\80693241
 
5984  96584/69980 KB       15.01.2019 16:38:16.096         SHELTER.DLL | Try: Plug Module D:\Online\sdmGazPromBank.dll
5984  96584/69980 KB       15.01.2019 16:38:16.096         SHELTER.DLL | Load Library D:\Online\sdmGazPromBank.dll Start
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | D:\Online\sdmGazPromBank.dll loaded ok
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | function MagicCode found
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | Magic code is ok
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | function Version found
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | DLL specs/build version: 1.06/1.00
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | function Info found
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | i: -------------------------------------------
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | i: CREDIT CARD( GAZPROMBANK)
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | i: version 1.0.0 2017.05.15
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | i: -------------------------------------------
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | Load Library D:\Online\sdmGazPromBank.dll Handle = 136118272
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | Init Library D:\Online\sdmGazPromBank.dll Start
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | function Init found
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | DLL init results: (0x00000000,0x081D0000)
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | Init Library D:\Online\sdmGazPromBank.dll Result = 0
5984  100132/76588 KB      15.01.2019 16:38:16.104         SHELTER.DLL | Module D:\Online\sdmGazPromBank.dll plugged ok
 
Все подчиняется тем же правилам, что и выше, но с указанием модуля.

Поиск ошибок в логах.

Одним из ключевых слов при поиске ошибок в логе является ERROR. Для поиска ошибок в логе, необходимо :
1. Воспроизвести проблему
2. Открыть сформировавшийся лог Shelter любым текстовым редактором (предпочтительнее Notepad++)
3. Нажать Ctrl + F в полей найти ввести error 
4. Нажать Найти
5. Попытаться найти решение самостоятельно
Исключения по error, на которые можно не обращать внимание :
1. select error
2. ERROR:  Different Charset [DBCharset=UNICODE_FSS,Charset=WIN1251]
3. ERROR : TShelterDLL.Destroy