Alois Kraus

blog

  Home  |   Contact  |   Syndication    |   Login
  111 Posts | 8 Stories | 296 Comments | 162 Trackbacks

News



Article Categories

Archives

Post Categories

Image Galleries

Programming

I do performance measurements quite regularly which involves to call a piece of code several times to measure how long it did take. I am sure nearly everybody has done this already. But as a physicist I know that (nearly) every measurement has fundamental problems which never go away. Key to a successful measurement is that you exactly know what you are measuring and not what you think you measure. The easiest way to get out of this dilemma without too much knowledge is to simply ignore the fact that you don´t know enough and restrict yourself to pure differential measurements. With differential I do mean that you measure it once, change the code in a way that makes it better and measure it again. When you measure different times then you can assume that your code change was the cause for the different timing. That does work to some extent quite well but you should always be vigilant when the results change dramatically from one build to the next. There is no error I did not make with performance measurements so I think it is safe to give away my top 101:

  1. DateTime.Now has a resolution of ~16ms. If you measure anything faster you must use Stopwatch which has a resolution of about 100ns.
  2. With Windows Vista you need to set your Power options to maximum performance to prevent the OS from change the CPU clock frequency at random times.
  3. Warm and cold start times are way different. Usually a factor of 2-6 is quite normal. With cold startup I mean that you have a fresh booted system which did have never run your test case. This cold startup time does mainly contribute to disk IO which you can watch with XPerf very nicely.
  4. Be sure that you measure the right thing. I cannot emphasize this enough. Did you really measure the right thing?
  5. Know your influencers. You need to get a good understanding how much e.g. number of iterations, input data size, concurrency, other applications can affect the outcome. I had more than once the case that I did execute a test in the evening and then next morning. But the results did differ by a factor two for no apparent reason.
  6. Debug and Release builds still differ in the managed world. Although the difference is much smaller than it was with C++.
  7. First time initialization effects should be measured separately. When you initialize a class and call some method 10 million times it makes not much sense to mix the ctor call time with pure function calling time.
  8. Do measure long enough to get reliable results. The mean value is a powerful ally to flatten sporadic effects.
  9. If you get strange disk IO reports check if a virus scanner does interfere.
  10. Other processes might be running as well. These might influence your test if they consume significant resources.
  11. Stupid but happens: Turn off tracing before you measure.

You still want to make some quick throw away measurements? You have been warned. It is a tricky thing. To get at least the timing calculation right I did create some extension methods I want to share there. With these extensions you can create an Action delegate and call the new Profile method on it to execute it n-times. To give you full control over the string formatting you can supply a format string which expands {runs}, {time} and {frequency} in a human readable way for you.

            Action func = () =>

            {

                using (File.OpenRead(@"C:\config.sys"))

                {

                }

            };

 

            func.Profile(1000, "Did open the file {runs} times in {time}s. Can do {frequency} File.Open/s");

That little snippet produces on the console

Did open the file 1 000 times in 0.06s. Can do 16 667 File.Open/s

Since we know that the first call to File.Open will involve actual disk accesses which are much slower we want to measure the first call independently to see the "cold" startup performance as well:

 

func.ProfileWithFirst(1000, "First File Open did take {time}s", "Did open the file {runs} times in {time}s. Can do {frequency} File.Open/s");

That will give us

First File Open did take 0.00s
Did open the file 999 times in 0.05s. Can do 20 388 File.Open/s

There are also times when you want to control the number of iterations by yourself. Nothing easier than that. Simply change the delegate type from Action to Func<int> and you are ready to go.

 

            Func<int> myFunc = () =>

                {

                    const int Runs = 1000;

                    for (int i = 0; i < Runs; i++)

                    {

                        using (File.OpenRead(@"C:\config.sys")) ;

                        using (File.OpenRead(@"C:\autoexec.bat")) ;

                    }

 

                    return Runs * 2;

                };

 

            myFunc.Profile("Did open {runs} files in {time}s");

That was almost too easy. But what if I do not like the formatting? Well it turns out you can customize it still. The format string placeholders {0} {1} and {2} are the number of runs, elapsed time in seconds  as float and call frequency (runs/s)  as float. They can be used as usual to customize the output format to your specific needs.

myFunc.Profile("Did open {runs} files in {1:F5}s");

Did open 2 000 files in 0,10000s

The actual class is written in C# 3.0 with lambda expressions. The usage of this rather low level primitives gives you a rather surprising amount of flexibility and composability to build higher level functions.

Here is the source code for the Action and Func<int> delegate extension methods:

 

