Holy Grail of Application Profiling with AOP

What’s the Holy Grail of Application Profiling?  Well, it should be…

  • Rich Data – Giving us detailed logging ability, recording which method is being called, where it’s being called from, when it starts, when it stops, overall execution time –and- if any exceptions are thrown.
  • Low Impact – Adds just a fraction of a second to the methods being profiled, highly performant. ( MS-Word says “performant” isn’t a word – Wiktionary and I disagree <grin> )
  • Minimal Code – Follows the D.R.Y. principle ( Don’t Repeat Yourself), less code == easier maintenance and generally better performance.
  • Loosely Coupled – Easy to add to a project, with little to no code added to the existing code.

So… How do we create the Holy Grail of Application Profiling?  We use a very cool technology called AOP ( Aspect Oriented Programming ). 

AOP complements Object-Oriented Programming (OOP), giving us even more tools that increase modularity and allowing us to elegantly handle “crosscutting concerns” such as logging, exception handling and other common challenges.  One of the most popular AOP tools is PostSharp (http://www.sharpcrafters.com/), which allows us to “IL Weave” our profiling code ( the act of adding code as IL instructions into the assemblies at compile time )!  Sweet…

So let’s start at the end – what do we get? 

We’ll if you start a brand new “MVC 4 Web Project” in Visual Studio – by adding a couple references and ONE line in your AssemblyInfo.cs file…

 

[assembly: ProfileAspect(AttributeTargetTypes = "ProfileWeb.Controllers.*")]

We can start logging to SQL and, for example, easily extract really rich data on pages hit and their load times such as…

image

Nice… Not bad for ONE line of code… Intrigued?  I know you would be…  🙂

Download the Profiler Code (44 MB)

I’ve included demo code / SQL, etc for your review – but here are the highlights of how to build the AOP “aspect” for profiling.

imageSo my project layout is as shown…

“Common.All” is my shared library that has Helper methods and code Extensions, etc – it’s my “code it, then forget how you coded it – and just call the cool methods you already made” library.  As always, it could use some additional house keeping, but it’s a great help in all my projects – feel free to use what you want out if it for your other projects.  And if you have cool code to add – send it to me, love to see it!

“Common.Aspects” is a very clean way of extracting all of the AOP “aspect” code out so we can include it cleanly in this and any other project.

“Common.Logging” is my ( not unexpected ) logging library – nice to have it wrapped up in it’s own library so you can use your favorite flavor of logger – I’m using NLog – which I add to the NuGet package installer.  Note, you need to copy the NLog.config file into each of your projects for which you are logging – gives you the flexibility to have different project logged with different levels of detail.

“Common.Models” are some model classes that I needed to share between libraries – specifically the “Profile” model that gets used in both the “Common.Aspects” and the “Common.Logging” libraries.

“ProfileConsole” is the C# Console app – that we use for testing impact through timing – play with your settings, logging configuration, etc – then use this to get an easy measurable way ( as I will show ) to see the impact of those settings.

“ProfileWeb” is a straight out of the box MVC4 “Internet” Web project.  This shows really how little code it takes to utilize the powerful feature of everything else that we’ve built!!!

There is a lot of great code in the “Common” projects – but we’ll just hit the highlights and let you then explorer the rest on your own.  But lets start by looking at the AOP code!  Note, I’m pretty OCD about including comments – mainly so when I come back in 6 months, _I_ remember why it was done this way – so I’ll leave those comments to explain the code. 🙂

 

   1:  using Common.All.Helpers;
   2:  using Common.Logging;
   3:  using Common.Models;
   4:  using PostSharp.Aspects;
   5:  using System;
   6:   
   7:  namespace Common.Aspects
   8:  {
   9:      [Serializable]
  10:      public class ProfileAspect : OnMethodBoundaryBaseAspect
  11:      {
  12:          /// <summary>
  13:          /// Method executed <b>before</b> the body of methods to which this aspect is applied.
  14:          /// </summary>
  15:          /// <param name="args">Event arguments specifying which method
  16:          /// is being executed, which are its arguments, and how should the execution continue
  17:          /// after the execution of <see cref="M:PostSharp.Aspects.IOnMethodBoundaryAspect.
  18:          ///   OnEntry(PostSharp.Aspects.MethodExecutionArgs)" />.</param>
  19:          public override void OnEntry(MethodExecutionArgs args)
  20:          {
  21:              //----------------------------------------------------------------------
  22:              // Ignore specified methods
  23:              //----------------------------------------------------------------------
  24:              if (IgnoreMethods(args)) return;
  25:   
  26:              //----------------------------------------------------------------------
  27:              // Create a new instance Profiler, start the stopwatch and persist to state
  28:              // Use the Fluent design pattern for .Start() as defined in our Profiler model
  29:              //----------------------------------------------------------------------
  30:              Profiler profile = new Profiler(AspectBoundaryType.OnEntry, args).Start();
  31:   
  32:              //----------------------------------------------------------------------
  33:              // Get the values from the calling AssemblyInfo.cs file attributes
  34:              // Use our customr AssemblyInfoCalling() class - that crawls the Stack
  35:              //  so we can get this information in as Loosely Coupled manner as possible
  36:              //----------------------------------------------------------------------
  37:              AssemblyInfoCalling assembly = new AssemblyInfoCalling();
  38:              profile.Application.Name = assembly.Title;
  39:              profile.Application.Version = assembly.VersionFull;
  40:              profile.Location.Name = assembly.Location;
  41:              args.MethodExecutionTag = profile;
  42:   
  43:              //----------------------------------------------------------------------
  44:              // Log the profiler object to our custom Logger class
  45:              //----------------------------------------------------------------------
  46:              _log = new Log();
  47:              _log.Profile(profile);
  48:          }
  49:   
  50:          /// <summary>
  51:          /// Method executed <b>after</b> the body of methods to which this aspect is applied,
  52:          /// but only when the method successfully returns (i.e. when no exception flies out
  53:          /// the method.).
  54:          /// </summary>
  55:          /// <param name="args">Event arguments specifying which method
  56:          /// is being executed and which are its arguments.</param>
  57:          public override void OnSuccess(MethodExecutionArgs args)
  58:          {
  59:              //----------------------------------------------------------------------
  60:              // Ignore specified methods
  61:              //----------------------------------------------------------------------
  62:              if (IgnoreMethods(args)) return;
  63:   
  64:              //----------------------------------------------------------------------
  65:              // Get the instance of Profiler, update the values and save back to persistant state
  66:              //----------------------------------------------------------------------
  67:              Profiler profile = (Profiler)args.MethodExecutionTag;
  68:              args.MethodExecutionTag = profile.Update(AspectBoundaryType.OnSuccess, args);
  69:   
  70:              //----------------------------------------------------------------------
  71:              // Log the profiler
  72:              //----------------------------------------------------------------------
  73:              _log.Profile(profile);
  74:          }
  75:   
  76:          /// <summary>
  77:          /// Method executed <b>after</b> the body of methods to which this aspect is applied,
  78:          /// even when the method exists with an exception (this method is invoked from
  79:          /// the <c>finally</c> block).
  80:          /// </summary>
  81:          /// <param name="args">Event arguments specifying which method
  82:          /// is being executed and which are its arguments.</param>
  83:          public override void OnExit(MethodExecutionArgs args)
  84:          {
  85:              //----------------------------------------------------------------------
  86:              // Ignore specified methods
  87:              //----------------------------------------------------------------------
  88:              if (IgnoreMethods(args)) return;
  89:   
  90:              //----------------------------------------------------------------------
  91:              // Get the instance of Profiler, stop the stopwatch and update values
  92:              //----------------------------------------------------------------------
  93:              Profiler profile = (Profiler)args.MethodExecutionTag;
  94:              profile.Update(AspectBoundaryType.OnExit, args).Stop();
  95:   
  96:              //----------------------------------------------------------------------
  97:              // Log the profiler
  98:              //----------------------------------------------------------------------
  99:              _log.Profile(profile);
 100:          }
 101:   
 102:          /// <summary>
 103:          /// Method executed <b>after</b> the body of methods to which this aspect is applied,
 104:          /// in case that the method resulted with an exception.
 105:          /// </summary>
 106:          /// <param name="args">Event arguments specifying which method
 107:          /// is being executed and which are its arguments.</param>
 108:          public override void OnException(MethodExecutionArgs args)
 109:          {
 110:              //----------------------------------------------------------------------
 111:              // Get the instance of Profiler, stop the stopwatch and update values
 112:              //----------------------------------------------------------------------
 113:              Profiler profile = (Profiler)args.MethodExecutionTag;
 114:              profile.Update(AspectBoundaryType.OnException, args);
 115:   
 116:              //----------------------------------------------------------------------
 117:              // Log the profiler
 118:              //----------------------------------------------------------------------
 119:              _log.Profile(profile);
 120:          }
 121:   
 122:          /// <summary>
 123:          /// Ignores these methods when profiling - add to these as you see fit, may be
 124:          /// a better way of excluding these through the assembly reference in PostSharp -
 125:          /// will have to check with the PostSharp devs. :)  But for now - this keeps
 126:          /// some of the unwanted "chatter" out of our data
 127:          /// </summary>
 128:          /// <param name="args">The args.</param>
 129:          /// <returns></returns>
 130:          private static bool IgnoreMethods(MethodExecutionArgs args)
 131:          {
 132:              switch (args.Method.Name)
 133:              {
 134:                  //----------------------------------------------------------------------
 135:                  // Don't want to see the timing for the Controller's constructors
 136:                  //----------------------------------------------------------------------
 137:                  case ".ctor":
 138:                      return true;
 139:                  default:
 140:                      return false;
 141:              }
 142:          }   
 143:      }
 144:  }

 

So PostSharp will take the above code – and “weave” it into the code – so using ILSpy (free) or JustDecompile (also free, and my favorite) – you can see a with and without AOP.

This is “without” – nice, clean – you see what it’s trying to do ( which isn’t much in this case ) – but if you had to code all of the do do profiling / exception handling, etc – that would be a maintenance nightmare – to the point where it just wouldn’t get done.

   1:  public ActionResult Index()
   2:  {
   3:      ViewBag.Message = "Modify this template to jump-start your ASP.NET MVC application.";
   4:   
   5:      return View();
   6:  }

And this is what we see when we decompile the same method – wow…  Glad I didn’t have to add all that great code to every method manually…!

   1:  public ActionResult Index()
   2:  {
   3:      ActionResult returnValue = null;
   4:      Arguments empty = Arguments.Empty;
   5:      MethodExecutionArgs methodExecutionArg = new MethodExecutionArgs(this, empty);
   6:      MethodBase methodBase = HomeController.HomeController.m1;
   7:      methodExecutionArg.Method = methodBase;
   8:      HomeController.HomeController.a23.OnEntry(methodExecutionArg);
   9:      if (methodExecutionArg.FlowBehavior != FlowBehavior.Return)
  10:      {
  11:          try
  12:          {
  13:              try
  14:              {
  15:                  ((dynamic)base.ViewBag).Message = "Modify this template to jump-start your ASP.NET MVC application.";
  16:                  ActionResult actionResult = base.View();
  17:                  returnValue = actionResult;
  18:                  methodExecutionArg.ReturnValue = returnValue;
  19:                  HomeController.HomeController.a23.OnSuccess(methodExecutionArg);
  20:                  returnValue = (ActionResult)methodExecutionArg.ReturnValue;
  21:              }
  22:              catch (Exception exception1)
  23:              {
  24:                  Exception exception = exception1;
  25:                  methodExecutionArg.Exception = exception;
  26:                  HomeController.HomeController.a23.OnException(methodExecutionArg);
  27:                  switch (methodExecutionArg.FlowBehavior)
  28:                  {
  29:                      case FlowBehavior.Continue:
  30:                      {
  31:                          methodExecutionArg.Exception = null;
  32:                          break;
  33:                      }
  34:                      case FlowBehavior.Return:
  35:                      {
  36:                          methodExecutionArg.Exception = null;
  37:                          returnValue = (ActionResult)methodExecutionArg.ReturnValue;
  38:                          break;
  39:                      }
  40:                      case FlowBehavior.ThrowException:
  41:                      {
  42:                          throw methodExecutionArg.Exception;
  43:                      }
  44:                      default:
  45:                      {
  46:                          throw;
  47:                      }
  48:                  }
  49:              }
  50:          }
  51:          finally
  52:          {
  53:              methodExecutionArg.ReturnValue = returnValue;
  54:              HomeController.HomeController.a23.OnExit(methodExecutionArg);
  55:              returnValue = (ActionResult)methodExecutionArg.ReturnValue;
  56:          }
  57:      }
  58:      else
  59:      {
  60:          returnValue = (ActionResult)methodExecutionArg.ReturnValue;
  61:      }
  62:      return returnValue;
  63:  }

So other highlights – in the “Common.Models” library – the “Profiler” class contains all the information we’re capturing – but also nicely contains “fluent” patterned methods for Start(), Stop() and Update() – also does a nice job of overriding the ToString() so we can cleanly write out a message just by calling it’s ToString() method.

 

   1:  public class Profiler
   2:  {
   3:      #region | Properties |
   4:   
   5:      public AspectBoundaryType BoundaryType { get; set; }
   6:      public DateTime? dateEnd { get; set; }
   7:      public DateTime? dateStart { get; set; }
   8:      public string MethodDeclaringTypeName { get; set; }
   9:      public string MethodName { get; set; }
  10:      public List<string> MethodParameters { get; set; }
  11:      public bool MethodParametersExist { get; set; }
  12:      public object ReturnValue { get; set; }
  13:      public Exception Exception { get; set; }
  14:      public ProfilerLocation Location { get; set; }
  15:      public ProfilerApplication Application { get; set; }
  16:   
  17:      private Stopwatch Stopwatch { get; set; }
  18:      public long EllapsedTime
  19:      {
  20:          get
  21:          {
  22:              return this.dateEnd != null ? this.Stopwatch.ElapsedMilliseconds : 0;
  23:          }
  24:      }
  25:   
  26:      #endregion
  27:   
  28:      #region | Constructors |
  29:   
  30:      /// <summary>
  31:      /// Initializes a new instance of the <see cref="Profiler"/> class.
  32:      /// </summary>
  33:      public Profiler(AspectBoundaryType boundaryType, MethodExecutionArgs args)
  34:      {
  35:          this.BoundaryType = boundaryType;
  36:          if (args.Method.DeclaringType != null) this.MethodDeclaringTypeName = args.Method.DeclaringType.Name;
  37:          this.MethodName = args.Method.Name;
  38:   
  39:          if (this.Location == null) this.Location = new ProfilerLocation();
  40:          if (this.Application == null) this.Application = new ProfilerApplication();
  41:      }
  42:   
  43:      #endregion
  44:   
  45:      #region | Methods |
  46:   
  47:      /// <summary>
  48:      /// Starts this timers.
  49:      /// </summary>
  50:      /// <returns>Fluent pattern instance</returns>
  51:      public Profiler Start()
  52:      {
  53:          this.Stopwatch = Stopwatch.StartNew();
  54:          this.dateStart = DateTime.Now;
  55:   
  56:          return this;
  57:      }
  58:   
  59:      /// <summary>
  60:      /// Stops this timers.
  61:      /// </summary>
  62:      /// <returns>Fluent pattern instance</returns>
  63:      public Profiler Stop()
  64:      {
  65:          this.Stopwatch.Stop();
  66:          this.dateEnd = DateTime.Now;
  67:   
  68:          return this;
  69:      }
  70:   
  71:      /// <summary>
  72:      /// Updates the profile values
  73:      /// </summary>
  74:      /// <param name="boundaryType">Type of the boundary.</param>
  75:      /// <param name="args">The args.</param>
  76:      /// <returns>Fluent pattern instance</returns>
  77:      public Profiler Update(AspectBoundaryType boundaryType, MethodExecutionArgs args)
  78:      {
  79:          this.BoundaryType = boundaryType;
  80:          if (args.Method.ContainsGenericParameters)
  81:          {
  82:              this.MethodParameters = args.Method.GetGenericArguments().Select(t => t.Name).ToList();
  83:          }
  84:          this.MethodParametersExist = args.Method.ContainsGenericParameters;
  85:          this.ReturnValue = args.ReturnValue;
  86:   
  87:          if (this.BoundaryType == AspectBoundaryType.OnException)
  88:          {
  89:              if (args.Exception != null)
  90:              {
  91:                  this.Exception = args.Exception;
  92:              }
  93:          }
  94:   
  95:          return this;
  96:      }
  97:   
  98:      /// <summary>
  99:      /// Returns a <see cref="System.String" /> that represents this instance.
 100:      /// </summary>
 101:      /// <returns>
 102:      /// A <see cref="System.String" /> that represents this instance.
 103:      /// </returns>
 104:      public override string ToString()
 105:      {
 106:          StringBuilder sb = new StringBuilder();
 107:   
 108:          if (MethodDeclaringTypeName != null)
 109:          {
 110:              sb.Append(string.Format("{0}.{1}", this.MethodDeclaringTypeName, this.MethodName));
 111:          }
 112:   
 113:          sb.Append(string.Format(" | {0}", this.BoundaryType));
 114:   
 115:          if (ReturnValue != null)
 116:          {
 117:              sb.Append(string.Format(" | Returns = {0}", this.ReturnValue));
 118:          }
 119:   
 120:          if ((this.Stopwatch != null) && (this.dateEnd != null))
 121:          {
 122:              sb.Append(string.Format(" | {0} ms", this.Stopwatch.ElapsedMilliseconds));
 123:          }
 124:   
 125:          if (this.dateEnd != null)
 126:          {
 127:              sb.Append(string.Format(" | {0}", this.dateStart.ToCustomDateTimeDetailed(this.dateEnd)));
 128:          }
 129:   
 130:          if (this.MethodParametersExist)
 131:          {
 132:              sb.Append(string.Format(" | <{0}>", this.MethodParameters.ToDelimString(",")));
 133:          }
 134:   
 135:          return sb.ToString();
 136:      }
 137:   
 138:      #endregion
 139:  }

If you haven’t extended NLog or your favorite flavor of logger – this is a pretty nice pattern on which to build. 

On top of the usual Log.Info(), Log.Warn(), Log.Error(), etc – added the ability Log.Profile() and simply pass in the object above.  Note – for NLog to be able to log the values – we pass them in through the GlobalDiagnosticsContext.Set() method.  See the NLog.config file below to see the other side of this communication.

 

   1:  [Serializable]
   2:  public class Log : ILog
   3:  {
   4:      #region | Properties |
   5:   
   6:      public Logger Logger { get; set; }
   7:   
   8:      #endregion
   9:   
  10:      #region | Constructors |
  11:   
  12:      /// <summary>
  13:      /// Initializes a new instance of the <see cref="Log"/> class.
  14:      /// </summary>
  15:      public Log()
  16:      {
  17:          //----------------------------------------------------------------------
  18:          // Initialize
  19:          //----------------------------------------------------------------------
  20:          this.Logger = LogManager.GetLogger("Logging");
  21:   
  22:          //----------------------------------------------------------------------
  23:          // Clear the additional logging info
  24:          //----------------------------------------------------------------------
  25:          GlobalDiagnosticsContext.Clear();
  26:      }
  27:   
  28:      public Log(System.Web.HttpContext context) : this()
  29:      {
  30:          string ip = GetIPAddress(context);
  31:          GlobalDiagnosticsContext.Set("LocationIp", ip);
  32:      }
  33:   
  34:      #endregion
  35:   
  36:      #region | Public Methods |
  37:   
  38:      /// <summary>
  39:      /// Logs the Profile properties
  40:      /// </summary>
  41:      /// <param name="profile">The profile.</param>
  42:      public void Profile(Profiler profile)
  43:      {
  44:          //----------------------------------------------------------------------
  45:          // Set the logging info for profile
  46:          //----------------------------------------------------------------------
  47:          this.Logger = LogManager.GetLogger(profile.MethodName);
  48:          GlobalDiagnosticsContext.Set("DateStart", profile.dateStart.ToDateTimeHighPrecision());
  49:          GlobalDiagnosticsContext.Set("DateEnd", profile.dateEnd.ToDateTimeHighPrecision());
  50:          GlobalDiagnosticsContext.Set("ExecutionTime", profile.EllapsedTime.ToString(CultureInfo.InvariantCulture));
  51:          GlobalDiagnosticsContext.Set("BoundaryType", profile.BoundaryType.ToString());
  52:          GlobalDiagnosticsContext.Set("SourceParent", profile.MethodDeclaringTypeName);
  53:          GlobalDiagnosticsContext.Set("Source", profile.MethodName);
  54:          GlobalDiagnosticsContext.Set("SourceParams", profile.MethodParameters.ToDelimString(","));
  55:          GlobalDiagnosticsContext.Set("SourceReturn", (profile.ReturnValue == null ? string.Empty : profile.ReturnValue.ToString()));
  56:          GlobalDiagnosticsContext.Set("ExceptionMessage", (profile.Exception == null ? string.Empty : profile.Exception.MessageFull()));
  57:          GlobalDiagnosticsContext.Set("ExceptionType", (profile.Exception == null ? string.Empty : profile.Exception.GetType().ToString()));
  58:          GlobalDiagnosticsContext.Set("StackTrace", (profile.Exception == null ? string.Empty : profile.Exception.StackTrace));
  59:          GlobalDiagnosticsContext.Set("Location", profile.Location.Name);
  60:          GlobalDiagnosticsContext.Set("LocationIp", profile.Location.Ip);
  61:          GlobalDiagnosticsContext.Set("LocationUser", profile.Location.User);
  62:          GlobalDiagnosticsContext.Set("Application", profile.Application.Name);
  63:          GlobalDiagnosticsContext.Set("ApplicationVersion", profile.Application.Version);
  64:   
  65:          //----------------------------------------------------------------------
  66:          // Write message to debug console
  67:          //----------------------------------------------------------------------
  68:          Debug.WriteLine(profile.ToString());
  69:   
  70:          //----------------------------------------------------------------------
  71:          // Log as different log levels based on boundary type
  72:          //----------------------------------------------------------------------
  73:          switch (profile.BoundaryType)
  74:          {
  75:              case AspectBoundaryType.OnEntry:
  76:              case AspectBoundaryType.OnSuccess:
  77:                  this.Logger.Trace(profile.ToString());
  78:                  break;
  79:   
  80:              case AspectBoundaryType.OnExit:
  81:                  this.Logger.Info(profile.ToString());
  82:                  break;
  83:   
  84:              case AspectBoundaryType.OnException:
  85:                  this.Logger.Error(profile.ToString(), profile.Exception);
  86:                  break;
  87:          }
  88:      }
  89:   
  90:      /// <summary>
  91:      /// Logs the Trace message
  92:      /// </summary>
  93:      /// <param name="message">The message.</param>
  94:      public void Trace(string message)
  95:      {
  96:          Initialize();
  97:   
  98:  #if DEBUG
  99:          Debug.WriteLine(message);
 100:  #endif
 101:          this.Logger.Trace(message);
 102:      }
 103:   
 104:      /// <summary>
 105:      /// Logs the Info message
 106:      /// </summary>
 107:      /// <param name="message">The message.</param>
 108:      public void Info(string message)
 109:      {
 110:          Initialize();
 111:   
 112:  #if DEBUG
 113:          Debug.WriteLine(message);
 114:  #endif
 115:          this.Logger.Info(message);
 116:      }
 117:   
 118:      /// <summary>
 119:      /// Logs the Warning message
 120:      /// </summary>
 121:      /// <param name="message">The message.</param>
 122:      public void Warn(string message)
 123:      {
 124:          Initialize();
 125:   
 126:  #if DEBUG
 127:          Debug.WriteLine(message);
 128:  #endif
 129:          this.Logger.Warn(message);
 130:      }
 131:   
 132:      /// <summary>
 133:      /// Logs the Error message
 134:      /// </summary>
 135:      /// <param name="message">The message.</param>
 136:      public void Error(string message)
 137:      {
 138:          Initialize();
 139:   
 140:  #if DEBUG
 141:          Debug.WriteLine(message);
 142:  #endif
 143:          this.Logger.Error(message);
 144:      }
 145:   
 146:      /// <summary>
 147:      /// Logs the Error message
 148:      /// </summary>
 149:      /// <param name="message">The message.</param>
 150:      /// <param name="exception">The exception.</param>
 151:      public void Error(string message, Exception exception)
 152:      {
 153:          Initialize();
 154:   
 155:          SetExceptionProperties(exception);
 156:   
 157:  #if DEBUG
 158:          Debug.WriteLine(message);
 159:  #endif
 160:          this.Logger.ErrorException(message, exception);
 161:      }
 162:   
 163:      public void Error(Exception exception)
 164:      {
 165:          Initialize();
 166:   
 167:          SetExceptionProperties(exception);
 168:   
 169:  #if DEBUG
 170:          Debug.WriteLine(exception.MessageFull());
 171:  #endif
 172:          this.Logger.ErrorException(exception.MessageFull(), exception);
 173:      }
 174:   
 175:      #endregion
 176:   
 177:      #region | Private Methods |
 178:   
 179:      /// <summary>
 180:      /// Initialization for logging methods
 181:      /// </summary>
 182:      private static void Initialize()
 183:      {
 184:          //----------------------------------------------------------------------
 185:          // Get the method and class
 186:          //----------------------------------------------------------------------
 187:          string methodName = GetInfo.CurrentMethod.Name(3);
 188:          string className = GetInfo.CurrentClass.Name(3);
 189:          GlobalDiagnosticsContext.Set("SourceParent", className);
 190:          GlobalDiagnosticsContext.Set("Source", methodName);
 191:   
 192:          //----------------------------------------------------------------------
 193:          // Get the calling assembly properties, need to set the level to 5 to get the correct assembly
 194:          //----------------------------------------------------------------------
 195:          AssemblyInfoCalling assembly = new AssemblyInfoCalling(5);
 196:          GlobalDiagnosticsContext.Set("Application", assembly.Title);
 197:          GlobalDiagnosticsContext.Set("ApplicationVersion", assembly.VersionFull);
 198:          GlobalDiagnosticsContext.Set("Location", assembly.Location);
 199:      }
 200:   
 201:      private static void SetExceptionProperties(Exception exception)
 202:      {
 203:          GlobalDiagnosticsContext.Set("ExceptionMessage", (exception == null ? string.Empty : exception.MessageFull()));
 204:          GlobalDiagnosticsContext.Set("StackTrace", (exception == null ? string.Empty : exception.StackTrace));
 205:          GlobalDiagnosticsContext.Set("ExceptionType", (exception == null ? string.Empty : exception.GetType().ToString()));
 206:      }
 207:   
 208:      //TODO: Validate that this works for non-local testing
 209:      protected string GetIPAddress(System.Web.HttpContext context)
 210:      {
 211:          string ipAddress = context.Request.ServerVariables["HTTP_X_FORWARDED_FOR"];
 212:   
 213:          if (!string.IsNullOrEmpty(ipAddress))
 214:          {
 215:              string[] addresses = ipAddress.Split(',');
 216:              if (addresses.Length != 0)
 217:              {
 218:                  return addresses[0];
 219:              }
 220:          }
 221:   
 222:          return context.Request.ServerVariables["REMOTE_ADDR"];
 223:      }
 224:   
 225:      #endregion
 226:  }

So NLog is obviously very powerful right out of the gate – allowing us to write to a database, file, webservice, email, etc – and allows us to tell it to do so asynchronously with just a setting.  So, while I’m in favor of using the best tool for the job – often I write my own – but in this case once you figure out some of the nuances of passing in your own values, there is little to no reason to not use NLog.  I scoured the internet for best configuration ideas of NLog.config files – and this is the culmination of what I’ve learned so far.  Use it and make it even better, then send me the updates. 🙂  Note – obviously, change the connection string to your database.

 

   1:  <?xml version="1.0" encoding="utf-8" ?>
   2:  <nlog autoReload="true" 
   3:        throwExceptions="true" 
   4:        internalLogLevel="Info"
   5:        internalLogToConsole="false"
   6:        internalLogFile="${basedir}/nlog.txt"
   7:        xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
   8:        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
   9:      
  10:    <!-- 
  11:    See http://nlog-project.org/wiki/Configuration_file 
  12:    for information on customizing logging rules and outputs.
  13:     -->
  14:   
  15:    <targets async="true">
  16:      <default-wrapper xsi:type="RetryingWrapper"/>
  17:      <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log" 
  18:              layout="${longdate} ${uppercase:${level}} ${message}" />
  19:      <target xsi:type="File" name="f2" fileName="c:/temp/logs/${shortdate}.log" 
  20:              layout="${longdate} ${uppercase:${level}} ${message}" />
  21:   
  22:      <target xsi:type="Database" name="databaseprofiler">
  23:   
  24:        <dbProvider>sqlserver</dbProvider>
  25:   
  26:        <!-- database connection parameters -->
  27:        <!-- alternatively you could provide a single 'connectionstring' parameter -->
  28:        <connectionString>Data Source=localhost;Initial Catalog=WebProfiler;Integrated Security=SSPI</connectionString>
  29:   
  30:        <commandText>
  31:          INSERT INTO [WebProfiler].[dbo].[LogProfiler]
  32:          ([LogLevel]
  33:          ,[DateStart]
  34:          ,[DateEnd]
  35:          ,[ExecutionTime]
  36:          ,[BoundaryType]
  37:          ,[SourceParent]
  38:          ,[Source]
  39:          ,[SourceParams]
  40:          ,[SourceReturn]
  41:          ,[Message]
  42:          ,[ExceptionType]
  43:          ,[ExceptionMessage]
  44:          ,[StackTrace]
  45:          ,[UserName]
  46:          ,[WindowsIdenty]
  47:          ,[MachineName]
  48:          ,[Location]
  49:          ,[LocationIp]
  50:          ,[LocationUser]
  51:          ,[Application]
  52:          ,[ApplicationVersion])
  53:          VALUES
  54:          (@LogLevel
  55:          ,@DateStart
  56:          ,@DateEnd
  57:          ,@ExecutionTime
  58:          ,@BoundaryType
  59:          ,@SourceParent
  60:          ,@Source
  61:          ,@SourceParams
  62:          ,@SourceReturn
  63:          ,@Message
  64:          ,@ExceptionType
  65:          ,@ExceptionMessage
  66:          ,@StackTrace
  67:          ,@UserName
  68:          ,@WindowsIdenty
  69:          ,@MachineName
  70:          ,@Location
  71:          ,@LocationIp
  72:          ,@LocationUser
  73:          ,@Application
  74:          ,@ApplicationVersion)
  75:        </commandText>
  76:   
  77:        <parameter name="@LogLevel" layout="${level}" />
  78:        <parameter name="@DateStart" layout="${gdc:DateStart}" />
  79:        <parameter name="@DateEnd" layout="${gdc:DateEnd}" />
  80:        <parameter name="@ExecutionTime" layout="${gdc:ExecutionTime}" />
  81:        <parameter name="@BoundaryType" layout="${gdc:BoundaryType}" />
  82:        <parameter name="@SourceParent" layout="${gdc:SourceParent}" />
  83:        <parameter name="@Source" layout="${gdc:Source}" />
  84:        <parameter name="@SourceParams" layout="${gdc:SourceParams}" />
  85:        <parameter name="@SourceReturn" layout="${gdc:SourceReturn}" />
  86:        <parameter name="@Message" layout="${message}" />
  87:        <parameter name="@ExceptionType" layout="${gdc:ExceptionType}" />
  88:        <parameter name="@ExceptionMessage" layout="${gdc:ExceptionMessage}" />
  89:        <parameter name="@StackTrace" layout="${gdc:StackTrace}" />
  90:        <parameter name="@UserName" layout="${environment:variable=UserName}" />
  91:        <parameter name="@WindowsIdenty" layout="${windows-identity}" />
  92:        <parameter name="@MachineName" layout="${machinename}" />
  93:        <parameter name="@Location" layout="${gdc:Location}" />
  94:        <parameter name="@LocationIp" layout="${gdc:LocationIp}" />
  95:        <parameter name="@LocationUser" layout="${gdc:LocationUser}" />
  96:        <parameter name="@Application" layout="${gdc:Application}" />
  97:        <parameter name="@ApplicationVersion" layout="${gdc:ApplicationVersion}" />
  98:        
  99:      </target>
 100:          
 101:    </targets>
 102:    <rules>
 103:      <!--<logger name="*" minlevel="Trace" writeTo="f" />-->
 104:      <!--<logger name="*" minlevel="Trace" writeTo="f2" />-->
 105:   
 106:      <logger name="*" minlevel="Trace" writeTo="databaseprofiler" />
 107:    </rules>
 108:  </nlog>

Here is the SQL side….

image

   1:  CREATE TABLE [dbo].[LogProfiler](
   2:      [Id] [bigint] IDENTITY(1,1) NOT NULL,
   3:      [LogLevel] [varchar](50) NOT NULL,
   4:      [DateCreated] [datetime] NOT NULL,
   5:      [DateStart] [datetime] NULL,
   6:      [DateEnd] [datetime] NULL,
   7:      [ExecutionTime] [int] NULL,
   8:      [BoundaryType] [varchar](50) NULL,
   9:      [SourceParent] [varchar](200) NULL,
  10:      [Source] [varchar](200) NULL,
  11:      [SourceParams] [varchar](max) NULL,
  12:      [SourceReturn] [varchar](max) NULL,
  13:      [Message] [varchar](max) NULL,
  14:      [ExceptionType] [varchar](200) NULL,
  15:      [ExceptionMessage] [varchar](max) NULL,
  16:      [StackTrace] [varchar](max) NULL,
  17:      [UserName] [varchar](100) NULL,
  18:      [WindowsIdenty] [varchar](100) NULL,
  19:      [MachineName] [varchar](100) NULL,
  20:      [Location] [varchar](200) NULL,
  21:      [LocationIp] [varchar](100) NULL,
  22:      [LocationUser] [varchar](200) NULL,
  23:      [Application] [varchar](200) NULL,
  24:      [ApplicationVersion] [varchar](50) NULL,
  25:   CONSTRAINT [PK_LogProfiler] PRIMARY KEY CLUSTERED 
  26:  (
  27:      [Id] ASC
  28:  )WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
  29:  ) ON [PRIMARY]
  30:   
  31:  GO
  32:   
  33:  ALTER TABLE [dbo].[LogProfiler] ADD  CONSTRAINT [DF_LogProfiler_DateCreated]  DEFAULT (getdate()) FOR [DateCreated]
  34:  GO

And here is the simple SQL query to get the data that we saw at the very beginning of this article!

 

   1:  SELECT SourceParent, Source, SUM(ExecutionTime) AS Total, 
   2:  MAX(ExecutionTime) AS MaxTime,
   3:  MIN(ExecutionTime) AS MinTime,
   4:  AVG(ExecutionTime) AS AvgTime,
   5:  Count(*) As Count FROM dbo.LogProfiler WHERE BoundaryType = 'OnExit' 
   6:  AND Application = 'ProfileWeb'
   7:  GROUP BY SourceParent, Source 
   8:  ORDER BY SourceParent, Source

Last thing in this EPIC blog posting ( what do you expect to be able to create the “Holy Grail”? ) is timing / testing to quantify the impact on code to get profiling information.

In the “ProfileConsole” project – we have a simple loop calling and timing a method in which we specify a specific Sleep() time.

 

   1:  class Program
   2:  {
   3:      static void Main(string[] args)
   4:      {
   5:          const int runTimes = 100;
   6:   
   7:          Log log = new Log();
   8:          log.Info("start");
   9:   
  10:          Stopwatch sw = new Stopwatch();
  11:          sw.Start();
  12:          for (int i = 0; i < runTimes; i++)
  13:          {
  14:              TestMethod1();
  15:              Console.WriteLine("Run Times: {0}", i);
  16:              //log.Trace(string.Format("Run Times: {0}", i));
  17:          }
  18:          sw.Stop();
  19:   
  20:          log.Info("end");
  21:   
  22:          var ms = sw.ElapsedMilliseconds;
  23:          Console.WriteLine("Run Times: {0}, Total Time: {1}, Avg Time: {2}", runTimes, ms, ms / runTimes);
  24:          Console.ReadLine();
  25:      }
  26:   
  27:      private static void TestMethod1()
  28:      {
  29:          Thread.Sleep(100);
  30:      }
  31:  }

Running this, here is the data I collected… The results show a very manageable impact of just 10 ms when running the Aspect and writing to the Database – but NOT writing to a file.  Writing to the file kicked it up to 28 ms – generally unnecessary cost there.

image

 

imageNotes – for my Visual Studio projects I use NuGet extensively – if you haven’t used it -do so-, it allows for libraries, code, etc to be easily added to Visual Studio projects. 

I found that adding the PostSharp reference through NuGet to be the most reliable and maintainable way to keep a consistent version of PostSharp across projects. 

Just right click on your project –> Click on “Manage NuGet Packages…” –> Select “Online” –> type “PostSharp” in text box in upper right and “Install”

 

 

 

So let’s see how we stacked up against our “Holy Grail” criteria…

  • Rich DataDONE! Gave us detailed logging, recording
    which method is being called, where it’s being called from, when it starts, when
    it stops, overall execution time –and- if any exceptions are thrown!
  • Low ImpactDONE! Our timing data shows that we are just adding ~10ms overhead, most excellent considering the Rich Data we’re getting!
  • Minimal CodeDONE! It’s D.R.Y. ( Don’t Repeat
    Yourself), no code has been harmed in the making of these classes. :p  Don’t have the same code repeated over and over and over – very maintainable.
  • Loosely CoupledDONE! I’d call one line in the AssemblyInfo.cs and a couple references pretty Loosely Coupled. 🙂

Very nice – Indiana Jones eat your heart out…

As always, love to get feedback and suggestions on how to make this even better… Have work to do, adding unit tests, etc.  But what a great start!

…Lance

Download the Profiler Code (44 MB)

0 thoughts on “Holy Grail of Application Profiling with AOP”

    1. Awesome – would love to hear that it works for your projects, do get back to me on that. As to NuGet — that’s a great idea – haven’t done so before, will add to my ToDo list to investigate. 🙂 Thanks.

Leave a Reply