Skip to content
This repository was archived by the owner on Jan 23, 2023. It is now read-only.

Resolve iterators and async methods in stacktrace#14655

Merged
karelz merged 1 commit intodotnet:masterfrom
benaadams:resolve-iterators-and-async
Jan 25, 2018
Merged

Resolve iterators and async methods in stacktrace#14655
karelz merged 1 commit intodotnet:masterfrom
benaadams:resolve-iterators-and-async

Conversation

@benaadams
Copy link
Member

@benaadams benaadams commented Oct 23, 2017

Allows a developer to determine correct overload called for async and iterators, from a stacktrace.

Matches the complier generated containing Type to the source method using:
method.DeclaringType == StateMachineAttribute.StateMachineType attribute to allow the stack trace to resolve the mangled method name to the correct overload. Also appends the statemachine method name with + for iterators (addressing #14655 (comment)).

Changes:

async

System.Exception: Exception of type 'System.Exception' was thrown.
   at Program.RecursiveAsync(Int32 count)
   at Program.RecursiveAsync(Int32 count)
   at Program.RecursiveAsync(Int32 count)
   at Program.MethodAsync()
   at Program.Main(String[] args)

Instead of the current:

System.Exception: Exception of type 'System.Exception' was thrown.
   at Program.<RecursiveAsync>d__2.MoveNext()
   at Program.<RecursiveAsync>d__2.MoveNext()
   at Program.<RecursiveAsync>d__2.MoveNext()
   at Program.<MethodAsync>d__1.MoveNext()
   at Program.<Main>d__0.MoveNext()

iterators

System.Exception: Exception of type 'System.Exception' was thrown.
   at Program.Range(Int32 start, Int32 end)+MoveNext()
   at Program.Range(Int32 start, Int32 end)+MoveNext()
   at Program.Main(String[] args)

Instead of the current:

System.Exception: Exception of type 'System.Exception' was thrown.
   at Program.<Range>d__1.MoveNext()
   at Program.<Range>d__1.MoveNext()
   at Program.Main(String[] args)

Builds on the other PRs for improving async stacktrace readability:

Which removed the async noise:

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) 
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult() 
   at ...
--- End of stack trace from previous location where exception was thrown ---

Resolves: https://github.com/dotnet/corefx/issues/24627

PTAL @stephentoub @tmat @noahfalk @aelij

@benaadams benaadams force-pushed the resolve-iterators-and-async branch 3 times, most recently from b09fd14 to 89a01b5 Compare October 23, 2017 13:14
return !(mb.IsDefined(typeof(StackTraceHiddenAttribute)) || (mb.DeclaringType?.IsDefined(typeof(StackTraceHiddenAttribute)) ?? false));
}

private static Type ResolveStateMachineMethod(ref MethodBase mb, Type stateMachineType)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is mb passed by ref but stateMachineType passed as an arg and then returned?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Change to both be ref

mb = method as MethodBase ?? mb;
stateMachineType = mb.DeclaringType;
break;
}
Copy link
Member

@stephentoub stephentoub Oct 23, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if (asma != null && asma.StateMachineType == stateMachineType && method is MethodBase matched)
{
    mb = matched;
    stateMachineType = matched.DeclaringType;
    break;
}

?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed

sb.AppendFormat(CultureInfo.InvariantCulture, " {0} ", word_At);

Type t = mb.DeclaringType;
if (typeof(IAsyncStateMachine).IsAssignableFrom(t) || typeof(IEnumerator).IsAssignableFrom(t))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Check for [CompilerGenerated]?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added

@stephentoub
Copy link
Member

stephentoub commented Oct 23, 2017

