TraceMethod oddity

CodeSite logging interface classes: default "CodeSite" logger, T|CodeSiteLogger class, destinations, formatters, etc.

TraceMethod oddity

Postby ogiesen » Wed May 30, 2012 4:15 am

I'll explain later why we did this, but first look at this code (simplified for illustration):

Code: Select all
type
  IDbgMethodLogger = ICodeSiteMethodTracer;

function DbgLogMethod(const AMethodName: String; const AArgs: array of const): IDbgMethodLogger; overload;
begin
  Result := CodeSite.TraceMethod(Format(AMethodName, AArgs));
end;

function DbgLogMethod(const AMethodName: String): IDbgMethodLogger; overload;
begin
  Result := DbgLogMethod(AMethodName, []);
end;

procedure P2(const AMsg: String);
begin
  DbgLogMethod('P2("%s")', [AMsg]);
  CodeSite.Send(AMsg);
end;

procedure P1;
begin
  DbgLogMethod('P1');
  P2('Booyah!');
end;

begin
  P1;
end.

Surprisingly, this produces the following output in CodeSite:

Code: Select all
->P1
<-P1
->P2("Booyah!")
  Booyah!
<-P2("Booyah!")

You'll notice that the output from the P2 method is not nested inside P1. However, if I change the implementation of the two log methods to this:

Code: Select all
function DbgLogMethod(const AMethodName: String): IDbgMethodLogger; overload;
begin
  Result := CodeSite.TraceMethod(AMethodName);
end;

function DbgLogMethod(const AMethodName: String; const AArgs: array of const): IDbgMethodLogger; overload;
begin
  Result := DbgLogMethod(Format(AMethodName, AArgs));
end;

...then I get the expected, properly nested output:

Code: Select all
->P1
  ->P2("Booyah!")
    Booyah!
  <-P2("Booyah!")
<-P1


Explanation:
As you might have guessed, this sprang from an effort to ease the transition from a homegrown logging "framework" (I use the term in a very loose sense here) in an existing project. There are literally thousands of log statements in the existing code already and rather than modifying all that code at once straight away, I reimplemented the existing log routines as a thin wrapper for CodeSite calls. This allows me to continue logging straight away during the transition phase. I intend to convert the statements to "native" CodeSite calls along the way.

Now, apparently something goes awry with the interface reference counting here when forwarding the open array argument as is, causing ExitMethod to be called too soon. This was not a problem with our old code. In comparison to TCodeSiteProfiler (i.e. the class that ultimately implements ICodeSiteMethodTracer) our helper class logged enter/leave-method not in _AddRef/Release but rather in its constructor/destructor.

In the above example the solution/workaround is simple enough but I wonder what else I might have to look out for...

[in case that matters here: I'm using Delphi XE2 with Update 4 and Hotfix 1 and CodeSite Studio 5.1]

Cheers,

Oliver
ogiesen
 
Posts: 6
Joined:
Tue May 29, 2012 4:31 pm

Re: TraceMethod oddity

Postby Raize Support » Wed May 30, 2012 4:17 pm

Hi,

Thanks for reporting your findings. After a brief look, the first thing that comes to mind is why you just didn't call CodeSite.TraceMethod in each of the overloads? That is, there is really no need to introduce the extra level of indirection between the two DbgLogMethod overrides. That is, following does work as expected.

Code: Select all
function DbgLogMethod(const AMethodName: String; const AArgs: array of const): IDbgMethodLogger; overload;
begin
  Result := CodeSite.TraceMethod(Format(AMethodName, AArgs));
end;

function DbgLogMethod(const AMethodName: String): IDbgMethodLogger; overload;
begin
  Result := CodeSite.TraceMethod( AMethodName );
end;



Ray
Raize Software Support
Raize Software
http://www.raize.com
Raize Support
 
Posts: 622
Joined:
Fri Mar 25, 2011 9:04 pm

Re: TraceMethod oddity

Postby ogiesen » Wed May 30, 2012 5:16 pm

Hi Ray!

Yes, that is an obvious fix/workaround indeed when there are only two overloads. My actual code however has six more overloaded versions of DbgLogMethod and I simply wanted to keep implementation duplication to a minimum.

Do you have any idea yet why TraceMethod doesn't work as expected in the first case?

Cheers,

Oliver
ogiesen
 
Posts: 6
Joined:
Tue May 29, 2012 4:31 pm

Re: TraceMethod oddity

Postby Raize Support » Thu May 31, 2012 2:31 am

Hi Oliver,

I don't have a specific reason as to why the first example does not work as expected. However, the behavior is certainly related to the empty open array parameter. For example, if you change the second DbgLogMethod to the following:

Code: Select all
function DbgLogMethod(const AMethodName: String): IDbgMethodLogger; overload;
begin
  Result := DbgLogMethod(AMethodName, [ 'Test' ]);
end;


The output is what is expected. From what I can tell by stepping through the code is that the open array parameter being called in your overloaded procedure is resulting in a copy of the interface reference. And when the first DbgLogMethod procedure exits, the copy is released and that is causing the P1 exit-method message to show up in the log. I'm not sure if there is anything that we can check for in the code to somehow prevent that from happening.

Ray
Raize Software Support
Raize Software
http://www.raize.com
Raize Support
 
Posts: 622
Joined:
Fri Mar 25, 2011 9:04 pm

Re: TraceMethod oddity

Postby ogiesen » Thu May 31, 2012 3:25 am

Yes, that's what I suspected out, too. However, as I wrote, my old code wasn't affected by this. The following produces properly nested output:

Code: Select all
type
  IDbgMethodLogger = interface
  end;

  TDbgMethodLogger = class(TInterfacedObject, IDbgMethodLogger)
  private
    FName: String;
  public
    constructor Create(const AName: String; const AArgs: array of const);
    destructor Destroy; override;
  end;

constructor TDbgMethodLogger.Create(const AName: String; const AArgs: array of const);
begin
  inherited Create();
  FName := Format(AName, AArgs);
  CodeSite.EnterMethod(FName);
end;

destructor TDbgMethodLogger.Destroy;
begin
  CodeSite.ExitMethod(FName);
  inherited Destroy;
end;

function DbgLogMethod(const AName: String; const AArgs: array of const): IDbgMethodLogger; overload;
begin
  Result := TDbgMethodLogger.Create(AName, AArgs);
end;

function DbgLogMethod(const AName: String): IDbgMethodLogger; overload;
begin
  Result := DbgLogMethod(AName, []);
end;

procedure P2(const AMsg: String);
begin
  DbgLogMethod('P2("%s")', [AMsg]);
  CodeSite.Send(AMsg);
end;

procedure P1;
begin
  DbgLogMethod('P1');
  P2('Hiya!');
end;

begin
  P1;
end.


As far as I can tell the main difference between the two implementations is that mine uses the constructor and destructor for triggering Enter/ExitMethod while CodeSite uses _AddRef and _Release...

Anyway, not a big issue as it's easy enough to work around or avoid altogether. Just trying to understand what's going on...

Cheers,

Oliver
ogiesen
 
Posts: 6
Joined:
Tue May 29, 2012 4:31 pm


Return to Loggers

Who is online

Users browsing this forum: No registered users and 2 guests

cron