Geeks With Blogs
Amit's Blog Sharing Thoughts and Learning

Instrumentation and Logging is an essential part of Software Development. Generally, most of the developer thinks instrumentation and logging is all about exception logging in a text file, which is not correct at all. Certainly, exception takes a major part in the instrumentation and logging. However, how many of us really bother the way the log data is written, do we really bother to import this data in a software to further analysis? In the following, I will present a handy class, which will automatically benchmark the instrumented method, so that we can do further analysis on the overall performance of our application.

PerformanceLog.cs:

   1:  using System;
   2:  using System.IO;
   3:  using System.Text;
   4:  using System.Reflection;
   5:  using System.Diagnostics;
   6:  using System.Globalization;
   7:  using System.Configuration;
   8:   
   9:   
  10:  public sealed class PerformanceLog : IDisposable
  11:  {
  12:      private static readonly bool _isPerformancelogEnabled = Convert.ToBoolean(ConfigurationManager.AppSettings["performanceLogEnabled"]);
  13:      private static readonly string _logFile = AppDomain.CurrentDomain.BaseDirectory + ConfigurationManager.AppSettings["performanceLogFile"];
  14:      private static readonly bool _includeParameters = Convert.ToBoolean(ConfigurationManager.AppSettings["performanceLogIncludeParameters"]);
  15:   
  16:      private Stopwatch _watch;
  17:   
  18:      public PerformanceLog()
  19:      {
  20:          if (_isPerformancelogEnabled)
  21:          {
  22:              _watch = new Stopwatch();
  23:              _watch.Start();
  24:          }
  25:      }
  26:   
  27:      public void Dispose()
  28:      {
  29:          if (_isPerformancelogEnabled)
  30:          {
  31:              _watch.Stop();
  32:   
  33:              DateTime end = DateTime.Now;
  34:              DateTime start = end.AddMilliseconds(-_watch.ElapsedMilliseconds);
  35:              string userName = System.Web.HttpContext.Current.User.Identity.Name;
  36:              string methodInfo = GetCallingMethodDetails(_includeParameters);
  37:   
  38:              using (FileStream fs = new FileStream(_logFile, FileMode.Append, FileAccess.Write, FileShare.None))
  39:              {
  40:                  using (StreamWriter sw = new StreamWriter(fs, Encoding.ASCII))
  41:                  {
  42:                      sw.Write(string.Format("\"{0}\",\"{1}\",\"{2}\",\"{3}\",\"{4}\"\n", userName, methodInfo, start, end, _watch.Elapsed));
  43:                  }
  44:              }
  45:          }
  46:      }
  47:   
  48:      private static string GetCallingMethodDetails(bool includeParameters)
  49:      {
  50:          StringBuilder output = new StringBuilder();
  51:          //Skipping two Frame, First one is the current method and second one is the dispose method.
  52:          StackTrace stackTrace = new StackTrace(2, false);
  53:   
  54:          StackFrame stackFrame = stackTrace.GetFrame(0);
  55:          MethodBase method = stackFrame.GetMethod();
  56:   
  57:          output.Append(method.Name);
  58:          output.Append("(");
  59:   
  60:          if (includeParameters)
  61:          {
  62:              ParameterInfo[] paramInfos = method.GetParameters();
  63:   
  64:              if ((paramInfos != null) && (paramInfos.Length > 0))
  65:              {
  66:                  output.Append(paramInfos[0].ParameterType.ToString());
  67:                  output.Append(" ");
  68:                  output.Append(paramInfos[0].Name);
  69:   
  70:                  if (paramInfos.Length > 1)
  71:                  {
  72:                      for (int j = 1; j < paramInfos.Length; j++)
  73:                      {
  74:                          output.AppendFormat(", {0} {1}", paramInfos[j].ParameterType.ToString(), paramInfos[j].Name);
  75:                      }
  76:                  }
  77:              }
  78:          }
  79:   
  80:          output.Append(")");
  81:   
  82:          return output.ToString();
  83:      }
  84:  }

Usage:

   1:      public List<Category> GetAllCategory()
   2:      {
   3:          using (PerformanceLog log = new PerformanceLog())
   4:          {
   5:              //Do your Processing over here
   6:          }
   7:      }

Web/App.config:

  <appSettings>
    <add key="performanceLogEnabled" value="true"/>
    <add key="performanceLogFile" value="PerformanceLog.csv"/>
    <add key="performanceLogIncludeParameters" value="false"/>
  </appSettings>

Logging Data:

"Amit-Dell\Kazi Manzur Rashid","GetAllCategory()","6/21/2007 11:26:06 PM","6/21/2007 11:26:08 PM","00:00:02.0282049"
"Amit-Dell\Kazi Manzur Rashid","GetProductList()","6/21/2007 11:26:08 PM","6/21/2007 11:26:09 PM","00:00:00.7225937"
"Amit-Dell\Kazi Manzur Rashid","GetProductList()","6/21/2007 11:26:12 PM","6/21/2007 11:26:12 PM","00:00:00.0400289"
"Amit-Dell\Kazi Manzur Rashid","GetProductList()","6/21/2007 11:26:43 PM","6/21/2007 11:26:43 PM","00:00:00.0012069"
"Amit-Dell\Kazi Manzur Rashid","GetProductList()","6/21/2007 11:26:43 PM","6/21/2007 11:26:44 PM","00:00:00.0463002"
"Amit-Dell\Kazi Manzur Rashid","GetCustomerList()","6/21/2007 11:26:49 PM","6/21/2007 11:26:49 PM","00:00:00.0952376"
"Amit-Dell\Kazi Manzur Rashid","GetAllSupplier()","6/21/2007 11:28:33 PM","6/21/2007 11:28:33 PM","00:00:00.0364298"

As you can see the class is simply dumping the User Name, The instrumented method(The Parameters info can be turned on from the web.config), start and end time of the method and the total elapsed time of the method in a csv format. The benefit of generating in csv format is we can easily import these data in Microsoft Excel to take full advantage of Excel such as finding the Longest and shortest call, Average call, Number of Average call of a User, Graph etc.

The simplicity of the class is, we do not have to do anything fancy except creating an instance of the class. The class is responsible to discover the method name and its parameter, start/end/elapsed time, user name etc.

In Pageflakes, we are doing the same but in a different twist, we are utilizing the Enterprise Library (logging and Instrumentation Block) to generate this. If you are interested to see how the EntLib can be used to do the above let me know.

Download: PerformanceLog.cs

kick it on DotNetKicks.com

Posted on Thursday, June 21, 2007 11:47 PM .NET , C# , Instrumentation/Logging , Tips/Tricks | Back to top


Comments on this post: Performance Benchmark with an Handy Class

# re: Performance Benchmark with an Handy Class
Requesting Gravatar...
Liked the idea!
Left by Mehfuz Hossain on Jun 23, 2007 12:06 PM

# re: Performance Benchmark with an Handy Class
Requesting Gravatar...
HI Amit,

Neat little code.....I'm tryring to grapple with an appropriate logging framework for my AJAX enabled site ...toying between EntLib and log4net.

I'll be doing a few round of testing with both f/w ...I'd to see the effects of EntLib via performance logging
Left by Augustine on Jul 18, 2007 1:28 AM

# re: Performance Benchmark with an Handy Class
Requesting Gravatar...
cool stuff looking forward to use this in my new project...
Left by y2kinfos on Mar 03, 2008 9:28 PM

Your comment:
 (will show your gravatar)
 


Copyright © Kazi Manzur Rashid | Powered by: GeeksWithBlogs.net | Join free