Introducing enhanced logging mechanism

ab · 2011-04-13 11:13:20

In the up-to-come 1.13 version, there is also a new logging mechanism with stack trace exception and such, just like MadExcept, using .map file content as source.

It's now used by the unit testing classes, so that any failure will create an entry in the log with the source line, and stack trace:

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:25

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)

The difference between a test suit without logging (TSynTests) and a test suit with logging (TSynTestsLogged) is only this:

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).

Available to download in our SynCommons.pas unit. Works from Delphi 6 up to XE.

ab · 2011-04-14 12:20:58

About exception logging, if you add e.g.:

uses 
  SynCommons;
 
(...)
  TSynLog.Family.Level := [sllExceptionOS];

all OS exceptions (excluding pure Delphi exception like EConvertError and such) will be logged to a separate log file.

TSynLog.Family.Level := [sllException,sllExceptionOS];

will trace also Delphi exceptions, for instance.

If you put a .map file together with the exe file, it will write the line numbers and such to the log file.

See the new Map2Mab.dpr program in "SQLite3\Samples\11 - Exception logging" sub folder to embed .map file content into an .exe.

edwinsn · 2011-04-15 07:01:49

This is great! I've used JCL DEBUG for a long time, and have recently switched to eurekalog.

richard6688 · 2011-05-12 16:43:10

Great! After study a while, I use this class as my project logger, and I load the log content into a memo to watch the response.
Nice, but is there other problem?

  TetLog = class(TSynLog)
  strict private
    fLastSize: Int64;
  protected
    procedure CreateLogWriter; override;
  public
    procedure DupLog(Lines: TStrings);
  end;

implementation

{ TetLog }

procedure TetLog.CreateLogWriter;
begin
  fLastSize:=0;
  fWriter := TJSONWriter.Create(nil,fFamily.BufferSize);
  inherited;
  fWriter.Stream := fWriterStream;
end;

procedure TetLog.DupLog(Lines: TStrings);
var SavePostion: Int64;
begin
  if fWriterStream=nil then Exit;
  if fLastSize=fWriterStream.Size then Exit;
  Lock;
  try
    SavePostion:= fWriterStream.Position;
    fWriterStream.Position:=0;
    Lines.LoadFromStream(fWriterStream);
    fWriterStream.Position:= SavePostion;
    fLastSize := fWriterStream.Size;
  finally
    Unlock;
  end;
end;

ab · 2011-05-12 17:36:58

It just sounds OK.

But your code won't work with Unicode version of Delphi (2009/2010/XE).

And it will become damn slow when the .log file tends to grow...

You should better use a TListBox in virtual mode, retrieving each line on request, using the Lines[] property.

Thanks for your interest!

richard6688 · 2011-05-13 01:02:36

Thank you very much for your suggestion!
You are right, I have notice that may be slow when log file grow. I may retrival data for latest in limit size. To use TListBox in virtual mode, it's a good idea. I may also make the log message colorful for each type. Thank you again.
In fact, I had compiled that code in Delphi XE, made a test, that seems Ok except for big log stream.

ab · 2011-05-13 05:31:08

For more information about logging, see the SAD pdf in the documentation downloadable from http://synopse.info/files/synproject/sampledoc.zip

I'm still creating the Log Viewer.
But as far as I understood your question, you're viewing the log during the application run itself, is it true?
Like a console real-time logging?

richard6688 · 2011-05-13 07:12:39

Yes, You are right. I just want user see the interact messages, something like delphi ide message window. I know this logger is better for server, but it's convinent class, I had tried out for display. later maybe I will change the Textwriter to my own when I have time. Anyway Thanks you again for your great job on syncommon.pas unit and synbigtable.pas unit, which I had used for my project.

ab · 2011-05-17 15:34:45

TSynLogFamily.Destroy is now able to delete and/or archive outdated .log files into .synlz or .zip, in a custom destination directory.
See TSynLogFamily.OnArchive new event handler.

The .synlz file format is used to fast .log compression (with UnSynLz.dpr for uncompressing this efficient but proprietary file format).
The compression will be much faster than .zip, but with a (little) less efficient compression ratio.

See http://synopse.info/fossil/info/9877caf56e

richard6688 · 2011-06-04 07:52:32

today, when I open the switch On (delphi XE)

ReportMemoryLeaksOnShutdown := DebugHook <> 0;

I found AV at AutoFlushProc in syncommons.pas; this may be due to thread delay-free problem.
I temporaryly add a line to resolve this problem

procedure AutoFlushProc(P: pointer); stdcall; // TThread not needed here
var i: integer;
begin
repeat
Sleep(1000); // thread will awake every second to check of pending data
if SynLogFile=nil then
continue;
inc(AutoFlushSecondElapsed);
if AutoFlushThread=0 then continue; //add this line to avoid av when program terminated
for i := 0 to SynLogFile.Count-1 do

PLS look around this problem.

ab · 2011-06-04 18:21:55

I wasn't able to reproduce it, but there was indeed a design issue here.

I've added a check to avoid GPF when shutdown takes too long.

See http://synopse.info/fossil/info/3f7908feb5

Thanks for the feedback!

ab · 2011-06-08 07:42:54

