MethodTimer Fody - Benchmarks

Updated 28/01/2025

“Use Case: Simplest way to measure how long a method on your code takes to execute, this is helpful for logging, profiling and general performance measurement. Often there is degradation over time and its useful to compare how long execution takes.”

The code used in this post can be found at https://github.com/carlpaton/BenchmarkDemo

Stopwatch (classic timer way)

This was how I learnt how to measure things using a Stopwatch

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public async Task MyMethod() 
{
    var sw = Stopwatch.StartNew();
    try
    {
        await UnitOfWorkAsync();
    }
    finally
    {
        sw.Stop();
        Console.WriteLine($"MyMethod took {sw.ElapsedMilliseconds}ms ({sw.Elapsed})ts");
        // Elapsed is a timespace, that would be more accurate
    }
}

As an example this could show MyMethod took 91ms (00:00:00.0916101)ts which is useful but the code now has noise. It really needs to just UnitOfWorkAsync, there are ways to make this smarter with wrappers (see dapper wrapper example) or MediatR but MethodTimer.Fody is a simpler implementation.

MethodTimer.Fody

These examples are based on Nick Chapsas’s video The Easiest Way to Measure Your Method’s Performance in C# and the Fody MethodTimer docs.

The library MethodTimer.Fody does some assembly weaving magic, this just takes the compiled code and injects some new behavior, like the stopwatch timer above.

  1. Install Fody and MethodTimer.Fody
  2. My debug did not immediately start working, I replaced the content of FodyWeavers.xml per the docs with the default, rebuilt and then it worked.
1
2
3
<Weavers>
  <MethodTimer/>
</Weavers>
  1. Add the attribute [Time] to the top of the method, this is just a marker that the weaving magic will look for and change the code
1
2
3
4
5
6
7
using MethodTimer;

[Time]
public async Task MyMethod() 
{
    await UnitOfWorkAsync();
}

If you look at the IL (intermediate language) it should have simliar code to the stop watch code above, I couldnt get this to work when trying in VS 2022.

  1. This will write to the trace logger, so you can view the logs in debug, this is useful if you just want to eyeball some performance times.
1
FodyExample.MyMethod 96ms

Interceptor MethodTimeLogger

You can hook into Fody by writing some extensions that the weaver will look for and use when logging

  1. Define the method
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
public static class MethodTimeLogger
{
    public static void Log(MethodBase baseMethod, TimeSpan ts, string message)
    {
        try
        {
            Trace.WriteLine($"ZZZZ MethodTimeLogger");
            Trace.WriteLine($"ZZZZ {baseMethod.DeclaringType!.Name}.{baseMethod.Name} {ts}");
            Trace.WriteLine($"ZZZZ message={message}");
        }
        catch (Exception e)
        {
            Trace.WriteLine($"e={e.Message}");
        }
    }
}
  1. Call as normal but pass the message param
1
2
3
4
5
6
[Time("this is the message with value {message}")]
public async Task MyMethod(int message)
{
    Trace.WriteLine($"ZZZZ START {message}");
    await UnitOfWorkAsync();
}
  1. This now logs the same as before but then you have access to the logging details which you can use with what ever metrics persistance your code base uses
1
2
3
ZZZZ MethodTimeLogger
ZZZZ FodyExample.MyMethod 00:00:00.0916101
ZZZZ message=this is the message with value 42

The message is useful as you can then have some context of the load, here 42 could be creater than 1 so you would take that into account with your metrics.

MethodTimer.Fody Example

I often struggle to understand the value of something if I have never needed it, although the below is a contrived example, selecting the correct data structure is something most developers will come across in their daily code.

  1. Consider these methods DemoUseDict(..) and DemoUseLinq(), here I pass in the data structures I want to query as I dont want to measure the creation, only the access. I dont do anything else like console writeline as that takes time, I just want to access the data. The variable s will be immutable, so we know a new string is created everytime but that shouldnt affect the results too much.

Spoiler Alert: Front of class nerds will know using a hash like Dictionary will be Big O of 1 ie: O(1) which is constant time, see Big O Notation. Lets ignore that for a second and just test the code

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public void DemoUseDict(Dictionary<int, DemoClass> dict)
{
    var s = "";
    for (int i = 0; i < 5000; i++)
    {
        s = dict[i].Name;
    }
}

public void DemoUseLinq(List<DemoClass> collection)
{
    var s = "";
    for (int i = 0; i < 5000; i++)
    {
        s = collection.FirstOrDefault(x => x.Id == i).Name;
    }
}
  1. Add the [Time] attribute as before
1
2
3
4
5
6
7
8
9
public void DemoUseDict(Dictionary<int, DemoClass> dict)
{
 ...
}

public void DemoUseLinq(List<DemoClass> collection)
{
 ...
}
  1. Create the data upfront, again we are interested in access speed not creation and call the methods
1
2
3
4
5
6
7
8
9
10
11
12
var dict = new Dictionary<int, DemoClass>();
var collection = new List<DemoClass>();

for (int i = 0; i < 5000; i++)
{
    dict.Add(i, new DemoClass() { Id = i, Name = $"Name{i}" });
    collection.Add(new DemoClass() { Id = i, Name = $"Name{i}" });
}

var eg = new FodyActualExample();
eg.DemoUseDict(dict);
eg.DemoUseLinq(collection);
  1. Running the results a few times and running them individually consistantly produces results as per the below, its clear the front of class kids were right about the hash but we now have some data to back it up.
1
2
3
4
5
6
7
8
FodyActualExample.DemoUseDict 0ms
FodyActualExample.DemoUseDict 0ms
FodyActualExample.DemoUseDict 0ms


FodyActualExample.DemoUseLinq 291ms
FodyActualExample.DemoUseLinq 227ms
FodyActualExample.DemoUseLinq 266ms

Obviously the results would change based on the machines power, usage at the time and this is not an accurate average - but its at least a data driven decision based on a small sample set.

BenchmarkDotNet

This alternate library is more advanced and shows cool outputs as shown below but the setup is harder and I have not seen a real use case.

1
2
3
|   Method |    Mean |   Error |
|----------|--------:|--------:|
| MyMethod | 0.36 ns | 0.00 ns |