Seems a bit strange that we're hiding the MoveNext method for compiler-generated enumerators, but we don't (and presumably wouldn't want to) for others (e.g. the one for list in your example stack trace). Why are the compiler-generated ones special?

@benaadams
Copy link
Member Author

benaadams commented Oct 23, 2017

Why are the compiler-generated ones special?

User code mapping; like the line numbers refer to the original source its mapping the method name back to the original source.

The statemachine's MoveNext is a post-compile transform to the original source and can be impenetrable if there are overloads and no line numbers - which doesn't help with diagnosing the problem.

The List.MoveNext is the original source; whereas this isn't

at Program.<ValueTaskAsync>d__9.MoveNext()  in C:\Exceptions\Program.cs:line 126

The line number; while correct, certainly isn't in a method called <ValueTaskAsync>d__9.MoveNext() because that method does not exist in Program.cs

@stephentoub
Copy link
Member

stephentoub commented Oct 23, 2017

because that method does not exist in Program.cs

Neither does List'1.Enumerator.MoveNext.

There is a fundamental difference between an exception escaping from:

System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)

and an exception escaping from:

System.Linq.Enumerable.<SkipWhileIterator>d__179`1.MoveNext()

as they're two distinct methods. An exception escaping from the former means it's coming out of the synchronous call to SkipWhileIterator, whereas an exception coming out of the latter is coming from a call at some point later to MoveNext, which of course does exist on the IEnumerator<T> interface that's being used. So this transformation is both effectively lying (it's saying the exception is coming from one method when it's really coming from another) and it's suggesting somehow that calling IEnumerator<T>.MoveNext is calling SkipWhileIterator again, when it's not actually.

I get that it can help in some situations. But this is why it seems strange to me. If others are ok with the change, fine, but we should fully understand the ramifications.

@benaadams
Copy link
Member Author

benaadams commented Oct 23, 2017

Neither does List`1.Enumerator.MoveNext.

Not sure what you mean?

Using the full exceptions (with line numbers):

at System.Collections.Generic.List`1.Enumerator.MoveNextRare() in 
 C:\GitHub\coreclr\src\mscorlib\shared\System\Collections\Generic\List.cs:line 1209
at System.Collections.Generic.List`1.Enumerator.MoveNext() in 
 C:\GitHub\coreclr\src\mscorlib\shared\System\Collections\Generic\List.cs:line 1202

Refers to source line 1209 in System.Collections.Generic.List<T>.Enumerator.MoveNextRare() which is a 1:1 mapping with the C# source?

Or do you mean the odd formatting of generics?

at System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)
 in C:\GitHub\corefx\src\System.Linq\src\System\Linq\Skip.cs:line 107

Is referring to source line 107 in SkipWhileIterator<TSource>(IEnumerable<TSource> source, Func<TSource, int, bool> predicate) where it evaluates the predicate, which throws the exception; again a 1:1 mapping with the C# source (other than the odd formatting of the generic types).

So this transformation is both effectively lying

