Poor Man’s Profiler: An Approach to Profiling .NET Code with Code Block Execution Timing and Parameter Logging

Applies to: .NET Standard 2.2+

This article is based on my example class library project Poor Man's Profiler on GitHub. To see the internals of this class library, please grab it there.

Basic Profiling

At some point in time most of us have likely used one of the following methods for basic timing of code execution.

DateTime dt = DateTime.Now;
System.Threading.Thread.Sleep(2000);
TimeSpan ts = DateTime.Now - dt;
Debug.WriteLine("Execution took: " + ts.TotalMilliseconds + "ms");

or

Stopwatch sw = Stopwatch.StartNew();
System.Threading.Thread.Sleep(2000);
sw.Stop();
Debug.WriteLine("Execution took: " + sw.ElapsedMilliseconds + "ms");

This is some really basic code that works well if all you want to know is the execution time of a given block of code. However, if you want to log multiple code blocks (especially within a single method,) and/or you want to log values of various variables, your code can start to get messy quick as it becomes littered with DateTime/TimeSpan/Stopwatch declarations and calls to Debug.WriteLine(). Additionally, if you want to be able to easily toggle this profiling code on or off, so you don’t have to comment it out or remove it all together when you don’t want it to run (like when the application is in production,) you are going to have to write some additional boilerplate code to handle this.

More Advanced Profiling

There are several software vendors who provide some really powerful frameworks that can be utilized for profiling and logging code performance, with the most popular being PostSharp. Such products most certainly have their place among a developer’s arsenal. In no way do I think my project here even remotely compares to the offerings of such products, especially considering my solution here is the work of a few meager hours of brainstorming and development.

For the sake of this article, Let’s pretend that you have an idea of roughly where a problem might be, but don’t feel that it is necessary to purchase a license (of have the budget) for a product that isn’t going to be truly utilized.

Enter what I have dubbed as the Poor Man's Profiler (Poor Man, as in, there are no licensing costs in this open source solution, which lacks the rich features and high scalability of the big commercial products.) This is more or less a very simple idea I recently had, that sort of evolved and continues to evolve as I keep thinking of ways to enhance it.

An AOP (Aspect Oriented Programming) or IL Weaving approach would likely be a better overall approach when writing our own logger that would keep the consuming application more in line with the DRY Principal (i’ll explain this later.) In fact, AOP/ IL Weaving is exactly what the earlier mentioned PostSharp is known for having mastered. Of course this could be the direction we take in Poor Man’s Profiler, utilizing DispatchProxy, but for the sake of going through an evolutionary concept, I wanted the first version Poor Man’s Profiler to be fairly basic, so that we could see some pros and cons.

The End Goal

So what was my goal here? I wanted to be able to:

• Time the executions of entire methods, and/or parts of method’s internals.
• Have the ability to log parameter/variable values easily.
• Identify both code block call frequency, and more importantly, repetitive code executions, whereas sometimes a block of code in itself when called once, isn’t necessarily causing a noticeable bottleneck, but when called multiple times unnecessarily, a performance issue begins to rears its ugly head.
• Easily enable/disable this profiling with minimal effort, so that the profiling code could be left intact, but not executed or even in existence while running in a Release build.
• Do the aforementioned with minimal code (as much as possible,) so as to not muck up and bloat the readability and flow of things that I wanted to profile.
• Take a stab at writing some code a little out of the ordinary.

Some Points of Caution

The first generation of an idea is usually far from perfect, and the fist version of Poor Man’s Profiler is of no exception.

Before we go any further, I must state that if you choose to use Poor Man’s Profiler in an application, it is coded to be a debug only logging option to help a developer gain better insight into things while troubleshooting code in debug mode. There is of course overhead with the use of Poor Man’s Profiler since it obviously adds more to instantiate and process, and depending on how it’s used, utilizes some reflection and causes some boxing. Interestingly enough however, I have come across a few AOP Logger implementations online, that rely on reflection and boxing as well.