The logging should now work under Delphi 5 by now.

The problem with this version of Delphi is that there is no RtlUnwindProc pointer available, to add a custom Exception handler.
I had to patch the System.pas unit assembler code in place, via the following code:

// Delphi 5 doesn't define the needed RTLUnwindProc variable :(
// so we will patch the System.pas RTL in-place
var RTLUnwindProc: Pointer;

procedure Delphi5UnWindProc;
asm
  jmp RTLUnwindProc
end;

procedure PatchCallRtlUnWind;
procedure Patch(P: PAnsiChar);
{   004038B6 52               push edx  // Save exception object
    004038B7 51               push ecx  // Save exception address
    004038B8 8B542428         mov edx,[esp+$28]
    004038BC 83480402         or dword ptr [eax+$04],$02
    004038C0 56               push esi  // Save handler entry
    004038C1 6A00             push $00
    004038C3 50               push eax
    004038C4 68CF384000       push $004038cf  // @@returnAddress
    004038C9 52               push edx
    004038CA E88DD8FFFF       call RtlUnwind }
var i: Integer;
begin
  for i := 0 to 31 do
    if (PCardinal(P)^=$6850006a) and  // push 0; push eax; push @@returnAddress
       (PWord(P+8)^=$E852) then begin // push edx; call RtlUnwind
      inc(P,10); // go to call RtlUnwind address
      if PInteger(P)^<0 then begin
        PatchCodePtrUInt(Pointer(P),Integer(@Delphi5UnWindProc)-Integer(P)-4);
        exit;
      end;
    end else
    inc(P);
end;
asm
  mov eax,offset System.@HandleOnException+275
  call Patch
  mov eax,offset System.@HandleAnyException+200
  call Patch
  mov eax,fs:[0]
  mov eax,[eax+4] // patch System.@ExceptionHandler
  add eax,50
  call Patch
end;

Could seems simple, but it was some kind of difficult to get it work as expected in fact.

Another issue with Delphi 5 is that the "array of const" parameter call is buggy: the code generated by the compiler sometimes corrupts the stack when pushing the parameters on the stack...
I had no choice than avoid using this "open parameter" feature with this version of Delphi.

See http://synopse.info/fossil/info/05a32c637b

ab · 2011-06-08 13:08:16

I finally used an even more generic patch method.

See details in http://synopse.info/forum/viewtopic.php?id=337
and corresponding commit in http://synopse.info/fossil/info/154f9f7f11

ab · 2011-09-03 07:24:56

In order to work with 64 bit Delphi XE2 Compiler, SynCommons will need modification about exception handling and stack trace.
See http://www.delphifeeds.com/go/s/83454

I think there is enough info in this link to make it work as expected.

yeradis · 2011-10-26 09:43:07

Hi, First all thanks for your work

i´m having an issue with this sample:

SynopseSQLite3\Samples\11 - Exception logging

On Delphi XE2 it works, but on Delphi 7 is not working, the apps get freezed

Thanks

ab · 2011-10-26 11:23:13

I've just tested with Delphi 6 (I do not have Delphi 7 at hand), and it works as expected.

Did you retrieve the latest version of SynCommons.pas from http://synopse.info/fossil ?

Moz · 2012-02-19 23:33:29

I've just tried to add this to a D2006 application. SynLz.pas is now also required.

The main problem is that when I try to set the family options I get "too big TSynMapSymbolDynArray" in WriteSymbol (line 26596). My map file is 25MB (for a 90MB exe). fBufLen=262144 and n=93643

Your code:

procedure WriteSymbol(var W: TFileBufferWriter; const A: TDynArray);
...
  with W do
    if fPos+n*5>fBufLen then // BufLen=1 shl 19=512 KB should be enough
      raise Exception.CreateFmt('too big %s',[PDynArrayTypeInfo(A.TypeInfo).Name]) else

My code:

    fLogWriter := TTextWriter.Create(nil,8192);
    with TSynLog.Family do begin Level := LOG_VERBOSE; PerThreadLog := true; DestinationPath := 'C:\Dev\Bin'; end;

The buffer size limit in your code:

constructor TFileBufferWriter.Create(aStream: TStream; BufLen: integer);
begin
  if BufLen>65536*4 then
    BufLen := 65536*4; // fail for CleverStoreInteger
...

If I comment out that buffer size restriction in the constructor and set a buffer size to 1MB it seems to work.

ab · 2012-02-20 09:43:17

What a big application - 25 MB .map file is quite huge!

SynLZ is required to compress the .map content into .mab.
I wonder what will be the compression ratio - I think much better than .zip - IMHO your .mab file will be around 2 MB when generated from a 25 MB .map file.

I've set the high limit to 4 MB in TFileBufferWriter.Create.
AFAIK CleverStoreInteger won't fail in case of bigger buffer.
See http://synopse.info/fossil/info/ec9a53a44c

Thanks for the feedback.

Moz · 2012-02-20 21:56:49

Thanks for the logger. And the quick fix! Using an interfaced type to do trace logging is very cunning. BTW, our app is split into dll's for distribution but for development it's monolithic (and huge). Part of the size is because the packaging has not been well controlled so there is a lot of code included multiple times. But I'm working through Peganza reports to clean some of that up.

