Async method that throws Exception not working

[adrianignat13]

You should already be a Patron

I am testing Fody to see if we can use it in our project and if so, we will become a patron. If this means that I cannot raise an issue, please ignore this.

Describe the issue

I have a simple async function that awaits a Task and then throws an exception afterwards. When I wrap this with [Time] there are two things that go weird a) the total time is incorrect (the await time is not taken into account) b) the time is written to the console twice.

Minimal Repro

https://github.com/adrianignat13/MethodTimerSample

From output:
Program.AsyncDelay 12ms
Exception thrown: 'System.Exception' in MethodTimerSample.exe
Program.AsyncDelay 12ms

Expected output (manual weaving)
Program.AsyncDelayWithTimer 00:00:01.0291857ms
Exception thrown: 'System.AggregateException' in mscorlib.dll

[GeertvanHorrik]

Since I wrote this part, and it could potentially affect us, I will look into this. Luckily you can actually evaluate this with any other use-case so that shouldn't block the considering whether you are becoming a patron or not.

Note that the Patron stuff is handled by @SimonCropp and I still think you should consider it ;-)

[SimonCropp]

I am testing Fody to see if we can use it in our project and if so, we will become a patron. If this means that I cannot raise an issue, please ignore this.

yes the issue will still be looked at due to this caveat

Issues from non-Patrons, that are bugs and are highly likely to effect the larger Fody user base, may justify the effort and be handled.

https://github.com/Fody/Home/blob/master/pages/licensing-patron-faq.md#do-i-need-to-be-a-patron-to-raise-an-issue

[GeertvanHorrik]

The reason it was not working correctly is because of the throwing of the exception that caused no other exit paths available in the example method.

I've much simplified the way MethodTimer deals with async methods by changing the following:

1. Add member method that only logs when the state machine is complete (state value == -2)
2. Call this method after every MoveNext call at the end of the method or before SetException (then the method execution stops as well)

Here is the output of a test console app:

The bottom one is from the repro provided by @adrianignat13

Here is the updated generated code after weaving for a state machine:

StopMethodTimerStopwatch()

private void StopMethodTimerStopwatch()
{
    if (this.<>__state != -2)
        return;
    this.methodTimerStopwatch.Stop();
    this.methodTimerMessage = (string) null;
    MethodTimeLogger.Log(MethodBase.GetMethodFromHandle(__methodref (Program.AsyncDelay), __typeref (Program)), this.methodTimerStopwatch.ElapsedMilliseconds, this.    
}

MoveNext()

As you can see, there are 2 places where StopMethodTimerStopwatch is being called, just before SetException and at the end of the method)

void IAsyncStateMachine.MoveNext()
{
    if (this.methodTimerStopwatch == null)
        this.methodTimerStopwatch = Stopwatch.StartNew();
    int num1 = this.<>1__state;
    try
    {
      TaskAwaiter awaiter;
      int num2;
      if (num1 != 0)
      {
        awaiter = Task.Delay(1000).GetAwaiter();
        if (!awaiter.IsCompleted)
        {
            this.<>1__state = num2 = 0;
            this.<>u__1 = awaiter;
            Program.<AsyncDelay>d__7 stateMachine = this;
            this.<>t__builder.AwaitUnsafeOnCompleted<TaskAwaiter, Program.<AsyncDelay>d__7>(ref awaiter, ref stateMachine);
            goto label_9;
        }
      }
      else
      {
        awaiter = this.<>u__1;
        this.<>u__1 = new TaskAwaiter();
        this.<>1__state = num2 = -1;
      }
      awaiter.GetResult();
      throw new Exception();
    }
    catch (Exception ex)
    {
        this.<>1__state = -2;
        ref AsyncTaskMethodBuilder local = ref this.<>t__builder;
        Exception exception = ex;
        this.StopMethodTimerStopwatch();
        local.SetException(exception);
    }
    label_9:
    this.StopMethodTimerStopwatch();
}

[SimonCropp]

This is now deployed. NuGet may take some time to make it available for download.

[adrianignat13]

Thanks for the quick turnaround. Really great work. I tested it and now the timer is computed correctly. However, the message is still logged twice.

Program.AsyncDelay 1039ms
Program.AsyncDelay 1039ms
Exception thrown: 'System.AggregateException' in mscorlib.dll
Exception thrown: 'System.Exception' in MethodTimerSample.exe
Program.AsyncDelayWithTimer 1010.0555ms
Exception thrown: 'System.AggregateException' in mscorlib.dll

If you use the log to count the number of times a method was called, this issue will skew the results.

Also, for my understanding, the method with [Timer] throws two exceptions, whereas the manually instrumented one throws only one. What is happening there?

[GeertvanHorrik]

In my tests it doesn't do it twice (because of the check for -2 in the state machine). Can you update your repro?

[adrianignat13]

I've updated my repo.

[GeertvanHorrik]

Can you try with a custom MethodTimeLogger such as this one (then you can actually put breakpoints, etc):

using System.Reflection;
using System;

/// <summary>
/// Note: do not rename this class or put it inside a namespace.
/// </summary>
internal static class MethodTimeLogger
{
    public static void Log(MethodBase methodBase, long milliseconds, string message)
    {
        Log(methodBase.DeclaringType, methodBase.Name, milliseconds, message);
    }

    public static void Log(Type type, string methodName, long milliseconds, string message)
    {
        if (type is null)
        {
            return;
        }

        //if (milliseconds == 0)
        //{
        //    // Don't log superfast methods
        //    return;
        //}

        var finalMessage = $"[METHODTIMER] {type.Name}.{methodName} took '{milliseconds}' ms";

        if (!string.IsNullOrWhiteSpace(message))
        {
            finalMessage += $" | {message}";
        }

        Console.WriteLine(finalMessage);
    }
}

[adrianignat13]

I've updated the repo with the MethodTimeLogger you provieded.

I sill get the Time method logged twice.

[METHODTIMER] Program.AsyncDelay took '1028' ms
[METHODTIMER] Program.AsyncDelay took '1028' ms
[METHODTIMER] d__2.MoveNext took '1010' ms

[GeertvanHorrik]

Interesting, will try in an hour or so.

[GeertvanHorrik]

I can indeed repro this. Investigating the generated IL. The reason is that after throwing the exception, the method does not return. Will create a separate PR to fix this.

[GeertvanHorrik]

[GeertvanHorrik]

I think the most realist way to solve this is to check whether the stopwatch is actually running. If not, then the method has already finished and does should not take any time anyway (so re-running the same task would not result in another method time log):

if (<>1__state != 2 || !stopwatch.IsRunning)
{
    return;
}

stopwatch.Stop();
Log();

[GeertvanHorrik]

Here is the final result:

[SimonCropp]

This is now deployed. NuGet may take some time to make it available for download.

thanks a heap to @GeertvanHorrik

[adrianignat13]

Tested, it works as expected now. Great work @GeertvanHorrik

[METHODTIMER] Program.AsyncDelay took '1043' ms
[METHODTIMER] d__2.MoveNext took '1010' ms