Only is so much as System.Collections.Generic.List`1.Enumerator.MoveNextRare() is also lying because its not instead using the Jit's compiler output of

00007FF90001050E E8 2D ED B5 FF       call        00007FF8FFB6F240

VS also lies to you in the same way as its generally more productive.

I think I'm missing what you mean?

If you are not trying to work out a compiler bug (and you can still do this with the StackFrames); why would you prefer the C# compiler's output; to the C# compiler's input?

The later you just look at the source; the former you need to crack open ildasm or similar to even find the method. (Though if you have been programming .NET for a while you might be used to guessing the right method even without line numbers)

@stephentoub
Copy link
Member

stephentoub commented Oct 23, 2017

Not sure what you mean?

I simply meant it's not in the user's Program.cs file. In one case it's compiler-transformed, in the other it's using a 3rd party library from the user's code... in either case, it's not in the user's source.

I think I'm missing what you mean?

Given an iterator:

public IEnumerable<int> FooAsync()
{
    yield return 1;
    throw new Exception();
}

when I call:

IEnumerable<int> enumerable = FooAsync();

no exception will be thrown, because the Exception isn't coming from the synchronous call to FooAsync. It's only when I then do:

IEnumerator<int> enumerator = enumerable.GetEnumerator();
enumerator.MoveNext();
enumerator.MoveNext();

that the exception will be thrown. So I'm calling MoveNext and the exception is coming from MoveNext. I'm not again calling FooAsync(), yet that's what the call stack would show.

@benaadams
Copy link
Member Author

In one case it's compiler-transformed, in the other it's using a 3rd party library from the user's code...

Maybe poor language choice I'm referring to the cs files as the "user's code" whether its their source, 3rd party or framework - e.g. its something you can directly look at; source step into the non-compiled files etc

when I then do: e.GetEnumerator().MoveNext();

Hmm... you may have me there...

Is async ok? No one (other than you 😉); is manually calling .MoveNext() on an AsyncStateMachine?

@aelij
Copy link

aelij commented Oct 23, 2017

I agree with @stephentoub it is a bit confusing. FWIW, the VS debugger does display it like so (removes MoveNext).

The difference between async and an iterator is that an async method starts executing immediately when called, so it makes sense to hide the generated code there.

@benaadams
Copy link
Member Author

FWIW, the VS debugger does display it like so (removes MoveNext).

It is the method where exception happens in the source file; so if you were trying to follow it through its the method you should look at - but yes I can see the disconnect with IEnumerable, if you call .MoveNext() manually.

Question though; does putting <FooAsync>d__1.MoveNext() in the stack trace add significant value over FooAsync()?

In your example where you immediately throw an exception

public IEnumerable<int> FooAsync()
{
    throw new Exception();
}

It cannot throw an exception (short of C# compiler bug) so FooAsync() will never appear in the stack trace; so it doesn't cause ambiguity doing the rename?

Type dt = declaringType.DeclaringType;
if (dt != null)
{
var methods = dt.GetMembers(BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.Instance);
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think dt.DeclaredMethods could be slightly cheaper here (don't need non-method members nor methods declared on base types).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is an extension on TypeInfo rather than Type also IEnumerable rather than array. Will add BindingFlags.DeclaredOnly

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And change to GetMethods

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@benaadams
Copy link
Member Author

e.g. for the Linq example there are two overloads

System.Linq.Enumerable.<SkipWhileIterator>d__177`1.MoveNext()
System.Linq.Enumerable.<SkipWhileIterator>d__179`1.MoveNext()

Whereas with this PR they would show as

System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`2 predicate)
System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)

@stephentoub
Copy link
Member

stephentoub commented Oct 23, 2017

This may not sit well with others, but what about showing both methods, e.g. rendering it as something like:
System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable'1 source, Func'2 predicate)+MoveNext()
?

@benaadams
Copy link
Member Author

what about showing both methods

Seems a fair comprimise

@benaadams
Copy link
Member Author

Output with that change

System.Exception: ...
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at Program.FirstException(Int32 value, Int32 index)
   at Program.<>c.<LinqIteration>b__4_0(Int32 x, Int32 i)
   at System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)+MoveNext()
   at System.Collections.Generic.LargeArrayBuilder`1.AddRange(IEnumerable`1 items)
   at System.Collections.Generic.EnumerableHelpers.ToArray[T](IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at Program.LinqIteration(Int32 count) 
   at Program.NonAsyncValueTask[TName](Int32 count, TName name)
   at Program.ValueTaskAsync(String name)+MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Program.TaskTAsync(Int32 count)+MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Program.MethodAsync(Int32 count)+MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Program.ConfiguredAsync(Int32 count)+MoveNext()

@benaadams
Copy link
Member Author

benaadams commented Oct 23, 2017

@stephentoub so since .... redacted ...

@stephentoub
Copy link
Member

@benaadams, I'd suggest that you limit PRs to a single purpose. There's a tendency here to push for additional changes that then slow the progress of the original PR.

@benaadams benaadams force-pushed the resolve-iterators-and-async branch from e9b81d8 to b84a0cd Compare October 23, 2017 17:19
@benaadams
Copy link
Member Author

benaadams commented Oct 23, 2017

K, not included that change

@stephentoub
Copy link
Member

K, not included that change

Thanks. Let's work on getting this change through, and if folks agree on it, then your subsequent one-line change can be debated on its own merits without tying it to debate on this one.

@benaadams benaadams force-pushed the resolve-iterators-and-async branch from b84a0cd to 5c64d20 Compare October 24, 2017 07:35
@benaadams benaadams changed the title Resolve iterators and async methods Resolve iterators and async methods in stacktrace Oct 24, 2017
@benaadams
Copy link
Member Author

Updated summary and squashed

return !(mb.IsDefined(typeof(StackTraceHiddenAttribute)) || (mb.DeclaringType?.IsDefined(typeof(StackTraceHiddenAttribute)) ?? false));
}