To deal with our existing really primitive log that's used in too many places I've replaced the internals of the class with this:

type TMyLogger = class
   private
      fLogWriter: TTextWriter;
      fLog:ISynLog;
...
constructor TMyLogger.Create;
begin
   fLogWriter := TTextWriter.Create(nil, 1024 * 1024); // but never free it - it's a magic self-garbage-collecting object
   TSynLog.Family.Level := LOG_VERBOSE;
   TSynLog.Family.PerThreadLog := True;
   fLog := TSynLog.Enter();
end;

procedure TMyLogger.Output(const Text: string);
begin
         //AV: fLogWriter.AddLine(AsText);
         //no log file: TSynLog.Enter().Log(sllCustom1, AsText);
         fLog.Log(sllCustom1,Text);
end;

Is that a reasonable way to do it? Would you do it a different way?

thanks again
Moz

ab · 2012-02-21 08:25:35

You could simply use a TSynLog instance instead of a ISynLog interface here.

The ISynLog interface was indeed developed for method profiling, not really for reference counting.

type TMyLogger = class
   private
      // fLogWriter: TTextWriter; // not  needed
      fLog: TSynLog; // instead of ISynLog
...
constructor TMyLogger.Create;
begin
   // fLogWriter := TTextWriter.Create(nil, 1024 * 1024); // you do not need it - instance is created by TSynLog
   TSynLog.Family.Level := LOG_VERBOSE;
   TSynLog.Family.PerThreadLog := True;
   fLog := TSynLog.Enter().Instance; // retrieve the associated logging instance
end;

procedure TMyLogger.Output(const Text: string);
begin
         //AV: fLogWriter.AddLine(AsText);
         //no log file: TSynLog.Enter().Log(sllCustom1, AsText);
         fLog.Log(sllCustom1,Text);
end;

You'd rather use some kind of parsing of the text, in order to set a custom Level: TSynLogInfo - it will make the logs much better.
E.g. if pos('ERROR',Text)>0 then fLog.Log(sllError,Text) else fLog.Log(sllCustom1,Text);
The log viewer is a very handy tool for handling the diverse kind of log level, and let the useful information show up.

By the way, what is the size of the resulting .mab?

Moz · 2012-02-21 22:54:48

ab wrote:

You could simply use a TSynLog instance instead of a ISynLog interface here.

That looks more sensible, thanks.

You'd rather use some kind of parsing of the text, in order to set a custom Level: TSynLogInfo - it will make the logs much better.