I found the performance hit to be surprisingly minor when not used excessively, in fact, relatively unnoticeable in most situations, even in more complex/lengthy logging situations. With that being said, lets discuss some of the cons of this approach.

Boxing

So What is this “Boxing” thing that I speak of? Boxing is a computationally expensive process of converting a value type to the type of object. You may have seen this done in code, or have done it yourself on many occasions and didn't even realize it was a potential issue. The following demonstrates boxing:

int i = 123;
object o = i;

Relying on boxing is a big no-no in applications that you expect to see operate with the best performance. Microsoft’s documentation describes the issue well: “Boxing is the process of converting a value type to the type object or to any interface type implemented by this value type. When the common language runtime (CLR) boxes a value type, it wraps the value inside a System.Object instance and stores it on the managed heap. Unboxing extracts the value type from the object.” If high-performance is one of the major goals of an application (which it should be,) you should limit code that converts to and from object as much as possible.

So while I am breaking my own advice here (that is, avoid boxing,) Poor Man’s Profiler provides a way around allowing such code to execute when in Release mode, which will be discussed later.

The DRY Principal

One of the concepts introduced in the 1999 work, “The Pragmatic Programmer” is the DRY (Don’t Repeat Yourself) Principal, which is pretty much self-explanatory. As far as programming goes, it is always best practice to write code in a way that you are not duplicating code. One good reason for this is that if you have a block of code duplicated all over the place, and then something needs to change in that block of code, you will have a lot of work on your hands making changes everywhere that code block is used.

As for Poor Man’s Profiler, you will find yourself duplicating some code wherever you want it to be used. This will consist of your declaration of the DebuggLogger class, and generally two simple method calls wherever you wish to Start and Stop a code profile. Though it may not be a huge deal if used conservatively, a very thorough use, i.e. if you have the StartDebug()/StopDebug() method calls plastered all over a large application, it could prove to cause a lot of potential future keyboard pounding refactoring, that is, if anything is changed in a future release concerning the way these core methods are called.

Getting Into the Code Behind Poor Man’s Profiler

One instance of DebugLogger class allows for the time monitoring and parameter logging of an unlimited number of code blocks, thus it is best to declare it at class level, where all methods in the class can use it.

The process of converting parameter values to a string

Unlimited parameter values can be logged. This first version supports primitive types and Lists of primitive types (with the addition of DateTime and Timespan) which tend to be the most common parameters I see in applications. The ParamValuesToString() method of the Logger base class, of course could easily be modified to support other types.

Dealing with Lists was a little uglier than I would have liked (see the the ParamValuesToString() method of the Logger base class,) and I have found no way to easily cast a boxed object representing a List<T> to an actual List<T> as the casting-to-type always needs to be known (i.e. “List<T> tl = (List<T>)object;” obviously won’t work, and “List tl = (List)object;” requires a type argument.) Our ultimate goal for logging is to extract the elements of a List<T> as strings, but because our object is a boxed representation a List of any possible type, there is no good way to cast the object to a List<string>, as this cannot be done with an explicit cast. One trick I have seen used to get around this is to serialize the object to JSON, then Parse the JSON and loop through the items as strings.

This will do the trick, but can be more difficult when working with Lists of more complex types. As far as performance goes, Initially I thought the performance of this approach was going to be horrendous, but with a quick test, I was surprised. The serialization process on a List of 7 integers for example, seems to be very comparable in speed, to a direct cast from object to List<int> then to List<string>, that is with the exception of the very first call to JsonConvert.SerializeObject() which lazy loads several dependencies, and takes more than 25x the amount of time it does with ensuing calls.

The following test, uses the Poor Man’s Profiler to compare these two ways to convert a List of int to a List of string.

private static DebugLogger dl = new DebugLogger();

