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

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.