private static bool TryResolveStateMachineMethod(ref MethodBase mb, ref Type declaringType)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't find anything particularly wrong with it, but may I suggest inverting the if statement to reduce the nesting? I think it will help readability, but I would like to hear your option.

private static bool TryResolveStateMachineMethod(ref MethodBase mb, ref Type declaringType)
{
    Debug.Assert(mb != null);
    Debug.Assert(declaringType != null);

    Type dt = declaringType.DeclaringType;
    if (dt == null) 
        return false;

    var methods = dt.GetMethods(BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.Instance | BindingFlags.DeclaredOnly);
    if(methods == null) 
        return false;

    foreach (var method in methods)
    {
        var asma = method.GetCustomAttribute<StateMachineAttribute>();
        if (asma != null && asma.StateMachineType == declaringType && method is MethodBase matched)
        {
            mb = matched;
            declaringType = matched.DeclaringType;
            return true;
        }
    }

    return false;
 }

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reduced

@benaadams benaadams force-pushed the resolve-iterators-and-async branch from 3f45055 to e9a7ee9 Compare January 18, 2018 12:54
@benaadams
Copy link
Member Author

benaadams commented Jan 18, 2018

Rebased to fix merge clash with "Remove Edi boundary for async" #15781

For async

Pre

System.Exception: Exception of type 'System.Exception' was thrown.
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<RecursiveAsync>d__2.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.<MethodAsync>d__1.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 22
   at asyncexceptions.Program.<Main>d__0.MoveNext() in C:\Work\Things\asyncexceptions\Program.cs:line 12

Post

System.Exception: Exception of type 'System.Exception' was thrown.
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.RecursiveAsync(Int32 count) in C:\Work\Things\asyncexceptions\Program.cs:line 32
   at asyncexceptions.Program.MethodAsync() in C:\Work\Things\asyncexceptions\Program.cs:line 22
   at asyncexceptions.Program.Main(String[] args) in C:\Work\Things\asyncexceptions\Program.cs:line 12

@benaadams
Copy link
Member Author

For iterators

Pre

System.Exception: Exception of type 'System.Exception' was thrown.
   at iteratorexceptions.Program.<Range>d__1.MoveNext() in C:\Work\Things\iteratorexceptions\Program.cs:line 35
   at iteratorexceptions.Program.<Range>d__1.MoveNext() in C:\Work\Things\iteratorexceptions\Program.cs:line 35
   at iteratorexceptions.Program.Main(String[] args) in C:\Work\Things\iteratorexceptions\Program.cs:line 12

Post

System.Exception: Exception of type 'System.Exception' was thrown.
   at iteratorexceptions.Program.Range(Int32 start, Int32 end)+MoveNext() in C:\Work\Things\iteratorexceptions\Program.cs:line 37
   at iteratorexceptions.Program.Range(Int32 start, Int32 end)+MoveNext() in C:\Work\Things\iteratorexceptions\Program.cs:line 35
   at iteratorexceptions.Program.Main(String[] args) in C:\Work\Things\iteratorexceptions\Program.cs:line 12