private static void ListToStringListCompare()
{
    List<int> ints = new List<int> { 1, 2, 3, 4, 5, 6, 7 };

    // Box the ints object
    object obj = ints;

    List<string> stringList = new List<string>();

    logger.WriteMessage("Performing JSON Serialize/Parse to List<string>");
    logger.StartDebug("JSON Serialize");
    // using Newtonsoft.Json;
    // using Newtonsoft.Json.Linq;
    JObject j = JObject.Parse("{ items: " + JsonConvert.SerializeObject(obj) + "}");
    stringList = (j["items"]).Select(x => x.ToString()).ToList();
    logger.StopDebug("JSON Serialize");

    logger.WriteMessage("Performing Cast to List<int> -> List<string>");
    logger.StartDebug("Direct Test/Cast");
    Type type = obj.GetType();
    if (type == typeof(List<int>)) stringList = ((List<int>)obj).Select(x => x.ToString()).ToList();
    logger.StopDebug("Direct Test/Cast");
}

Executing this 3x, we can see that after the first execution, both methods perform the same.

******** Message  : Performing JSON Serialize/Parse to List<string>
******** Started  : Program -> JSON Serialize() ...
******** Completed: Program -> JSON Serialize() took [263ms] to execute.
******** Message  : Performing Direct Cast to List<int> -> List<string>
******** Started  : Program -> Direct Test/Cast() ...
******** Completed: Program -> Direct Test/Cast() took [5ms] to execute.

******** Message  : Performing JSON Serialize/Parse to List<string>
******** Started  : Program -> JSON Serialize() ...
******** Completed: Program -> JSON Serialize() took [2ms] to execute.
******** Message  : Performing Direct Cast to List<int> -> List<string>
******** Started  : Program -> Direct Test/Cast() ...
******** Completed: Program -> Direct Test/Cast() took [2ms] to execute.

******** Message  : Performing JSON Serialize/Parse to List<string>
******** Started  : Program -> JSON Serialize() ...
******** Completed: Program -> JSON Serialize() took [1ms] to execute.
******** Message  : Performing Direct Cast to List<int> -> List<string>
******** Started  : Program -> Direct Test/Cast() ...
******** Completed: Program -> Direct Test/Cast() took [1ms] to execute.

Using Poor Man’s Profiler in Your Application

In its most basic form, its use looks something like this:

private static DebugLogger logger = new DebugLogger { Prefix = "Program", MaxElementsIfNonNumericList = 5, MaxElementsIfNumericList = 25, MaxStringLength = 100 };

static void Main(string[] args)
{
  Test(123, new List<string> { "This", "Is", "A", "Test" }, new List<DateTime> { DateTime.Now, DateTime.Now.AddDays(5) }, new List<int> { 9, 8, 7, 6, 5, 4, 3, 2, 1 });
}  

private static void Test(int a, List<string> b, List<DateTime> c, List<int> d)
{
   // Start a stopwatch on the method
   logger.StartDebug("TestMethod");

   for (int x = 0; x < 10; x++)
   {
      // Start a stopwatch and log some values
      logger.StartDebug("loop" + x, x, a, b, c, d);

      // Some code here ...

      logger.StopDebug("loop" + x);
   }

   logger.StopDebug("TestMethod");
}

The Output window of the IDE will quickly display the following:

******** Started  : Program -> TestMethod() ...
******** Started  : Program -> loop0(0, 123, ["This", "Is", "A", "Test"], ["2/5/2020 8:08:13 PM", "2/10/2020 8:08:13 PM"], [9, 8, 7, 6, 5, 4, 3, 2, 1]) ...
******** Completed: Program -> loop0() took [1ms] to execute.
******** Started  : Program -> loop1(1, 123, ["This", "Is", "A", "Test"], ["2/5/2020 8:08:13 PM", "2/10/2020 8:08:13 PM"], [9, 8, 7, 6, 5, 4, 3, 2, 1]) ...
******** Completed: Program -> loop1() took [1ms] to execute.
******** Started  : Program -> loop2(2, 123, ["This", "Is", "A", "Test"], ["2/5/2020 8:08:13 PM", "2/10/2020 8:08:13 PM"], [9, 8, 7, 6, 5, 4, 3, 2, 1]) ...
******** Completed: Program -> loop2() took [1ms] to execute.
******** Started  : Program -> loop3(3, 123, ["This", "Is", "A", "Test"], ["2/5/2020 8:08:13 PM", "2/10/2020 8:08:13 PM"], [9, 8, 7, 6, 5, 4, 3, 2, 1]) ...
******** Completed: Program -> loop3() took [1ms] to execute.
******** Started  : Program -> loop4(4, 123, ["This", "Is", "A", "Test"], ["2/5/2020 8:08:13 PM", "2/10/2020 8:08:13 PM"], [9, 8, 7, 6, 5, 4, 3, 2, 1]) ...
******** Completed: Program -> loop4() took [1ms] to execute.
******** Completed: Program -> TestMethod() took [18ms] to execute.

