Exact time measurement for performance testing

Question

What is the most exact way of seeing how long something, for example a method call, took in code?

The easiest and quickest I would guess is this:

DateTime start = DateTime.Now;
{
    // Do some work
}
TimeSpan timeItTook = DateTime.Now - start;

But how exact is this? Are there better ways?

Answer 1

A better way is to use the Stopwatch class:

using System.Diagnostics;
// ...

Stopwatch sw = new Stopwatch();

sw.Start();

// ...

sw.Stop();

Console.WriteLine("Elapsed={0}",sw.Elapsed);

Answer 2

As others have said, Stopwatch is a good class to use here. You can wrap it in a helpful method:

public static TimeSpan Time(Action action)
{
    Stopwatch stopwatch = Stopwatch.StartNew();
    action();
    stopwatch.Stop();
    return stopwatch.Elapsed;
}

(Note the use of Stopwatch.StartNew(). I prefer this to creating a Stopwatch and then calling Start() in terms of simplicity.) Obviously this incurs the hit of invoking a delegate, but in the vast majority of cases that won't be relevant. You'd then write:

TimeSpan time = StopwatchUtil.Time(() =>
{
    // Do some work
});

You could even make an ITimer interface for this, with implementations of StopwatchTimer, CpuTimer etc where available.

Answer 3

As others said, Stopwatch should be the right tool for this. There can be few improvements made to it though, see this thread specifically: Benchmarking small code samples in C#, can this implementation be improved?.

I have seen some useful tips by Thomas Maierhofer here

Basically his code looks like:

//prevent the JIT Compiler from optimizing Fkt calls away
long seed = Environment.TickCount;

//use the second Core/Processor for the test
Process.GetCurrentProcess().ProcessorAffinity = new IntPtr(2);

//prevent "Normal" Processes from interrupting Threads
Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.High;

//prevent "Normal" Threads from interrupting this thread
Thread.CurrentThread.Priority = ThreadPriority.Highest;

//warm up
method();

var stopwatch = new Stopwatch()
for (int i = 0; i < repetitions; i++)
{
    stopwatch.Reset();
    stopwatch.Start();
    for (int j = 0; j < iterations; j++)
        method();
    stopwatch.Stop();
    print stopwatch.Elapsed.TotalMilliseconds;
}

Another approach is to rely on Process.TotalProcessTime to measure how long the CPU has been kept busy running the very code/process, as shown here This can reflect more real scenario since no other process affects the measurement. It does something like:

 var start = Process.GetCurrentProcess().TotalProcessorTime;
 method();
 var stop = Process.GetCurrentProcess().TotalProcessorTime;
 print (end - begin).TotalMilliseconds;

A naked, detailed implementation of the samething can be found here.

I wrote a helper class to perform both in an easy to use manner:

public class Clock
{
    interface IStopwatch
    {
        bool IsRunning { get; }
        TimeSpan Elapsed { get; }

        void Start();
        void Stop();
        void Reset();
    }



    class TimeWatch : IStopwatch
    {
        Stopwatch stopwatch = new Stopwatch();

        public TimeSpan Elapsed
        {
            get { return stopwatch.Elapsed; }
        }

        public bool IsRunning
        {
            get { return stopwatch.IsRunning; }
        }



        public TimeWatch()
        {
            if (!Stopwatch.IsHighResolution)
                throw new NotSupportedException("Your hardware doesn't support high resolution counter");

            //prevent the JIT Compiler from optimizing Fkt calls away
            long seed = Environment.TickCount;

            //use the second Core/Processor for the test
            Process.GetCurrentProcess().ProcessorAffinity = new IntPtr(2);

            //prevent "Normal" Processes from interrupting Threads
            Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.High;

            //prevent "Normal" Threads from interrupting this thread
            Thread.CurrentThread.Priority = ThreadPriority.Highest;
        }



        public void Start()
        {
            stopwatch.Start();
        }

        public void Stop()
        {
            stopwatch.Stop();
        }

        public void Reset()
        {
            stopwatch.Reset();
        }
    }