Our code has a kind-of set of Info parameter that I can use, but I am quite dependent on having a specifier from my own logger (which I'm not using largely because I prefer to be able to point at a FOSS download rather than "try Moz's website and good luck").

By the way, what is the size of the resulting .mab?

Only about 2MB.

I've just started working on a new codebase that's 10 years old and a bit cluttered. So I'm doing a lot of exploration. The good news is that by using the filtering in the setup I can keep my debug logs down to less than 100kB most of the time, so they're not too hard to sort through. Currently I'm bulk profiling by replacing all the "^begin" with "var Log:ISynLog;\nbegin\n Log := TSynLog.Enter;" (regular expressions) then pruning. Being able to have multiple "var" statements at the start of a method is brilliant in this situation

procedure TFoo.Bah;
var
   ExistingVariable:integer;
   ...
   var Log: ISynLog;
begin
   Log := TSynLog.Enter;

ab · 2012-02-22 08:21:06

Using regular expression like replacing all the "^begin" with "var Log:ISynLog;\nbegin\n Log := TSynLog.Enter;" is a good idea.
We may use a parser to profile a whole unit at once... like a regular instrumental profiler... but perhaps not worth it.
What I usual do is to start with profiling some high-level methods, then tune the profiling in order to fine the bottlenecks.

It may tend to create huge log, if every method has its own Enter/Leave events.
But I suspect you are only logging meaningful methods!

Only 2 MB of .mab file does make sense.

Moz · 2012-02-22 23:34:42

Sorry, a couple more questions. I am logging within a dll and the profiler is not picking up method info:

20120223 09003447  +    
20120223 09003447 debug 	Loaded DLL
20120223 09003508  +    		
20120223 09003508  +    			
20120223 09003522  -    			 00.229.427

Even a pointer value here would be more useful than an empty space. The code to set up logging is a copy of the executable code:

library MyLib;
...
begin
   {$IFDEF DEBUG}
   TTextWriter.Create(nil,1024*1024); 
   // LOG_VERBOSE is everything, LOG_ALL_BUT_TRACE is less
   with TSynLog.Family do begin Level := LOG_VERBOSE; PerThreadLog := true;  end;
   TSynLog.Enter.Log(sllDebug, 'Loaded DLL');
   {$ENDIF}
end.

There's a map file, but no mab file being created.

Also, two log files. Is it possible to get instances to all write to the same file as I'm manually merging now and when I start doing that with 20-odd files from testing the packaged version of the executable it's going to be ugly. Ditto if I get a customer to turn on logging on site "please send me all the .log files". I have a request in for MadExcept which will solve that to some extent but don't know how long it will take to get it.

Also, when I get a log created by the dll the header still references the executable that loaded the dll. I haven't seen a dll referenced in the header yet.

When I'm working on a couple of nasty AV bugs I've got it'd be nice to be able to set AutoFlushTimeOut to less than 1s or the 4kB buffer to something more aggressive, even at the cost of overall performance. Getting every log entry when it's sent would be ideal. I'm using an SSD so even if Windows buffering doesn't work the drive is nice and quick.

ab · 2012-02-23 08:36:59

About bufferred writing:
- You can set AutoFlushTimeOut=0 to disable the background writing thread;
- In case of an AV exception, the content is always flushed to the disk, whatever the AutoFlushTimeOut value is (just to track such nasty AV bugs).

Yes, there are several limitations with the current implementation, when using dlls:
- Only the main .map file of the executable is loaded (since paramstr(0) retrieves only the executable name);
- There is still at least one log file per TSynLog instance - you can have one log file per thread, but you can't merge log content between dlls and main exe.

I'll try to make a solution for the library issue, with two points:
- Find how to retrieve the library file name - a simple call to GetModuleFileName(hInstance,..) should be enough to get the corresponding dll name and therefore associated .map/.mab;
- Add a non intrusive way of sharing a log instance between instances (dlls and main exe).

For the 2nd point, I'd like to add an open solution, efficient for in-process memory sharing, and also for remote debugging:
- For dll/exe merged logging, I'd like to use the same technique as in FastMM4 / InstallMemoryManager - that is, a local shared memory file (named after the process ID), in order to retrieve any TSynLog instance of the main executable;
- But the main architecture should be able to easily handle remote debugging, using Windows GDI messages (very fast), or even HTTP/TCP (in the future).

I think that having dll/exe logging shared by default make sense to me - with an option to have the dll creates its own log file.
What do you think about that?

If you have any idea, feel free to discuss here!

ab · 2012-02-23 11:16:40

The first point (i.e. proper handling of libraries by TSynLog) has been implemented:
- TSynLog now stores the executable build time, and library name (if any);
- TSynLog and TSynMapFile now handle libraries (.dll/.ocx/.bpl) .map/.mab debugging information (only .exe was previously handled);
- Modified SynLogViewer and Map2Mab tools to reflect those TSynLog changes.

See http://synopse.info/fossil/info/e6c84794ec

Moz · 2012-02-23 21:28:29

ab wrote:

I think that having dll/exe logging shared by default make sense to me - with an option to have the dll creates its own log file.
What do you think about that?

That sounds great. What I've done in the past is have a shared location that has the common address but also a buffer pointer, an index and indent level that are accessed via interlocked instructions so that getting a buffer slot is fast and easy, and knowing the indent level likewise. It leads to occasional indent level slips when the log is being hammered by multiple threads (because the index and indent are accessed independently) but it's very lightweight. The intent is that everything a simple write needs is in that shared memory block and it's accessed frequently to keep it in the CPU cache.

I'm sorry but I haven't looked at the detail of how your logger works, so this might be silly for your design. But here's what I do for my log

The index is into a rotating buffer that is just an array of pointers to internal log objects which are created by the log method{1}. In my case I untangle those to strings in the log thread to keep the logging overhead low for the caller, so they have a high frequency timer value, TDateTime, string, array of const and a couple of other things. There's code to increment that buffer size if required but doing so is slow and ugly (because I have to lock all logging while I'm moving the buffer) so I usually default it to "lots" (256k entries in debug mode(a 1MB block of memory), with a usual peak load of about 4k) since my programs rarely run low on memory. On client sites it is rarely used, rarely hammered, and defaults to 1k entries. I've only seen it resized a few times. I don't have a flag to tell callers when the buffer cycles, but the thread tracks that and does a few stats. The design is deliberately loose - in theory it could all fall apart and leak memory or just choke, but in practice the combination of rapid input, slow disk, little CPU for the log thread and low memory has only occurred when testing that scenario Even with the old BorlandMM!

{1} there was a performance gain for single-physical-CPU machines if you re-use the log objects but when they have to get shunted between physical CPUs the timing is worse for reuse, so I don't reuse. I haven't profiled recent multicore CPUs to see whether it pays off on them. Nor have I looked into how FastMM deals with the issue. It's been a few years since I reviewed the design, sorry (hence using your logger rather than mine). I think the real performance gain would having separate buffers for each thread and doing the merge in the writer, because locks are very slow (single CPU/single threaded log writes can be under 100 cycles, but an interlocked instruction is typically 1000's and the current design has two per write).

Moz · 2012-02-23 22:03:11

Oh, and thanks for the quick update with the dll name. I'm still not seeing mab files for the dlls or any identifier in the trace logs. For now I'm using that to detect dll usage in the "monolithic" debug executable. Is this something you think you'll be able to bring in in the next month or so?

ab · 2012-02-24 08:23:18

The dlls .map files will be used:
- If the .map is located in the same place than the .dll;
- If the dll code starts explicitly some TSynLog instance: it has to use its own instance.

Moz · 2012-02-27 21:16:18

I have the "foo.dll", "foo.map" and "foo.mab" files in the same directory and created at the same time. The dll has this code:

