C# *Strange* problem with StopWatch and a foreach loop

Question

I have the this code:

var options = GetOptions(From, Value, SelectedValue);     
var stopWatch = System.Diagnostics.Stopwatch.StartNew();

foreach (Option option in options)
{
    stringBuilder.Append("<option");

    stringBuilder.Append(" value=\"");
    stringBuilder.Append(option.Value);
    stringBuilder.Append("\"");

    if (option.Selected)
        stringBuilder.Append(" selected=\"selected\"");

    stringBuilder.Append('>');

    stringBuilder.Append(option.Text);
    stringBuilder.Append("</option>");
}

HttpContext.Current.Response.Write("<b>" + stopWatch.Elapsed.ToString() + "</b><br>");

It is writing:
00:00:00.0004255 in the first try (not in debug)
00:00:00.0004260 in the second try and
00:00:00.0004281 in the third try.

Now, if I change the code so the measure will be inside the foreach loop:

var options = GetOptions(From, Value, SelectedValue);     

foreach (Option option in options)
{
    var stopWatch = System.Diagnostics.Stopwatch.StartNew();

    stringBuilder.Append("<option");

    stringBuilder.Append(" value=\"");
    stringBuilder.Append(option.Value);
    stringBuilder.Append("\"");

    if (option.Selected)
        stringBuilder.Append(" selected=\"selected\"");

    stringBuilder.Append('>');

    stringBuilder.Append(option.Text);
    stringBuilder.Append("</option>");

    HttpContext.Current.Response.Write("<b>" + stopWatch.Elapsed.ToString() + "</b><br>");
}

...I get
[00:00:00.0000014, 00:00:00.0000011] = 00:00:00.0000025 in the first try (not in debug),
[00:00:00.0000016, 00:00:00.0000011] = 00:00:00.0000027 in the second try and
[00:00:00.0000013, 00:00:00.0000011] = 00:00:00.0000024 in the third try.

?!
It is completely unsense according to the first results... I've heard that the foreach loop is slow, but never imagined that it is so slow... Is it that?

options has 2 options. Here's the option class, if it is needed:

public class Option
{
    public Option(string text, string value, bool selected)
    {
        Text = text;
        Value = value;
        Selected = selected;
    }

    public string Text
    {
        get;
        set;
    }

    public string Value
    {
        get;
        set;
    }

    public bool Selected
    {
        get;
        set;
    }
}

Thanks.

Answer 1

Hard to tell since you didn't tell us how many items you have in your Options collection.

Answer 2

The first code example doesn't output anything until all the options have been iterated while the second one outputs a time after the first option has been processed. If there are multiple options, you would expect to see such a difference.

Answer 3

If you measure the time taken to do something 160 times, it will usually take of the order of 160 times longer than measuring the time it takes to do it once. Are you suggesting that the contents of the loop is only executed once, or are you trying to compare chalk and cheese?

In the first case, try changing the last line of your code from using stopWatch.Elapsed.ToString() to stopWatch.Elapsed.ToString() / options.Count

That will at least mean you are comparing one iteration with one iteration.

However, your results will still be useless. Timing a very short operation once gives poor results - you have to repeat such thing tens of thousands of times to get a statistically meaningingful average time. Otherwise the inaccuracy of the system clock and the overheads involved in starting and stopping your timer will swamp your results.

Also, what is the PC doing while all this is happening? If there are other processes loading the CPU, then they could easily interfere with your timings. If you're running this on a busy server then you may get competely random results.

Lastly, how you exceute the tests can alter things. If you always run test 1 followed by test 2, it's possible that running the first test affects CPU caches (e.g. of the data in the options list) etc so that the following code is able to execute faster. If garbage collection occurs during one of your tests, it wil skew the results.

You need to eliminate all these factors before you have numbers that are worth comparing. Only then should you ask "why is test 1 running so much slower than test 2"?

Answer 4

The foreach loop itself has nothing to do with the time difference.

What is the GetOptions method returning? My guess is that it's not returning a collection of options, but rather an enumerator that is capable of getting the options. That means that actually fetching the options are not done until you start to iterate them.

In the first case you are starting the clock before starting iterating the options, which means that the time for fetching the options is included in the time.

In the second case you are starting the clock after starting iterating the options, which means that the time for fetching the options is not included in the time.

So, the time difference that you see it not due to the foreach loop itself, it's the time it takes to fetch the options.

You can make sure that the options are fetched immediately by reading them into a collection:

var options = GetOptions(From, Value, SelectedValue).ToList();

Now measure the performance, and you will see very little difference.

Answer 5

Just pause it a few times in the IDE and you'll see where the time goes.

There's a very natural and strong temptation to think that the time things take is proportional to how much code they are. For example, which do you think is faster?

for (MyClass x in y)

for (MyClass theParticularInstanceOfClass in MyCollectionOfInstances)

It is natural to think that the first is faster, when in fact the code size is irrelevant and could be hiding a multitude of expensive operations.