Lets break this down a bit. Within the class level declaration of the DebugLogger object named “logger” we have some properties being set:

private static DebugLogger logger = new DebugLogger { Prefix = "Program", MaxElementsIfNonNumericList = 5, MaxElementsIfNumericList = 25, MaxStringLength = 100 };

Prefix: This is an optional string value that will precede the code block name with every log entry, this is helpful for helping to identify what class the profiler is currently logging from, if you so choose to use this.

MaxElementsIfNonNumericList: Since the contents of Lists of primitive types will be written to the log in a comma delimited fashion in between brackets, we want a way to restrict the number of elements to actually log, in the event the List contains a lot of elements. This property applies to primitive types that are non-numeric. This value will restrict the number of elements to be logged. Specify 0 if you want all elements listed.

MaxElementsIfNumericList: Works the same as the aforementioned property except it applies to Lists of primitive types that are numeric.

MaxStringLength: This determines at which length a string value in the log should be trimmed. This helps to avoid logging large strings that will then muddy up the logs. Specify 0 if strings should not be trimmed.

IndentNumber: Which isn't shown in the code example above. This is used to set the number of TABS you want to precede the code block name (and Prefix if one is set). This can be useful if you have the Profiler running in different layers of the application. An example would be any properly abstracted, where you might want to apply an IndentNumber on code blocks running in the Business Layer, to help display a sort of hierarchy in code execution.

Starting a Timer/StopWatch

In the above code example, you could see that a string value was passed in with the calls to StartDebug()/StopDebug(). Behind the scenes, Poor Man’s Profiler holds a collection of StopWatch items, and we must correlate which items to Stop from a Start based on a name.

logger.StartDebug("TestMethod");
...
logger.StopDebug("TestMethod");

Alternatively, an explicit name doesn't have to be passed in which essentially makes the code more generic, if null is passed as the first parameter, the name of the calling block will be the calling method name pulled from the Stack Trace (ahh reflection).

logger.StartDebug(null);

However, because the name isn't going to be known, you will need to grab the LastStartID so that it can later be used with a call to StopDebug().

private static void Test2()
{
    // Start a stopwatch on the method, let StartDebug get the name
    logger.StartDebug(null);

    // Since we didnt pass a name, lets get the ID so we can use it when stopping the stopwatch
    long p1 = logger.LastStartID;

    for (int x = 0; x < 10; x++)
    {
        // Some code here …                
    }

    logger.StopDebug(p1);
}

Your first observations of the code block above may be: “Why is he calling StartDebug() and then assigning a variable of type long with the value of LastStartID? Why not just return the ID with the StartDebug()?” The answer to that question is both simple, and somewhat frustrating (for a lack of better words.) This is because the StartDebug() method, along with other various methods are marked with the [Conditional(“Debug”)] attribute, which means that these methods as well as any code that calls them will be excluded when the code is compiled in Release mode. This is how we can guarantee that Poor Man’s Logger will not cause any performance degrading overhead when the application is run in production.