Code

Details ```csharp class Program { static void Main(string[] args) { try { foreach (var i in Range(0, 5)) { Console.WriteLine(i); } } catch (Exception e) { Console.WriteLine(e); } }
static IEnumerable<int> Range(int start, int end)
{
    for (var i = start; i < end; i++)
    {
        yield return i;
    }

    if (start == end)
    {
        throw new Exception();
    }

    foreach(var i in Range(end, end))
    {
        yield return i;
    }
}

}

</details>

@danmoseley danmoseley requested a review from VSadov January 18, 2018 16:52
@danmoseley
Copy link
Member

@tmat @noahfalk any other feedback?

}
catch
{
// Linq.Expression compiled functions can throw when checking attributes
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does it throw? Is that a bug?

Copy link
Member Author

@benaadams benaadams Jan 18, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't need this; dynamic expressions have no declaring type so it wouldn't get here; and the other issues (benaadams/Ben.Demystifier#31, benaadams/Ben.Demystifier#20) are full framework bugs.

@benaadams benaadams force-pushed the resolve-iterators-and-async branch from 20618a1 to 1d83cdd Compare January 20, 2018 17:00
@benaadams
Copy link
Member Author

@dotnet-bot test Windows_NT x64 Checked corefx_baseline
@dotnet-bot test Ubuntu x64 Checked corefx_baseline

@benaadams
Copy link
Member Author

benaadams commented Jan 23, 2018

Tizen https://github.com/dotnet/coreclr/issues/15914

Failed "Ubuntu arm Cross Debug Innerloop Build" not a CI test anymore? #15959

@noahfalk
Copy link
Member

no more feedback, I'm happy 👍

@karelz
Copy link
Member

karelz commented Jan 25, 2018

@tmat is it ready for merge from your point of view?
@noahfalk can you please mark it Approved? (easier to track ;))

@tmat
Copy link
Member

tmat commented Jan 25, 2018

👍

@karelz I don't see anything on the PR that would allow me to mark Approve.

@karelz
Copy link
Member

karelz commented Jan 25, 2018

Thanks @tmat -- on the top - "Files Changed" - right side top "Review changes" - "Approve" option.

@karelz
Copy link
Member

karelz commented Jan 25, 2018

@dotnet-bot test CentOS7.1 x64 Release Innerloop Build and Test
@dotnet-bot test Ubuntu arm Cross Debug Innerloop Build

@benaadams
Copy link
Member Author

Ubuntu arm Cross Debug Innerloop Build doesn't exist anymore, so can't be retested

@karelz
Copy link
Member

karelz commented Jan 25, 2018

CentOS7.1 and Tizen armel legs are failing all over other PRs as well, so we are ready for merge I guess :)

@karelz karelz merged commit 8dfd31f into dotnet:master Jan 25, 2018
@tmat
Copy link
Member

tmat commented Jan 25, 2018

@karelz Oh. OK. see it now. That's not very discoverable :(

@benaadams benaadams deleted the resolve-iterators-and-async branch January 25, 2018 18:45
@noahfalk
Copy link
Member

@benaadams - thanks for all your work on this, I know it was a bit of slog but its a very nice improvement for .NET!

swgillespie pushed a commit to swgillespie/coreclr that referenced this pull request Jan 26, 2018
Allows a developer to determine *correct* overload called for *async* and *iterators*, from a stacktrace.

Matches the compiler generated containing `Type` to the source method using: 
`method.DeclaringType == StateMachineAttribute.StateMachineType` attribute to allow the stack trace to resolve the mangled method name to the correct overload.  Also appends the statemachine method name with `+` for iterators.

Resolves: dotnet/corefx#24627
@benaadams
Copy link
Member Author

netfx-port-consider?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Make stack traces readable