begin
   {$IFDEF DEBUG}
   // set up Synopse logger - to file next to executable, with timestamp.
   // LOG_VERBOSE is everything, LOG_ALL_BUT_TRACE is less
   with TSynLog.Family do begin Level := LOG_VERBOSE; PerThreadLog := true; HighResolutionTimeStamp := True; end;
   TSynLog.Enter.Log(sllDebug, '--------------------------------------------------------------------------------------');
   TSynLog.Enter.Log(sllDebug, 'Loaded Orders DLL');
   {$ENDIF}
end.

Which gives a log file that starts like this:

C:\...\MyProg.exe 0.0.0.0 (2012-02-24 08:56:45)
Host=MYCOMPUTER User=Me CPU=4*9-6-10759 OS=13.1=6.1.7601 Wow64=1 Freq=3312886 Instance=C:\...\FOO.DLL
TSynLog 1.16 2012-02-28T07:59:03

0000000000000001  +    
0000000000000007 debug 	--------------------------------------------------------------------------------------
0000000000000026  +    	
0000000000000027 debug 		Loaded Foo DLL
0000000000000028  -    	 00.000.000
000000000000002A  -     00.000.012

I'm getting the mab file now, but it doesn't seem to get loaded. No sure why, sorry.

Moz · 2012-02-28 03:36:02

OK, I give up. I've just ripped all evidence of SynCommons out of my code and the ugly AV I've been chasing all day has gone away.

The problem is that it's a low level AV - the exception is in the kernal with a truncated call stack, so it's pretty much impossible to debug. I can't step to it because it happens in a DLL during the unload process (as far as I can tell). But I can't afford to spend more time debugging a log tool, sorry.

ab · 2012-02-28 08:23:14

I did make some days ago a correction related to .map logging from .dll in this commit:
http://synopse.info/fossil/info/be458e5fb5
It will solve the problem about logging .map for the .dll.

The sample as implemented in http://synopse.info/fossil/info/103f3e926f shows that the .map is read and used for the MyLibrary.dll:

D:\Dev\lib\SQLite3\Samples\11 - Exception logging\LibraryTest.exe 0.0.0.0 (2012-02-28 09:37:30)
Host=MyPC User=ABouchez CPU=2*9-6-3846 OS=13.1=6.1.7601 Wow64=1 Freq=1818447 Instance=D:\\Dev\\lib\\SQLite3\\Samples\\11 - Exception logging\\MyLibrary.dll
TSynLog 1.16 2012-02-28T09:37:32

20120228 09373220  +    0001E822 MyLibrary.Test (18) 
20120228 09373220 debug 	Called from Test exported procedure
20120228 09373220  -    0001E84B MyLibrary.Test (18)  00.000.002

In your code, you are creating a fLogWriter instance - and I do not know why.
You should not need to use your own fLogWriter, but rely on the one initialized by TSynLog instances.
You AV may come from wrong fLogWriter use.

And you should not use TSynLog.Enter in the main begin..end. block of a library.
Because the ISynLog instance may be released AFTER all other items will be freed.
See http://stackoverflow.com/questions/9282 … 29#9282229

Moz · 2012-02-28 20:52:49

ab wrote:

In your code, you are creating a fLogWriter instance - and I do not know why.

Originally that was because otherwise I didn't get a log file created. Then I needed to specify a buffer size. Then you suggested not doing that, so I stopped. Now I'm not doing it, you're just imagining that I am.

And you should not use TSynLog.Enter in the main begin..end. block of a library.

I worked that out. As I said, removing it caused the problem to go away. The problem for me is that it's not at all obvious how I write a log entry from the main block of the dll. At that stage I don't have a global logging object to call on.

After the first few issues where I report a problem, you tell me that there's a problem and suggest possible fixes, including making code changes, to me suggests an immature product. It may work very well for the author, but it's not ready for public use.

My main suggestion is that you disconnect your logger from the rest of SynCommons, as it's annoying to always have to have SynCommons as the very first include in any unit. But I have to do that otherwise your redeclaration of common functions but using incompatible signatures means I have to make extensive code changes. Have SynLogger use SynCommons, so you can use your functions, just don't make everyone else do so.

But I'm not able to spend time being a beta tester, so I'm going to go with another solution.

ab · 2012-02-28 21:36:02

TSynLog does rely on SynCommons for a lot of features: UTF-8 text handling, variable-length encoding, TDynArray wrapper for the symbol table, serialization, and so on.
Delphi "smart linking" feature makes it no worry to use SynCommons - exe size is still small. You only link what is used.

I think you are a bit rude saying it is an immature project.

Our logging feature has an evolving approach (a client/server feature is on its way), but it is used on production in diverse commercial applications, using versions of the IDE from Delphi 5 up to XE2.
Its symbol table (.mab file) is much smaller than other existing approach (thanks to SynCommons low-level stuff).
Its profiling features are IMHO unique.
We try to have reactive support - but don't forget that Open Source is about a sharing experience, not "use it because it is free".

About how to use the log feature without the interface, you can just use TSynLog.Add.Log(), or use your own TSynLog instance, as stated by the documentation.

Moz · 2012-02-29 04:55:48

ab wrote:

Delphi "smart linking" feature makes it no worry to use SynCommons - exe size is still small. You only link what is used.

But I still have to change every single reference to each function that you redeclare so that it says "SysUtils.SomeFunc" instead of "SomeFunc". That's a lot of code changes. And none of them relate to the logging functionality that I actually want. It reflects a "my way or the highway" approach on your part, where your users are expected to wholeheartedly embrace your whole framework and change everything to work with it. I can't do that. I have to put an explanatory comment next to the include just so my co-workers don't re-order it to match our coding standard and break the build. I was getting away with it as a "I'm just trying this to see if it works", but that's not a long-term solution. I do like the TSynLog.Enter trick, but it's much easier to add that to another logger than force your logger into our code.

ab wrote:

I think you are a bit rude saying it is an immature project.

You've had to make code changes to fix basic things, there is at least one severe bug, and there are things that don't work. I accept that it works for you, and that's great. But I don't think your logger is a useful shareable utility as it is. It's more of an internal part of your Synopse project. I am assuming that the rest of the Synopse code works much better than this internal part does, but I'm open to correction on that.

For comparison, I used OmniThreadLibrary quite a lot and found only one or two minor bugs, despite using it in ways that Primoz had not done. I found him responsive to requests and willing to accept criticism (also quite willing to criticise himself rather than always claiming that his code is wonderful). His code also works well with other peoples code, rather than everything having to change to use it everywhere. I can mix Delphi threads with OTL threads with no problems (great for incrementally changing over, in either direction).

Your code? Not so much. About half of the changes I'd like to make to your code relate to "does not play well with others". For example, adding to the sll... enum is easy. But it's declared in SynCommons. So I have to redo that change every time I get a new version. I'd like to move that and the matching const to a new unit that just has the two declarations. That's not hard. Hard is making SynCommons compatible with our existing code. The redefinitions of standard RTL functions problem is a big obstacle to me. You seem reluctant to extract the logging code from SynCommons, but I'm equally reluctant to make the huge changes to our code that the existing structure requires. And writing a wrapper for a logger impacts performance in a nasty way, especially in the geriatric Delphi 2006 I use at work that doesn't have good inline support.

I appreciate that open source is not "free as in beer", but at the same time I don't have unlimited spare time to contribute to FOSS projects, nor will my boss pay me to do that. So when I try to extract a minor part of your FOSS project and it doesn't do what I want, I don't expect you to make that one aspect your main focus, I accept that your requirements are not the same as mine and look elsewhere.

ab · 2012-02-29 06:34:22

Moz wrote:

It reflects a "my way or the highway" approach on your part, where your users are expected to wholeheartedly embrace your whole framework and change everything to work with it.

To be fair, you just need two units: SynCommons.pas and SynLZ.pas.
Not "the whole framework" at all!!!

Moz wrote:

I was getting away with it as a "I'm just trying this to see if it works", but that's not a long-term solution. I do like the TSynLog.Enter trick, but it's much easier to add that to another logger than force your logger into our code.

Nice to see that some of our ideas are pleasing you.

Moz wrote:

You've had to make code changes to fix basic things, there is at least one severe bug, and there are things that don't work.

Could you be more specific?
Just saying "that don't work" is a bit short.

Moz wrote:

For example, adding to the sll... enum is easy. But it's declared in SynCommons. So I have to redo that change every time I get a new version. I'd like to move that and the matching const to a new unit that just has the two declarations. That's not hard. Hard is making SynCommons compatible with our existing code.

I still do not get that point.
Do you know about Diff utilities? That's what they are for.
I use Total Commander comparison features every day, but you can use WinMerge (or any other) to apply your modifications to an existing unit.
The fact that this is one big unit or several units does not make any difference.
You can have your own version of SynCommons, if you need, and apply patches. But of course, this is not ideal.

About sll.... constants, you have sllCustom1 to sllCustom4 available for your own purpose.
Of course, if you expect others items to be added to the list, just make a proposal, and I'd be happy to make a longer list - since your requirements may fit other's.
I'm not sure that other logging engines are more open to custom events than ours. And the fact that our is a set of levels, instead of levels, did make sense to me: you can log not only at one level (typically error/warning/info/trace), but specify which kind of event you want to log (e.g. error+exception+enter).

Moz wrote:

The redefinitions of standard RTL functions problem is a big obstacle to me.

I understand your concerns, even if I still do not understand what is wrong with the current implementation.
FillChar() and Move() enhanced replacements are very stable: those are untouched FastCode version, as integrated in Delphi RTL.
RecordCopy() may have problems, so I've undefined it by default.
So I've made RecordCopy() disabled by default - may be faulty here, with a small performance gain on common process.
See http://synopse.info/fossil/info/e4a87480a5

Moz wrote:

I appreciate that open source is not "free as in beer", but at the same time I don't have unlimited spare time to contribute to FOSS projects, nor will my boss pay me to do that.

Sorry to hear that.
From my experiment, developing FOSS has a good ROI - with a permissive license like ours (MPL/LGPL/GPL), you can be sure that you can do whatever you want with the source code in the future.

Of course, there are other very good logging solutions around.
You are right, TSynLog is part of our mORMot framework (it was created to add logging to it), but it is also used with old existing huge project code (Delphi 5-Delphi 6, millions of lines of code), with great success.

