#1 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-03-06 23:31:59

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

#2 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-29 04:55:48

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

#3 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-28 20:52:49

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

#4 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-28 03:36:02

Moz

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.

#5 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-27 21:16:18

Moz

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.

#6 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-23 22:03:11

Moz

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?

#7 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-23 21:28:29

Moz
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 smile

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

#8 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-22 23:34:42

Moz

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.

#9 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-21 22:54:48

Moz
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 smile

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

#10 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-20 21:56:49

Moz

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

#11 Re: Source Code repository » Introducing enhanced logging mechanism » 2012-02-19 23:33:29

Moz

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.

Board footer

Powered by FluxBB