The frustrating aspect of this is that this attribute can only be applied to void return methods, which means there is a little more code that needs to be written. When you think about this limitation it makes sense, because one would not want code that is setting a value to a variable to suddenly disappear in production code, as this no doubt would lead to all sorts of problems.

My workaround here was to have a property in the DebugLogging class that will simply default to 0 if not assigned to. When code is compiled in Release mode, and all the Poor Man’s Profiler code vanishes, at worse there will be various long typed variables defined that will all simply be set to 0 and never actually used.

Logging Parameters

The StartDebug() method can also be called with an unlimited number of parameters values which will in turn be logged.

logger.StartDebug("CodeBlock1", a, b, c, d, e, f, g); 

This of course is where most additional overhead comes into play, as the parameters passed in are all boxed into type object, so that any type of object can be passed in. Additionally reflection is used to obtain the actual type of the object parameters to best determine how to render their values in the logs. To top it off, a lot of string concatenation is also used here, which is another process that isn't known for high performance, and another thing to avoid when your end goal is high-performance code. The more parameter values you add, the more overhead you add, thus, add parameters sparingly.

Despite the use of performance killer code (where Microsoft’s Ben Watson would likely shake his head in disapproval) interestingly enough, in my tests, the performance reduction due to boxing, reflection, and string concatenation is rather insignificant for debugging purposes. However caution should be taken regardless, and since every application should strive to gain every fraction of a millisecond of speed that it can gain, we only allow this to be run in debug, which is why the StartDebug()/StartDebug() methods are given the aforementioned conditional attribute. They run when in debug mode, and disappear when in release mode.

With the first release of this library, using the logger to log parameter values is most useful if the parameters are:

• Any object with a primitive type (with the addition of DateTime and Timespan)
• An implementation of IList of any primitive type (with the addition of DateTime, Timespan).
• Any object of a non-primitive type or IList of a non-primitive type which overrides the base.ToString() method (which provides useful info about the object).
• Any object that does not meet the criteria above will simply be logged by its type name, or essentially the return of base.ToString().

Additional Methods

To stay on the safe side, I strongly suggest always using StartDebug() and StopDebug(), however I have exposed two alternative methods called Start() and Stop() that can be used with a little less code, however come with the caveat of not being able to be automatically removed when compiling in Release mode. The major downfall here is that if you use Start() and pass in parameter values, you will be triggering boxing, despite the fact that when in non-debug mode, the method calls will not actually be doing anything with these boxed objects, since the internals of these methods are marked with the precompiler directives to exclude code when not in debug mode. The benefit of using Start() is that you can get the ID for which to be used with Stop() from the call itself:

long p1 = logger.Start();

The benefit of using Stop() is that a double is returned representing total milliseconds in the event that you want to do something with this value besides the logging that is already happening internally.

double x = logger.Stop(p1);

I want to reiterate though, that these method calls will remain in Release code, so unless you don’t really care (i.e top performance isn't necessary) or you have a plan to remove them manually, just stick with StartDebug()/StopDebug().

There are a couple of other useful methods that are marked with the debug conditional, thus are safe to leave in code:

WriteParamValuesToString() which takes an unlimited list of parameter values to be logged which may be useful if you want to periodically log various variable values in strategic areas of code.

WriteMessage() which takes a string to be logged.

Making Sense of the Logs

Since the current working implementation of Poor Man’s Profiler writes to the Output window of the IDE, its likely going to be difficult to make whole lot of sense of things, especially since other events and messages are going to be logged in the same location.

It isn’t exactly pretty, but there is a way to use this log dump, and turn it into something of more use.

If there is interest in this, I could always write a log parser/aggregation application in Angular and/or Blazor as the topic of an upcoming article.

Summary

This article was meant to discuss a simple approach to .NET code profiling that can be used to time code block executions as well as log parameter/variable values. As noted, there are vendors who have created far more powerful frameworks for this need, as well as there are other ways to go about accomplishing this goal through AOP/IL Weaving to help reduce code redundancy.

Once again, this article is based on my example class library project that can be found on GitHub -> Poor Man's Profiler