Time measurement in ASP.NET page

Question

I have a normal asp.net page containing some code that I want to measure the execution time of. I have created a very basic helper class for this purpose:

public class Timing
{
    private long m_ticksBefore;
    private long m_ticksAfter;

    public void Before()
    {
        m_ticksBefore = DateTime.Now.Ticks;
    }

    public void After()
    {
        m_ticksAfter = DateTime.Now.Ticks;
    }

    public void TraceTime(string note)
    {
        TimeSpan span = new TimeSpan(m_ticksAfter - m_ticksBefore);
        System.Diagnostics.Trace.Write(string.Format("\n...Timing for {0}...\nTicks: \t{1}\nMilliseconds: \t{2}\nSeconds: \t{3}\n..................", note, span.Ticks, span.TotalMilliseconds, span.TotalSeconds));
    }
}

I instantiate a new Timing object and wrap the code I wish to monitor with the Before() and After methods and finally call the TraceTime() method in order to output the result to the output window in the IDE.

The strange thing is that the first request to the page results in an expected timing result of some 40 milliseconds, but refreshing the page (F5) gives me 0 ticks of execution time. Even executing the page with new parameters forcing the execution of different code within the monitored area reveals a flat 0.

If I use System.Diagnostics.StopWatch instead I get much more realistic results

Stopwatch watch1 = Stopwatch.StartNew();
//Some code to monitor
watch1.Stop();
System.Diagnostics.Trace.Write(watch1.ElapsedTicks);

To me the code seems very similar and I cannot seem to find out why the first approach fails to output realistic results...

It seems to be some sort of optimization issue that is performed behind the scene, but I don't really get it. Maybe it is due to my personal Timing issue i.e. bed-time issue...

Answer 1

I'm not experiencing the same problem as you are. I put the following code on a button click event:

Timing timing = new Timing();
timing.Before();
for (int i = 0; i < 100; i++)
    Thread.Sleep(1);
timing.After();
// I altered TraceTime to receive a HttpResponse.
timing.TraceTime("this is a note", this.Response);

The response is always close to:

...Timing for this is a note... Ticks: 1000057 Milliseconds: 100,0057 Seconds: 0,1000057 ..................

No matter if it's a post back, not post back... If I refreshed the page or not.

How are you using the Timing class?

Edit

I also put the code above on the Page Load handler and got the exact same results. It doesn't matter if it's a post-back, refresh or whatever.

You have to tell us the context in which the error is happening.

Answer 2

Although DateTime.Now appears to have a resolution of 100ns, Windows actually only updates its internal clock every 15ms. Therefore, if your code takes less than about 7.5ms to run, it will appear to have taken no time at all, since on average you have to wait 7.5ms for DateTime.Now to change.

If you need more accurate timing, you can (as you've found) use StopWatch. This uses a different, more accurate API to get results.

EDIT The MSDN documentation for DateTime.Now gives the resolution as "approximately 10ms". The GetTickCount API (which uses the same system timer) gives its resolution as "typically in the range of 10 milliseconds to 16 milliseconds".

Apparently it's hardware dependent - single processor systems are typically 10ms, multiple processor systems are typically 15ms.