C:\Dev\lib\SQLite3\exe\TestSQL3.exe 0.0.0.0 (2011-04-13) Host=Laptop User=MyName CPU=2*0-15-1027 OS=2.3=5.1.2600 Wow64=0 Freq=3579545 TSynLogTest 1.13 2011-04-13 05:40:25The difference between a test suit without logging (TSynTests) and a test suit with logging (TSynTestsLogged) is only this:
20110413 05402559 fail TTestLowLevelCommon(00B31D70) Low level common: TDynArray "" stack trace 0002FE0B SynCommons.TDynArray.Init (15148) 00036736 SynCommons.Test64K (18206) 0003682F SynCommons.TTestLowLevelCommon._TDynArray (18214) 000E9C94 TestSQL3 (163)
procedure TSynTestsLogged.Failed(const msg: string; aTest: TSynTestCase); begin inherited; with TestCase[fCurrentMethod] do fLogFile.Log(sllFail,'%: % "%"', [Ident,TestName[fCurrentMethodIndex],msg],aTest); end;
The logging mechanism can be used to trace recursive calls. It can use an interface-based mechanism to log when you enter and leave any method:
procedure TMyDB.SQLExecute(const SQL: RawUTF8); var ILog: ISynLog; begin ILog := TSynLogDB.Enter(self,'SQLExecute'); // do some stuff ILog.Log(sllInfo,'SQL=%',[SQL]); end; // when you leave the method, it will write the corresponding event to the log
It will be logged as such:
20110325 19325801 + MyDBUnit.TMyDB(004E11F4).SQLExecute 20110325 19325801 info SQL=SELECT * FROM Table; 20110325 19325801 - MyDBUnit.TMyDB(004E11F4).SQLExecute
Here the method name is set in the code ('SQLExecute'). But if you have an associated .map file, the logging mechanism is able to read this symbol information, and write the exact line number of the event.
Note that by default you have time and date written to the log, but it's also possible to replace this timing with high-resolution timestamps. With this, you'll be able to profile your application with data coming from the customer side, on its real computer. Via the Enter method (and its auto-Leave feature), you have all information needed for this.
In this log entries, you'll see both high-resolution time stamp, and the entering and leaving of the TTestCompression.TestLog method traced with no additional code (with accurate line numbers):
0000000000000B56 + TTestCompression(00AB3570).000E6C79 SynSelfTests.TTestCompression.TestLog (376) 0000000000001785 - TTestCompression(00AB3570).000E6D09 SynSelfTests.TTestCompression.TestLog (385)
I still need to write some tool to compute the profiling, but there is already a dedicated TSynLogFile class able to read the .log file, and recognize its content.
The first time the .map file is read, a .mab file is created, and will contain all symbol information needed. You can send the .mab file with the .exe to your client, or even embed its content to the .exe. This .mab file is optimized: a .map of 927,984 bytes compresses into a 71,943 .mab file.
You have several debugging levels available. And even 4 custom types. It's worth saying that the logging level is a SET, and not an enumerate: that is, you can select several kind of logging information to be logged at once, on request:
/// the available logging events, as handled by TSynLog // - sllError will log errors // - sllInfo will log general information events // - sllDebug will log detailed debugging information // - sllEnter will log every method start // - sllLeave will log every method quit // - sllLastError will log the GetLastError OS message // - sllException will log all exception raised - available since Windows XP // - sllExceptionOS will log all OS low-level exceptions (EDivByZero, // ERangeError, EAccessViolation...) - available since Windows XP // - sllMemory will log memory statistics // - sllStackTrace will log caller's stack trace (it's by default part of // TSynLogFamily.LevelStackTrace) // - sllFail was defined fo TSynTestsLogged.Failed method // - sllSQL is dedicated to trace the SQL statements // - sllResult could trace the SQL results, JSON encoded // - sllDB is dedicated to trace low-level database engine features // - sllHTTP could be used to trace HTTP process // - sllClient/sllServer could be used to trace some Client or Server process // - sllCustom* items can be used for any purpose TSynLogInfo = ( sllNone, sllError, sllInfo, sllDebug, sllEnter, sllLeave, sllLastError, sllException, sllExceptionOS, sllMemory, sllStackTrace, sllFail, sllSQL, sllResult, sllDB, sllHTTP, sllClient, sllServer, sllCustom1, sllCustom2, sllCustom3, sllCustom4); /// used to define a logging level // - i.e. a combination of none or several logging event // - e.g. use LOG_VERBOSE constant to log all events TSynLogInfos = set of TSynLogInfo;
Of course, this logging mechanism is able to intercept the raise of exceptions, including the worse (e.g. EAccessViolation), to be logged automatically in the log file:
000000000000090B EXCOS EAccessViolation (C0000005) at 000E9C7A SynSelfTests.Proc1 (785) stack trace 000E9D51 SynSelfTests.Proc2 (801) 000E9CC1 SynSelfTests.Proc1 (790) 000E9D51 SynSelfTests.Proc2 (801) 000E9CC1 SynSelfTests.Proc1 (790) 000E9D51 SynSelfTests.Proc2 (801) 000E9CC1 SynSelfTests.Proc1 (790) 000E9D51 SynSelfTests.Proc2 (801) 000E9CC1 SynSelfTests.Proc1 (790) 000E9D51 SynSelfTests.Proc2 (801) 000E9CC1 SynSelfTests.Proc1 (790) 000E9E2E SynSelfTests.TestsLog (818) 000EA0FB SynSelfTests (853) 00003BF4 System.InitUnits 00003C5B System.@StartExe 000064AB SysInit.@InitExe 000EA3EC TestSQL3 (153)
Objects, TList, and dynamic arrays can also be serialized as JSON in the log
on request.
TSQLRecords can also be serialized as JSON in the log.
For instance, the following code:
procedure TestPeopleProc; var People: TSQLRecordPeople; Log: ISynLog; begin Log := TSQLLog.Enter; People := TSQLRecordPeople.Create; try People.ID := 16; People.FirstName := 'Louis'; People.LastName := 'Croivébaton'; People.YearOfBirth := 1754; People.YearOfDeath := 1793; Log.Log(sllInfo,People); finally People.Free; end; end;
will result in the following log content:
0000000000001172 + 000E9F67 SynSelfTests.TestPeopleProc (784) 000000000000171B info {"TSQLRecordPeople(00AB92E0)":{"ID":16,"FirstName":"Louis","LastName":"Croivébaton","Data":"","YearOfBirth":1754,"YearOfDeath":1793}} 0000000000001731 - 000EA005 SynSelfTests.TestPeopleProc (794)
You can have several log files per process, and even a per-thread log file, if needed (it could be sometimes handy, for instance on a server running the same logic in parallel in several threads).
Works with Delphi 6 up to XE.
Feedback and questions are welcome in our forum.
Blog post edit
- Now works with Delphi 5 up to XE2;
- Has been enhanced a lot since 1.13 version;
- The
SynCommons.pas
unit can be downloaded in its latest version from here; - There is an enhanced log viewer tool available now;