Thanks for your interest!

Moz · 2012-03-06 23:31:59

Moz wrote:

You've had to make code changes to fix basic things, there is at least one severe bug, and there are things that don't work.

On my machines: There's no debug info in the trace logs of dll log files. Trace logging the load/unload (main code block) of dlls is apparently impossible. Opening SynCommons.pas makes the D2006 IDE even more unstable (a remarkable if dubious achievement).

Moz wrote:

The redefinitions of standard RTL functions problem is a big obstacle to me.

It looks as though you've fixed the include file for D2006, as I no longer get this. Before, your redeclaration of Trim() and Pos() meant that every use of those functions gave me a compile error unless SynCommons was included before SysUtils.

Like I said, the amount of time I have to spend trying to get SynCommons to work, and whining to you on this forum, is an issue. The fact that it's FOSS doesn't really affect its value, or its cost. To date I've probably spent more than $1000 of my employers money trying to make this go. By comparison $500-odd for MadExcept plus half an hour to get it working is cheap.

ab · 2012-03-07 06:28:12

You can't blame SynCommons for bugs in Delphi 2006... please see with Embarcadero support (which will answer it is not supported) or use Delphi 2007 if you do not want to crush the Unicode barrier, but want a more stable release. The latest XE2 license contains a Delphi 2007 license (yes, you can use your employer's money to use a version not supported).

We made workarounds for some regression bugs introduced in Delphi 2009 (and up) - see http://blog.synopse.info/post/2011/01/2 … elphi-2010 and we always try to fix issues in all Delphi versions (even if some IDE versions, like Delphi 2009, is barely usable).
As stated by the documentation, Delphi 5, Delphi 6, Delphi 7, Delphi 2007, Delphi 2010 and Delphi XE2 are tested on our side. Other versions have feedback from users.
None of those IDEs complains about code - even if Delphi XE2 background compiler was buggier than ever: the main compiler works without any problem, but the background compiler fails to understand correct code. See http://stackoverflow.com/questions/7632 … ource-path

In all cases, MadExcept is really a GREAT product, it has features not available in TSynLog (like email reports) but its purpose is smaller: only catch exceptions, not logging.
I'm happy if you are happy with MadExcept.

lestat · 2012-03-30 07:26:30

How can i log log in/out of users from server?

ab · 2012-03-30 07:56:32

lestat wrote:

How can i log log in/out of users from server?

What do you mean exactly?

Within mORMot, user authentication steps are already logged, e.g. in TAuthSession.Create.

By default, all signed request is logged as such in TSQLRestServer.URI:

Log.Log(sllUserAuth,'%/%',[Session.User.LogonName,Context.Session],self);

I've added a missing log at log out time (session deletion).
See http://synopse.info/fossil/info/dac514e940

lestat · 2012-04-06 14:15:14

Thanks ab,
i try the patch and it works.

But i log the sessions deleted after closing the client, but i can't log those deleted by timeout.
How can i do this?

Thanks

ab · 2012-04-06 15:20:56

You are right: authentication session deletions after time out were not properly handled.

This should be fixed by http://synopse.info/fossil/info/a51ce2fac0

mpv · 2012-12-26 14:16:05

It's continue of topic I start here - http://synopse.info/forum/viewtopic.php?pid=5952#p5952
On stress tests I already got AV in server when use this parameters:
with TSynLog.Family do begin
Level := LOG_VERBOSE;
PerThreadLog := ptIdentifiedInOnFile;
AutoFlushTimeOut := 10;
end;
I 100% sure this is because ptIdentifiedInOnFile. Setting PerThreadLog to ptOneFilePerThread pass all my tests.
This exception occurs ONLY in really HARD multithread test ( server run with 12 working thread. 4 client computer run in circle 1 000 000 requests to server). So it very hard for me to understand where exception is, but reason is in TSynLog.AddRecursion - in log recursion depth is bigger than it really is and resursion depth is grows and grows until AV is raised

2AB - I send 2 log files on your e-mail - please, take a look on it. Scroll down AllThreadInOneFile.log file - you can see how recursion is increase. In the end of file no resursion at all and last line - AV. OneFilePerThread.log is example of one thread log when server do the same thing.

ab · 2012-12-26 17:07:14

Ok.

I'm still in vacation but I will check it soon.

Thanks for the feedback.

mpv · 2014-03-15 15:27:36

To close a ticket http://synopse.info/fossil/info/19e567b8ca I test all 3 type of logging (MergedInOneFile, IdentifiedInOnFile, and OneFilePerThread) using my HI load synthetic tests and confirm - no exceptions found. Slowdown of other method compared to OneFilePerThread of about 3% (4 core CPU / 8 server working thread / 1000 concurred connection / 1Gb of log produced). Very good result as for me.. Thanks for your work!

ab · 2014-03-15 15:29:13

Perhaps the slow-down is mainly about the fact that there is a bit more content to write, i.e. the thread number column.

The current implementation is not only based on critical sections, but with a dedicated recursion stack per thread, without any threadvar, but a fast hash of the threadid.
From our tests, it was safe and sound.

I suppose you are using log rotation with 1GB of content!

Thanks for the feedback.

mpv · 2014-03-15 15:53:05

On production I still used OneFilePerThread (so log rotation could not be used). But now, after test IdentifiedInOnFile, I also try to rotate.

docme · 2014-03-27 13:37:29

Curious why the log PerformRotation procedure renames all the log files in sequence; instead of just making the new log file the next number up. (like Delphi history files). Could be either way I think - boolean property driven feature.

mpv · 2014-12-09 14:40:09

AB, we fount the problem with SQL statement logging: I try to execute statement like 'insert into table(clobField) values(?)' and bind into parameter string of 3 Mb length. Inside *Statement.ExecutePrepared I fix code

with Log.Instance do
    if sllSQL in Family.Level then
      LogLines(sllSQL,pointer(SQLWithInlinedParams),self,'--');

This code try to put to log very long statement and my application go to AV
I made small commit to prevent long SQL statement logging (like you do for Postgre)

with Log.Instance do
    if sllSQL in Family.Level then
      Log(sllSQL,SQLWithInlinedParams,self,2048);

But this is partial solution. My propose is to change function GetSQLWithInlinedParams to be called in this way:

with Log.Instance do
    if sllSQL in Family.Level then
      Log(sllSQL,GetSQLWithInlinedParams(2048),self,2048);

Can I create a ticket?

P.S.
Or may me even better to log only fSQL and not to insert parameters at all...

Last edited by mpv (2014-12-09 15:19:31)

ab · 2014-12-09 16:54:03

You may create a ticket, indeed.

ab · 2014-12-12 15:33:39

We have added the new TSQLDBConnectionProperties.LoggedSQLMaxSize property to limit the logged SQL content as requested by http://synopse.info/fossil/tktview/0b6006e4f5b6
See http://synopse.info/fossil/info/d794746547

mORMot Open Source

#1 2011-04-13 11:13:20

Introducing enhanced logging mechanism

#2 2011-04-14 12:20:58

Re: Introducing enhanced logging mechanism

#3 2011-04-15 07:01:49

Re: Introducing enhanced logging mechanism

#4 2011-05-12 16:43:10

Re: Introducing enhanced logging mechanism

#5 2011-05-12 17:36:58

Re: Introducing enhanced logging mechanism

#6 2011-05-13 01:02:36

Re: Introducing enhanced logging mechanism

#7 2011-05-13 05:31:08

Re: Introducing enhanced logging mechanism

#8 2011-05-13 07:12:39

Re: Introducing enhanced logging mechanism

#9 2011-05-17 15:34:45

Re: Introducing enhanced logging mechanism

#10 2011-06-04 07:52:32

Re: Introducing enhanced logging mechanism

#11 2011-06-04 18:21:55

Re: Introducing enhanced logging mechanism

#12 2011-06-08 07:42:54

Re: Introducing enhanced logging mechanism

#13 2011-06-08 13:08:16

Re: Introducing enhanced logging mechanism

#14 2011-09-03 07:24:56

Re: Introducing enhanced logging mechanism

#15 2011-10-26 09:43:07

Re: Introducing enhanced logging mechanism

#16 2011-10-26 11:23:13

Re: Introducing enhanced logging mechanism

#17 2012-02-19 23:33:29

Re: Introducing enhanced logging mechanism

#18 2012-02-20 09:43:17

Re: Introducing enhanced logging mechanism

#19 2012-02-20 21:56:49

Re: Introducing enhanced logging mechanism

#20 2012-02-21 08:25:35

Re: Introducing enhanced logging mechanism

#21 2012-02-21 22:54:48

Re: Introducing enhanced logging mechanism

#22 2012-02-22 08:21:06

Re: Introducing enhanced logging mechanism

#23 2012-02-22 23:34:42

Re: Introducing enhanced logging mechanism

#24 2012-02-23 08:36:59

Re: Introducing enhanced logging mechanism

#25 2012-02-23 11:16:40

Re: Introducing enhanced logging mechanism

#26 2012-02-23 21:28:29

Re: Introducing enhanced logging mechanism

#27 2012-02-23 22:03:11

Re: Introducing enhanced logging mechanism

#28 2012-02-24 08:23:18

Re: Introducing enhanced logging mechanism

#29 2012-02-27 21:16:18

Re: Introducing enhanced logging mechanism

#30 2012-02-28 03:36:02

Re: Introducing enhanced logging mechanism

#31 2012-02-28 08:23:14

Re: Introducing enhanced logging mechanism

#32 2012-02-28 20:52:49

Re: Introducing enhanced logging mechanism

#33 2012-02-28 21:36:02

Re: Introducing enhanced logging mechanism

#34 2012-02-29 04:55:48

Re: Introducing enhanced logging mechanism

#35 2012-02-29 06:34:22

Re: Introducing enhanced logging mechanism

#36 2012-03-06 23:31:59

Re: Introducing enhanced logging mechanism

#37 2012-03-07 06:28:12

Re: Introducing enhanced logging mechanism

#38 2012-03-30 07:26:30

Re: Introducing enhanced logging mechanism

#39 2012-03-30 07:56:32

Re: Introducing enhanced logging mechanism

#40 2012-04-06 14:15:14