Using IDisposable + timer to measure elapsed time

Question

I have some code that does a lot of work. It does enough work over enough time that we don't generally care about precise accuracy (i.e. to the millisecond), but being off by more than a minute would not be useful. We have a stored procedure that we call to log the start of a task, and the end of the task. Right now we have a lot of code that looks like this:

Logger.LogTaskStart(taskName);
// do stuff
Logger.LogTaskEnd(taskName);

Where the two methods save the metadata, which is eventually persisted via the afore-mentioned stored procedure. We also have some places where we may sometimes log timing information, but not always b/c it is either too much noise, or it usually doesn't have a problem.

if (debug) Logger.LogTaskStart(taskName);
// do stuff
if (debug) Logger.LogTaskEnd(taskName);

We've had issues where we inadvertently mismatch a start & end, or we only put one under a debug flag, etc. We've considered creating a pretty simple logger class that implements IDisposable to do it for us, such that we'd just do this (assume that the constructor starts the timer RAII style, and that Dispose stops it)

using (new Logger(taskName, debug))
{
    // Do stuff
}

As best as we can tell, this should just compile to approximately this:

Logger loggerThing = null;
try
{
    loggerThing = new Logger(taskName, debug);
    // Do stuff
}
finally
{
    loggerThing?.Dispose();
}

As such, it seems reasonably safe to use this for our larger tasks with enough granularity to be able to say "that ran a reasonable amount of time" or "that ran substantially faster/slower than normal". Are we right?

From some reading, I found the following articles, code samples, and SO Q&A. We clearly aren't the only people to have thought of this or something similar, but no-one seems to have ever given a clear and definitive answer to the question of "how timely can we assume Dispose will be called, and how reliable would timing results of that be?" Given the first post below, regarding how using is just syntactic sugar, we're inclined to think that is the case.

So clearly you have reasons not to trust the [answer](https://stackoverflow.com/a/4060720/477420) from question you've linked to... but why? What exactly is missing to clarify to you how `Dispose` is called by `using`? — Alexei Levenkov, Apr 12 '19 at 22:27
What do you mean by timely? Dispose is going to be called at the end of the using block. — pinkfloydx33, Apr 12 '19 at 23:27

James Adcock · Answer 1 · 2019-04-13T16:21:57.500

The Dispose method is called immediately after the code in the using statement. To confirm this we can take a peek at the IL that is generated from a using statement:

The following simple example:

    class Program
    {
        static void Main()
        {
            using (new TestClass())
            {
                Console.WriteLine("Do work");

            }
        }
    }

    class TestClass : IDisposable
    {
        public void Dispose()
        {
            Console.WriteLine("disposed");
        }
    }

Produces the following IL.

Program.Main:
IL_0000:  nop         
IL_0001:  newobj      UserQuery+TestClass..ctor
IL_0006:  stloc.0     
IL_0007:  nop         
IL_0008:  ldstr       "Do work"
IL_000D:  call        System.Console.WriteLine
IL_0012:  nop         
IL_0013:  nop         
IL_0014:  leave.s     IL_0021
IL_0016:  ldloc.0     
IL_0017:  brfalse.s   IL_0020
IL_0019:  ldloc.0     
IL_001A:  callvirt    System.IDisposable.Dispose
IL_001F:  nop         
IL_0020:  endfinally  
IL_0021:  ret         

Program..ctor:
IL_0000:  ldarg.0     
IL_0001:  call        System.Object..ctor
IL_0006:  nop         
IL_0007:  ret         

TestClass.Dispose:
IL_0000:  nop         
IL_0001:  ldstr       "disposed"
IL_0006:  call        System.Console.WriteLine
IL_000B:  nop         
IL_000C:  ret         

TestClass..ctor:
IL_0000:  ldarg.0     
IL_0001:  call        System.Object..ctor
IL_0006:  nop         
IL_0007:  ret

Here we can see the dispose method being called immediately after the code in the using statement.

Using IDisposable + timer to measure elapsed time

1 Answers1