    class CpuWatch : IStopwatch
    {
        TimeSpan startTime;
        TimeSpan endTime;
        bool isRunning;



        public TimeSpan Elapsed
        {
            get
            {
                if (IsRunning)
                    throw new NotImplementedException("Getting elapsed span while watch is running is not implemented");

                return endTime - startTime;
            }
        }

        public bool IsRunning
        {
            get { return isRunning; }
        }



        public void Start()
        {
            startTime = Process.GetCurrentProcess().TotalProcessorTime;
            isRunning = true;
        }

        public void Stop()
        {
            endTime = Process.GetCurrentProcess().TotalProcessorTime;
            isRunning = false;
        }

        public void Reset()
        {
            startTime = TimeSpan.Zero;
            endTime = TimeSpan.Zero;
        }
    }



    public static void BenchmarkTime(Action action, int iterations = 10000)
    {
        Benchmark<TimeWatch>(action, iterations);
    }

    static void Benchmark<T>(Action action, int iterations) where T : IStopwatch, new()
    {
        //clean Garbage
        GC.Collect();

        //wait for the finalizer queue to empty
        GC.WaitForPendingFinalizers();

        //clean Garbage
        GC.Collect();

        //warm up
        action();

        var stopwatch = new T();
        var timings = new double[5];
        for (int i = 0; i < timings.Length; i++)
        {
            stopwatch.Reset();
            stopwatch.Start();
            for (int j = 0; j < iterations; j++)
                action();
            stopwatch.Stop();
            timings[i] = stopwatch.Elapsed.TotalMilliseconds;
            print timings[i];
        }
        print "normalized mean: " + timings.NormalizedMean().ToString();
    }

    public static void BenchmarkCpu(Action action, int iterations = 10000)
    {
        Benchmark<CpuWatch>(action, iterations);
    }
}

Just call

Clock.BenchmarkTime(() =>
{
    //code

}, 10000000);

or

Clock.BenchmarkCpu(() =>
{
    //code

}, 10000000);

The last part of the Clock is the tricky part. If you want to display the final timing, its up to you to choose what sort of timing you want. I wrote an extension method NormalizedMean which gives you the mean of the read timings discarding the noise. I mean I calculate the the deviation of each timing from the actual mean, and then I discard the values which was farer (only the slower ones) from the mean of deviation (called absolute deviation; note that its not the often heard standard deviation), and finally return the mean of remaining values. This means, for instance, if timed values are { 1, 2, 3, 2, 100 } (in ms or whatever), it discards 100, and returns the mean of { 1, 2, 3, 2 } which is 2. Or if timings are { 240, 220, 200, 220, 220, 270 }, it discards 270, and returns the mean of { 240, 220, 200, 220, 220 } which is 220.

public static double NormalizedMean(this ICollection<double> values)
{
    if (values.Count == 0)
        return double.NaN;

    var deviations = values.Deviations().ToArray();
    var meanDeviation = deviations.Sum(t => Math.Abs(t.Item2)) / values.Count;
    return deviations.Where(t => t.Item2 > 0 || Math.Abs(t.Item2) <= meanDeviation).Average(t => t.Item1);
}

public static IEnumerable<Tuple<double, double>> Deviations(this ICollection<double> values)
{
    if (values.Count == 0)
        yield break;

    var avg = values.Average();
    foreach (var d in values)
        yield return Tuple.Create(d, avg - d);
}

Answer 4

Use the Stopwatch class

Answer 5

System.Diagnostics.Stopwatch is designed for this task.

Answer 6

Stopwatch is fine, but loop the work 10^6 times, then divide by 10^6. You'll get a lot more precision.

Answer 7

I'm using this:

HttpWebRequest request = (HttpWebRequest)WebRequest.Create(myUrl);
System.Diagnostics.Stopwatch timer = new Stopwatch();

timer.Start();

HttpWebResponse response = (HttpWebResponse)request.GetResponse();

statusCode = response.StatusCode.ToString();

response.Close();

timer.Stop();