What happens if your client complains that your application is running very slow!!! or in your load/stress testing, you found that some functionalities are very slow in executing than expected. This is the time where you go for profiling the execution, to analyse the root cause of these issues.
So how we could develop a profiler, where we don’t have to wrap our normal code in a profiling code.
Before going to create the profiler, we have to decide where to put the profiled information. In this tutorial, I am making use of Log4Net as underlying layer to store this information. If you have not used Log4Net before, I suggest you read this post as a starting point.
With the help of AOP (Aspect-Oriented Programming), we could do the profiling task without interrupting the actual code.
AOP is a programming paradigm in which secondary or supporting functions are isolated from the main program’s business logic
Source: Wikipedia
So in order to bring the AOP functionality into this application, I am going to use a third party library PostSharp which I believe is one of the best that is available in the market. Please download it from here.
So, now we have got the basic things to start with and now let’s start coding….
Start a new solution in Visual Studio and add a new console application project to it. Then, add the below references to the newly created project:
- Add reference to the Log4Net.dll
- Add reference to PostSharp.Laos.dll and PostSharp.Public.dll (Please read this article to get the basic installation procedure)
Next, create a new attribute class called “ProfileMethodAttribute
” – this class is responsible for doing the profiling work. Make sure that you have decorated this class with “Serializable
” attribute.
[Serializable]
public class ProfileMethodAttribute : OnMethodBoundaryAspect
{
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
........
}
public override void OnExit(MethodExecutionEventArgs eventArgs)
{
......
}
}
This class actually derives from “OnMethodBoundaryAspect
”, it has got two methods “OnEntry
” and “OnExit
” which we needed. These methods will be called before the start of a method execution and at the end of method execution respectively, when this attribute is decorated against a method.
When a call comes to “OnEntry
” method, we will first log the execution call using the LoggerHelper
, then start a clock using another helper class “Profiler
”.
public class LoggerHelper
{
private static ILog logger;
static LoggerHelper()
{
log4net.Config.XmlConfigurator.Configure();
logger = LogManager.GetLogger(typeof(Program));
}
public static void Log(string message)
{
string enableProfiling = ConfigurationManager.AppSettings["EnableProfiling"];
if (string.IsNullOrEmpty(enableProfiling) ||
enableProfiling.ToLowerInvariant() == "true")
{
logger.Debug(message);
}
}
public static void Log(string methodName, string url,
string executionFlowMessage, string actualMessage)
{
Log(ConstructLog(methodName, url, executionFlowMessage, actualMessage));
}
public static void Log(string methodName, string url,
string executionFlowMessage, string actualMessage, int executionTime)
{
Log(ConstructLog(methodName, url, executionFlowMessage, actualMessage, executionTime));
}
private static string ConstructLog(string methodName, string url,
string executionFlowMessage, string actualMessage)
{
var sb = new StringBuilder();
if (!string.IsNullOrEmpty(methodName))
{
sb.AppendFormat("MethodName : {0}, ", methodName);
}
if (!string.IsNullOrEmpty(url))
{
sb.AppendFormat("Url : {0}, ", url);
}
if (!string.IsNullOrEmpty(executionFlowMessage))
{
sb.AppendFormat("ExecutionFlowMessage : {0}, ", executionFlowMessage);
}
if (!string.IsNullOrEmpty(actualMessage))
{
sb.AppendFormat("ActualMessage : {0}, ", actualMessage);
}
string message = sb.ToString();
message = message.Remove(message.Length - 2);
return message;
}
private static string ConstructLog(string methodName, string url,
string executionFlowMessage, string actualMessage, int executionTime)
{
var sb = new StringBuilder();
sb.Append(ConstructLog(methodName, url, executionFlowMessage, actualMessage));
sb.AppendFormat(", ExecutionTime : {0}", executionTime);
return sb.ToString();
}
}
LoggerHelper
just uses the Log4Net objects to log the message to configured location.
The “Profiler
” class:
internal static class Profiler
{
private static readonly object SyncLock = new object();
private static readonly Dictionary<int, Stack<long>> ProfilePool;
static Profiler()
{
ProfilePool = new Dictionary<int, Stack<long>>();
}
public static void Start()
{
lock (SyncLock)
{
int currentThreadId = Thread.CurrentThread.ManagedThreadId;
if (ProfilePool.ContainsKey(currentThreadId))
{
ProfilePool[currentThreadId].Push(Environment.TickCount);
}
else
{
var timerStack = new Stack<long>();
timerStack.Push(DateTime.UtcNow.Ticks);
ProfilePool.Add(currentThreadId, timerStack);
}
}
}
public static int Stop()
{
lock (SyncLock)
{
long currentTicks = DateTime.UtcNow.Ticks;
int currentThreadId = Thread.CurrentThread.ManagedThreadId;
if (ProfilePool.ContainsKey(currentThreadId))
{
long ticks = ProfilePool[currentThreadId].Pop();
if (ProfilePool[currentThreadId].Count == 0)
{
ProfilePool.Remove(currentThreadId);
}
var timeSpan = new TimeSpan(currentTicks - ticks);
return (int)timeSpan.TotalMilliseconds;
}
}
return 0;
}
}
which stores the starting tick and calculates the time taken to execute when “Stop
” is called.
Below is a code snippet from “OnEntry
” method:
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
this._methodName = this.ExcludeMethodName ? string.Empty : eventArgs.Method.Name;
this._url = this.IncludeUrl ? string.Empty :
(HttpContext.Current == null) ? string.Empty : HttpContext.Current.Request.Url.ToString();
LoggerHelper.Log(this._methodName, this._url, this.EntryMessage, this.Message);
Profiler.Start();
}
And OnExist
is almost similar expect there we will stop the profile timer.
public override void OnExit(MethodExecutionEventArgs eventArgs)
{
int count = Profiler.Stop();
LoggerHelper.Log(this._methodName, this._url, this.EntryMessage, this.Message, count);
}
I haven’t explained each line of the code, so please find the attached sample the attached sample for all of these source codes.
The next step is to use this and see whether it is logged properly.
In order to enable profiling for a method, you just need to decorate it with the “ProfileMethod
” attribute. Like below:
[ProfileMethod()]
public void SimpleMethod()
{
Thread.Sleep(5000);
}
Then if you run the application and somebody calls this above method, a log entry will be created where you have configured.
The out of that log file will be something like below:
PROFILING 2010-02-26 00:19:59,838 [1] Log MethodName : SimpleMethod
PROFILING 2010-02-26 00:20:04,865 [1] Log MethodName : SimpleMethod, ExecutionTime : 5002
Download the source code for this tutorial from here.
Please let me know if this helped you.