Code Tracing

• Download source - 580.2 KB

Introduction

Tracer helps ease up developer's application performance tuning, logging &/or exception handling tasks. Instead of focusing on the teeny weeny details of code instrumentation, Tracer puts the developer in the driver's seat in both code instrumentation (for logging) efforts & application monitoring & technical support.

Background

Recently, there are developments in the area of Aspect Oriented Programming(AOP). However, specifically for logging and tracing, yours truly had been dabbling around this somewhat an AOP concept for years now, but finally, he's able to come up with a souped up, zero perf baggage solution (a high performant Tracing API!).

Thus, Tracer was born. It is the author's attempt/concept on cross cutting requirements for logging and code tracing in application's development.

Using the Code

In order for an application or API to be easily supportable in production environments, developers typically instrument code they are authoring with calls to the logging API in key areas of the app he or she is implementing.

A typical code block with logging and exception handling looks like:

void Main()
{
  try
  {
    Log(Info, "Before calling Foo(123).");
    DateTime t1 = DateTime.Now();
    Foo(123);
    DateTime t2 = DateTime.Now();
    Log(Info, "After calling Foo(123). Run time:{0} milli", t2.Subtract(t1).TotalMilliSeconds);
  }
  catch(Exception exc)
  {
    Log(Error, "Exception occurred in Foo(123), details: " + exc.Message);
    throw exc;
  }
}
void Foo(int i)
{
  // your elegant and cool code here. :)
}

Using Tracer, that exact code block shown above is reduced into one line of code such as:

void Main()
{
  Tracer.Invoke(Foo, 123, funcFootprint: "Foo(123)");
}
void Foo(int i)
{
  // your elegant and cool code here. :)
}

Via usage of Lambda expression, Tracer is able to offer a code tracing solution without adding unnecessary performance baggage to your application. It doesn't use Reflection or anything that impacts performance. Plus, Tracer offers full customizable features usable for integration to your application.

Tracing API

Flow Description

On application initialization, the respective application event handlers are hooked in to Tracer so the application can take care of interfacing (or logging) with respective Log Targets setup for use by the logging framework.

Application uses Tracer.Invoke to execute high level function(s), pass necessary parameters, invoke verbosity flag(s), function call footprint (name & parameter values). Invoke executes the submitted function calling necessary event handlers as necessary.

It has the following member events which are useful for integration:

• OnLog event - used to specify log event handler for pre/post call (information) logging to your favorite Logging framework.
• OnLogException event - used to specify method handler for logging an exception encountered when running a method for invoke.
• OnException event - used to specify a method for handling an exception generated when running a method for invoke.
• OnEventException event - used to specify a method for handling an exception encountered by Tracer when it tries to log some information about the method call. Usual suspect when this is encountered is mis-configuration of the logging API used by your app, so, when OnLog event is called, it throws an exception due to this logging mis-configuration.

Class Hierarchy

• InvokeWrapperBase - base class containing logic that manages submitted function or method execution, try-catch wrapping and calling necessary event handlers across the execution life cycle. This defines the overridable (virtual) methods used for raising events such as: OnEnter, OnLeave, OnException & OnEventException. Basic or generic member events such as OnException and OnEventException are also defined.
• InvokeWrapper - derives from InvokeWrapperBase class and implements for general purpose use function or method execution event handling. It adds OnEnter & OnLeave event members.
• Tracer - derives from InvokeWrapperBase class and implements the trace-logging domain specific member events such as: OnLog, OnLogException. Tracer takes care of generating nicely formatted messages to convey appropriate meaning and content based on which event type is invoked. For example, when OnLeave event is raised after calling the submitted function, OnLog event is invoked passing a message about the event type (post run call), optional function run time (elapsed) measurement & the function call footprint passed in to the invoke call.

Control Knobs?

Following are available to control logs generation:

• InvokeVerbosity parameter allows a user to control what logs to generate, e.g. - there is a flag for OnEnter, OnLeave, OnException.
• static Enabled field allows the user to disable the invoke try-catch wrapper. This is useful for (usually temporarily) allowing developer to globally turn off call wrapping which is useful when debugging methods submitted to Tracer for invoke. The method is invoked directly or outside of the call wrapper, thus, the developer is able to navigate or debug step-in to the method quite easily just like method is invoked directly without Tracer use.

TraceScope

TraceScope usage is another way of doing trace logging without calling the Tracer.Invoke method. However, via TraceScope usage, Tracer is not able to do exception event handling. Your code has to handle exception and its logging requirements.

Sample code using TraceScope:

void main()
{
  using(new TraceScope(Tracer, "Foo(123)"))
  {
    Foo(123);
  }
}
void Foo(int i)
{
  // your elegant and cool code here. :)
}

Results Evaluator

Code can control whether to generate a post method execution event (OnLeave event) or not, and what kind of message log to generate based on method results evaluation. Specify a ResultsEvaluator delegate and Tracer will call this function to determine whether to call the Tracer's OnLog event handler or not. Action Result returned by the evaluator function drives whether Tracer will log Pass, Fail messages or skip logging.

Here is an example using the ResultsEvaluator:

void main()
{
  // ctor for new EnterpriseTracer; specify log category & ResultEvaluator delegate params.
  EnterpriseTracer Tracer = new EnterpriseTracer(
    new string[] { "ResultsEvaluator Msg Category" }, resultEval);
  using (new Tracing.MSEnterpriseLogging.TraceScope(Tracer, "Foo(123)"))
  {
    Foo(123);
  }
}
// Result Evaluator sample method.
private static ResultActionType resultEval(object result, TimeSpan? runTime, out string customMessage)
{
  if (runTime.Value.TotalSeconds >= 5)
  {
    // log a failed warning msg if method took more than 4 seconds.
    customMessage = "Warning! Method took more than 4 secs to run.";
    return ResultActionType.Fail;
  }
  // log a passed msg if method ran faster than 5 seconds.
  customMessage = null;
  return ResultActionType.Pass;
}

void Foo(int i)
{
  // your elegant and cool code here. :)
}

Custom On Leave Event Handling

You can specify your custom OnLeave event handler if you'd like to run some custom code right after calling the method submitted for invoke. Tracer will call this event handler passing necessary parameters for it to do necessary task such as making a log call based on the performance of the method invoked.

Sample code specifying a custom OnLeave event handler:

private static void DemoEnterpriseTracerWithCustomOnLeave()
{
  // create a Tracer instance passing a log Category.
  var Tracer = new EnterpriseTracer(new string[] { "DemoEnterpriseTracerWithCustomOnLeave" });
  // specify a custom OnLeave event handler
  Tracer.OnLeave += Tracer_OnLeave;
  // Invoke the method "Foo()"
  Tracer.Invoke(Foo, funcFootprint: "Foo()");
}
private static void Tracer_OnLeave(InvokeWrapperBase sender, object result, 
     string funcFootprint, TimeSpan? runTime)
{
  // Log a failure msg "Too slow, 'failed" if run time took more than five seconds.
  if (runTime.Value.TotalSeconds > 5)
  {
    Tracer_OnLog(LogLevels.Warning, ((Tracing.Tracer)sender).Category, "Too slow, 'failed!");
    return;
  }
  // log a pass message, otherwise.
  Tracer_OnLog(LogLevels.Information, ((Tracing.Tracer)sender).Category, 
               string.Format("Passed calling {0}.", funcFootprint));
}

Logging Framework Integration

Integration to a logging framework is simple enough. Provide and implement the Tracer's OnLog and OnLogException event handlers to write or log to your favorite logging framework such as MS Enterprise Logging, nLog, etc...

Here is a sample code implementation to show extending the Tracer class and providing integration hooks for the MS Enterprise Logging framework:

public class EnterpriseTracer : Tracing.Tracer
{
    public EnterpriseTracer() : this(null, null) { }
    public EnterpriseTracer(string[] category = null, ResultEvaluatorDelegate resultEvaluator = null,
        bool hookDefaultEventHandler = true) : base(category, resultEvaluator)
    {
        if (hookDefaultEventHandler)
        {
            OnLog += Log;
            OnLogException += LogException;
        }
    }
    private void LogException(System.Exception exc, string[] category, string message)
    {
       Log(LogLevels.Error, category, 
           string.Format(MessageStrings.MessageWithDetailsMessageTemplate, message, exc.ToString()));
    }
    private void Log(LogLevels logLevel, string[] category, string message)
    {
        try
        {
            // Populate LogEntry w/ log message.
            LogEntry logEntry = new LogEntry();
            logEntry.Message = message;
            if (category != null)
            {
                foreach (var c in category)
                    logEntry.Categories.Add(c);
            }
            logEntry.Priority = 1;
            logEntry.Severity = Tracer.Convert(logLevel);
            Logger.Write(logEntry);
        }
        catch (System.Exception exc)
        {
            // catch and throw TraceException to tell Tracer something went wrong during logging,
            // perhaps MSEL is not configured properly, etc...
            throw new TraceException(
              Tracer.Format(MessageStrings.FailedLoggingMessageTemplate, message), exc);
        }
    }
}

Customizable Tracer Emitted Messages

Tracer's generated messages are customizable, they are compiled in one class for easy management. Please feel free to customize to fit your needs/taste the messages, errors and template strings in the MessageStrings.cs file.

Unit Tests?

In the Tracer zip, there are unit tests created to both test the API and to showcase different Tracer features.

Sample App & Logging Integration?

A simple app was also included in the Tracer zip that logs to the Console. This also demonstrates how to plugin Tracer to your favorite Logging framework.

Points of Interest

Being able to offer an optimal and flexible solution for simplifying code tracing is a fun challenge.

History

• 10/04/2015 - Added discussion on Integration with Logging Framework & custom OnLeave event handler.
• 09/26/2015 - Added support more fine grain control on the OnLeave event handling, e.g. - ResultEvaluator delegate, custom OnLeave event handler; Also added sample implementation for MS Enterprise Logging framework. See the new downloadable zip with these changes and more demos to show these new feature.
• 09/11/2015 - Made code also available via git in: https://github.com/SharedCode
• 09/09/2015 - Added C# "using" keyword/feature support via new TraceScope class
• 09/04/2015 - Initial submission