How to measure code performance in .NET?

Viewed 26279

I'm doing some real quick and dirty benchmarking on a single line of C# code using DateTime:

long lStart = DateTime.Now.Ticks;
// do something
long lFinish = DateTime.Now.Ticks;

The problem is in the results:

Start Time [633679466564559902]
Finish Time [633679466564559902]

Start Time [633679466564569917]
Finish Time [633679466564569917]

Start Time [633679466564579932]
Finish Time [633679466564579932]

...and so on.

Given that the start and finish times are identical, Ticks is obviously not granular enough.

So, how can I better measure performance?

18 Answers

The Stopwatch class, available since .NET 2.0, is the best way to go for this. It is a very high performance counter accurate to fractions of a millisecond. Take a look at the MSDN documentation, which is pretty clear.

EDIT: As previously suggested, it is also advisable to run your code a number of times in order to get a reasonable average time.

Execute your code repeatedly. The problem seems to be that your code executes a lot faster than the granularity of your measuring instrument. The simplest solution to this is to execute your code many, many times (thousands, maybe millions) and then calculate the average execution time.

Edit: Also, due to the nature of current optimizing compilers (and Virtual Machines such as the CLR and the JVM) it can be very misleading to measure the execution speed of single lines of code, since the measurement can influence the speed quite a lot. A much better approach would be to profile the entire system (or at least larger blocks) and check where the bottlenecks are.

I find these useful

http://accelero.codeplex.com/SourceControl/changeset/view/22633#290971 http://accelero.codeplex.com/SourceControl/changeset/view/22633#290973 http://accelero.codeplex.com/SourceControl/changeset/view/22633#290972

TickTimer is a cut down copy of Stopwatch that starts when constructed and does not support restarting. It will also notify you if the current hardware does not support high resolution timing (Stopwatch swallows this problem)

So this

var tickTimer = new TickTimer();
//call a method that takes some time
DoStuff();
tickTimer.Stop();
Debug.WriteLine("Elapsed HighResElapsedTicks " + tickTimer.HighResElapsedTicks);
Debug.WriteLine("Elapsed DateTimeElapsedTicks " + tickTimer.DateTimeElapsedTicks);
Debug.WriteLine("Elapsed ElapsedMilliseconds " + tickTimer.ElapsedMilliseconds);
Debug.WriteLine("Start Time " + new DateTime(tickTimer.DateTimeUtcStartTicks).ToLocalTime().ToLongTimeString());

will output this

Elapsed HighResElapsedTicks 10022886
Elapsed DateTimeElapsedTicks 41896
Elapsed ElapsedMilliseconds 4.18966178849554
Start Time 11:44:58

DebugTimer is a wrapper for TickTimer that will write the result to Debug. (note: it supports the Disposable pattern)

So this

using (new DebugTimer("DoStuff"))
{
    //call a method that takes some time
    DoStuff();
}

will output this to the debug window

DoStuff: Total 3.6299 ms

IterationDebugTimer is for timing how long it takes to run an operation multiple times and write the result to Debug. It will also perform an initial run that is not included so as to ignore startup time. (note: it supports the Disposable pattern)

So this

int x;
using (var iterationDebugTimer = new IterationDebugTimer("Add", 100000))
{
    iterationDebugTimer.Run(() =>
    {
        x = 1+4;
    });
}

Will output this

Add: Iterations 100000 
Total 1.198540 ms 
Single 0.000012 ms

Just to add to what others have already said about using Stopwatch and measuring averages.

Make sure you call your method before measuring. Otherwise you will measure the time needed to JIT compile the code as well. That may skew your numbers significantly.

Also, make sure you measure release mode code as optimizations are turned off by default for debug builds. Tuning debug code is pointless imho.

And make sure you're measuring what you actually want to measure. When optimizations kick in, the compiler/JIT compiler may rearrange code or remove it entirely, so you may end up measuring something a little different than intended. At least take a look at the generated code to make sure code has not been stripped.

Depending on what you're trying to measure keep in mind, that a real system will stress the runtime differently than a typical test application. Some performance problems are related to e.g. how objects are garbage collected. These problems will typically not show up in a simple test application.

Actually, the best advise is to measure real systems with real data as sandbox tests may turn out to be highly inaccurate.

You can use the Stopwatch, assuming you are using .NET 2.0 or newer.

System.Diagnostics.Stopwatch.StartNew();

The Stopwatch class also has public read-only field IsHighResolution that will let you know if the stopwatch is based on a high-resolution performance counter. If its not, it is based on the system timer.

I'm not sure what it takes for stopwatch to be based on high-resolution performance counter. There are some API calls but I figure if the stopwatch doesn't use a high resolution, then the API is probably not there.

Disposable style Stopwatch works best to me.

class VWatch : IDisposable {
    Stopwatch watch = new Stopwatch();
    public VWatch() {
        this.watch.Start();
    }
    public void Dispose() {
        this.watch.Stop();
        Console.WriteLine("Finished. Elapsed={0}", this.watch.Elapsed);
    }
}

And then:

using (new VWatch()) {
    /// do something for time measurement
}

My preferences go for BenchmarkDotNet mentioned by @Evgeniy. Probably his reply is bypassed because there is no code snippet, but as this is a complex item it worth at least taking a look into the library before to go head first into something bespoke.

And because some code always catches eyes, here is the example from the quoted site:

using System;
using System.Security.Cryptography;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;

namespace MyBenchmarks
{
    [ClrJob(baseline: true), CoreJob, MonoJob, CoreRtJob]
    [RPlotExporter, RankColumn]
    public class Md5VsSha256
    {
        private SHA256 sha256 = SHA256.Create();
        private MD5 md5 = MD5.Create();
        private byte[] data;

        [Params(1000, 10000)]
        public int N;

        [GlobalSetup]
        public void Setup()
        {
            data = new byte[N];
            new Random(42).NextBytes(data);
        }

        [Benchmark]
        public byte[] Sha256() => sha256.ComputeHash(data);

        [Benchmark]
        public byte[] Md5() => md5.ComputeHash(data);
    }

    public class Program
    {
        public static void Main(string[] args)
        {
            var summary = BenchmarkRunner.Run<Md5VsSha256>();
        }
    }
}

Sometimes it may be best to look at why you need to time the operation? Is it running slow? Or are you just curious? First rule of optimization is "Don't do it". So, depending on what you're actually measuring, could change the opinion on what tool is best suited for the task.

Related