using System;

using System.Globalization;

using System.Diagnostics;

 

namespace PerformanceTester

{

    /// <summary>

    /// Helper class to print out performance related data like number of runs, elapsed time and frequency

    /// </summary>

    public static class Extension

    {

        static NumberFormatInfo myNumberFormat;

 

        static NumberFormatInfo NumberFormat

        {

            get

            {

                if (myNumberFormat == null)

                {

                    var local = new CultureInfo("en-us", false).NumberFormat;

                    local.NumberGroupSeparator = " "; // set space as thousand separator

                    myNumberFormat = local; // make a thread safe assignment with a fully initialized variable

                }

                return myNumberFormat;

            }

        }

 

        /// <summary>

        /// Execute the given function and print the elapsed time to the console.

        /// </summary>

        /// <param name="func">Function that returns the number of iterations.</param>

        /// <param name="format">Format string which can contain {runs} or {0},{time} or {1} and {frequency} or {2}.</param>

        public static void Profile(this Func<int> func, string format)

        {

 

            Stopwatch watch = Stopwatch.StartNew();

            int runs = func();  // Execute function and get number of iterations back

            watch.Stop();

 

            string replacedFormat = format.Replace("{runs}", "{3}")

                                          .Replace("{time}", "{4}")

                                          .Replace("{frequency}", "{5}");

 

            // get elapsed time back

            float sec = watch.ElapsedMilliseconds / 1000.0f;

            float frequency = runs / sec; // calculate frequency of the operation in question

 

            try

            {

                Console.WriteLine(replacedFormat,

                                    runs,  // {0} is the number of runs

                                    sec,   // {1} is the elapsed time as float

                                    frequency, // {2} is the call frequency as float

                                    runs.ToString("N0", NumberFormat),  // Expanded token {runs} is formatted with thousand separators

                                    sec.ToString("F2", NumberFormat),   // expanded token {time} is formatted as float in seconds with two digits precision

                                    frequency.ToString("N0", NumberFormat)); // expanded token {frequency} is formatted as float with thousands separators

            }

            catch (FormatException ex)

            {

                throw new FormatException(

                    String.Format("The input string format string did contain not an expected token like "+

                                  "{{runs}}/{{0}}, {{time}}/{{1}} or {{frequency}}/{{2}} or the format string " +

                                  "itself was invalid: \"{0}\"", format), ex);

            }

        }

 

        /// <summary>

        /// Execute the given function n-times and print the timing values (number of runs, elapsed time, call frequency)

        /// to the console window.

        /// </summary>

        /// <param name="func">Function to call in a for loop.</param>

        /// <param name="runs">Number of iterations.</param>

        /// <param name="format">Format string which can contain {runs} or {0},{time} or {1} and {frequency} or {2}.</param>

        public static void Profile(this Action func, int runs, string format)

        {

            Func<int> f = () =>

            {

                for (int i = 0; i < runs; i++)

                {

                    func();

                }

                return runs;

            };

            f.Profile(format);

        }

 

        /// <summary>

        /// Call a function in a for loop n-times. The first function call will be measured independently to measure

        /// first call effects.

        /// </summary>

        /// <param name="func">Function to call in a loop.</param>

        /// <param name="runs">Number of iterations.</param>

        /// <param name="formatFirst">Format string for first function call performance.</param>

        /// <param name="formatOther">Format string for subsequent function call performance.</param>

        /// <remarks>

        /// The format string can contain {runs} or {0},{time} or {1} and {frequency} or {2}.

        /// </remarks>

        public static void ProfileWithFirst(this Action func, int runs, string formatFirst, string formatOther)

        {

            func.Profile(1, formatFirst);

            func.Profile(runs - 1, formatOther);

        }

    }

 

}

posted on Tuesday, December 16, 2008 11:21 AM

Feedback

# re: Measure Performance With Stopwatch 12/17/2008 10:42 PM Peter Gfader
Good post Alois.

Thx for that Extension methods.
Will definitely use them.

Peter

# re: Measure Performance With Stopwatch 12/18/2008 8:44 PM pumaboyd
very good nice

# re: Measure Performance With Stopwatch 6/3/2010 5:21 PM arjaygg
Hi Alois,

Thanks for sharing this.

very nice solution.

# re: Measure Performance With Stopwatch 12/15/2010 1:31 PM titwan
Really nice, I have extended for my purpose. I would definitively use it for testing. Thanks. Happy Xmass.

Post A Comment
Title:
Name:
Email:
Comment:
Verification: