Reduce infrastructure steps in Async Stack Traces#14564
Reduce infrastructure steps in Async Stack Traces#14564benaadams wants to merge 1 commit intodotnet:masterfrom
Conversation
| if (exception != null) | ||
| { | ||
| throw exception; | ||
| } |
There was a problem hiding this comment.
Why did you change this? It's going to make all of the call sites bigger.
There was a problem hiding this comment.
To throw in-place rather than deeper in the stack
There was a problem hiding this comment.
Will output the asm, check the before and after - hopefully its not terrible
There was a problem hiding this comment.
Main change looks to be
G_M53132_IG04:
+ mov rcx, rax
+ call CORINFO_HELP_THROW
...
call TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref)
- nop
+ test rax, rax
+ jne SHORT G_M53132_IG04
| throw GetThrowableException(); | ||
| } | ||
|
|
||
| public Exception GetThrowableException() |
There was a problem hiding this comment.
Eep, was internal - took it out, put it back, typo'd
|
Changes output of this program using System;
using System.Threading.Tasks;
public class Program
{
public static async Task Main(string[] args)
{
try
{
await AsyncMethod(10);
}
catch (Exception e)
{
Console.WriteLine(e);
}
}
private static async Task AsyncMethod(int count)
{
if (count == 0)
{
await Task.Delay(10);
throw new Exception();
}
else
{
await IntermediateAsync(count - 1);
}
}
private static async Task DelayedAsync(int count)
{
await Task.Delay(10);
await AsyncMethod(count - 1);
}
private static async Task IntermediateAsync(int count)
{
await DelayedAsync(count);
}
}From To Somethings not quite right as the line numbers change |
| // Restore the exception dispatch details before allowing this exception to be thrown. | ||
| m_Exception.RestoreExceptionDispatchInfo(this); | ||
| throw m_Exception; | ||
| return m_Exception; |
There was a problem hiding this comment.
Someone more familiar with the innards of exceptions would need to pipe in on whether handing out an exception object like this with the EDI info restored is acceptable.
There was a problem hiding this comment.
It might be the issue changing the line numbers; although they didn't seem completely right in the first place (maybe release mode?)
e.g.
AsyncMethod always at 27 in pre
AsyncMethod at 27, 22, 22, 22... in post
However the source is 23, 27, 27, 27, 27...
| sb.Append(SR.Exception_EndStackTraceFromPreviousThrow); | ||
| } | ||
|
|
||
| entriesInFrame = 0; |
There was a problem hiding this comment.
I don't know how sacrosanct the stack trace format is (maybe @mikem8361 or @noahfalk could comment), and whether anything different on a line could cause problems for tools, but maybe for the entriesInFrame == 1 case, we could append a comment to the line instead, e.g.
at AoA.Gaia.StandaloneTest.Program.<AsyncMethod>d__2.MoveNext() in C:\Work\AoA\test\AoA.Gaia\Standalone.Server\Program.cs:line 41 // from previous location where exception was thrownto avoid losing that information, or something like that,
There was a problem hiding this comment.
My worry is it would break current Stack Trace parsers like https://github.com/atifaziz/StackTraceParser
| return task.IsCompletedSuccessfully ? null : GetNonSuccessException(task); | ||
| } | ||
|
|
||
| /// <summary>Throws an exception to handle a task that completed in a state other than RanToCompletion.</summary> |
There was a problem hiding this comment.
If this method changes to return rather than throw, the comment is wrong.
| @@ -129,7 +135,8 @@ internal static void ValidateEnd(Task task) | |||
| /// the await on the task, and throws an exception if the task did not complete successfully. | |||
There was a problem hiding this comment.
If this method returns rather than throws, the comment is wrong.
|
Doesn't greatly change the call sites Pre Inlines into 06000010 <IntermediateAsync>d__3:MoveNext():this
[0 IL=0016 TR=000063 06000003] [FAILED: unprofitable inline] Program:DelayedAsync(int):ref
[1 IL=0021 TR=000067 06002329] [below ALWAYS_INLINE size] Task:GetAwaiter():struct:this
[2 IL=0001 TR=000140 060044FC] [below ALWAYS_INLINE size] TaskAwaiter:.ctor(ref):this
[3 IL=0029 TR=000077 060044FD] [below ALWAYS_INLINE size] TaskAwaiter:get_IsCompleted():bool:this
[4 IL=0006 TR=000162 060022FE] [below ALWAYS_INLINE size] Task:get_IsCompleted():bool:this
[5 IL=0010 TR=000174 060022FF] [below ALWAYS_INLINE size] Task:IsCompletedMethod(int):bool
[6 IL=0061 TR=000107 060044D6] [below ALWAYS_INLINE size] AsyncTaskMethodBuilder:AwaitUnsafeOnCompleted(byref,byref):this
[0 IL=0008 TR=000195 060044E1] [FAILED: too many il bytes] AsyncTaskMethodBuilder`1:AwaitUnsafeOnCompleted(byref,byref):this
[7 IL=0098 TR=000044 06004500] [below ALWAYS_INLINE size] TaskAwaiter:GetResult():this
[8 IL=0006 TR=000207 06004501] [below ALWAYS_INLINE size] TaskAwaiter:ValidateEnd(ref)
[9 IL=0001 TR=000213 060022E2] [aggressive inline attribute] Task:get_IsWaitNotificationEnabledOrNotRanToCompletion():bool:this
[0 IL=0009 TR=000223 06004502] [FAILED: unprofitable inline] TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref)
[0 IL=0121 TR=000128 060044D9] [FAILED: within catch region] AsyncTaskMethodBuilder:SetException(ref):this
[10 IL=0142 TR=000055 060044D8] [profitable inline] AsyncTaskMethodBuilder:SetResult():this
[11 IL=0011 TR=000255 060044EA] [profitable inline] AsyncTaskMethodBuilder`1:SetResult(ref):this
[0 IL=0026 TR=000277 060044E8] [FAILED: noinline per IL/cached result] AsyncTaskMethodBuilder`1:SetExistingTaskResult(struct):this
Budget: initialTime=504, finalTime=688, initialBudget=5040, currentBudget=5040
Budget: discretionary inline caused a force inline
Budget: initialSize=3505, finalSize=3969
; Assembly listing for method <IntermediateAsync>d__3:MoveNext():this
; Emitting BLENDED_CODE for X64 CPU with AVX
; optimized code
; rbp based frame
; fully interruptible
; Final local variable assignments
;
; V00 this [V00,T00] ( 18, 15 ) byref -> [rbp+0x10] do-not-enreg[H] this
; V01 loc0 [V01,T08] ( 2, 2 ) int -> rcx
; V02 loc1 [V02 ] ( 6, 6 ) struct ( 8) [rbp-0x10] do-not-enreg[XS] must-init addr-exposed ld-addr-op
;* V03 loc2 [V03 ] ( 0, 0 ) ref -> zero-ref class-hnd
;* V04 tmp0 [V04 ] ( 0, 0 ) int -> zero-ref
; V05 tmp1 [V05,T11] ( 2, 0 ) ref -> rdx class-hnd
; V06 tmp2 [V06,T02] ( 3, 6 ) ref -> rax class-hnd
;* V07 tmp3 [V07 ] ( 0, 0 ) struct ( 8) zero-ref
; V08 tmp4 [V08,T04] ( 2, 4 ) ref -> rdx ld-addr-op class-hnd
; V09 tmp5 [V09,T09] ( 2, 2 ) int -> rdx
; V10 tmp6 [V10,T05] ( 2, 4 ) byref -> rcx
; V11 tmp7 [V11,T03] ( 3, 5 ) ref -> rcx ld-addr-op class-hnd
;* V12 tmp8 [V12 ] ( 0, 0 ) ref -> zero-ref ld-addr-op class-hnd
; V13 tmp9 [V13,T06] ( 2, 4 ) byref -> rsi
; V14 tmp10 [V14,T01] ( 4, 8 ) byref -> rsi
; V15 tmp11 [V15,T10] ( 2, 2 ) struct ( 8) [rbp-0x18] do-not-enreg[SF] must-init ld-addr-op
; V16 tmp12 [V16,T07] ( 2, 4 ) ref -> rdx class-hnd
; V17 tmp13 [V17 ] ( 6, 6 ) ref -> [rbp-0x10] do-not-enreg[X] addr-exposed V02.m_task(offs=0x00) P-DEP
;* V18 tmp14 [V18 ] ( 0, 0 ) ref -> zero-ref V07.m_task(offs=0x00) P-INDEP
; V19 OutArgs [V19 ] ( 1, 1 ) lclBlk (32) [rsp+0x00]
; V20 PSPSym [V20 ] ( 1, 1 ) long -> [rbp-0x20] do-not-enreg[X] addr-exposed
;* V21 tmp17 [V21 ] ( 0, 0 ) byref -> zero-ref
;
; Lcl frame size = 56
G_M53132_IG01:
55 push rbp
56 push rsi
4883EC38 sub rsp, 56
488D6C2440 lea rbp, [rsp+40H]
33C0 xor rax, rax
488945F0 mov qword ptr [rbp-10H], rax
488945E8 mov qword ptr [rbp-18H], rax
488965E0 mov qword ptr [rbp-20H], rsp
48894D10 mov bword ptr [rbp+10H], rcx
G_M53132_IG02:
488B4D10 mov rcx, bword ptr [rbp+10H]
8B09 mov ecx, dword ptr [rcx]
G_M53132_IG03:
85C9 test ecx, ecx
745A je SHORT G_M53132_IG04
488B4D10 mov rcx, bword ptr [rbp+10H]
8B4904 mov ecx, dword ptr [rcx+4]
E8E5DAFFFF call Program:DelayedAsync(int):ref
8B10 mov edx, dword ptr [rax]
488945F0 mov gword ptr [rbp-10H], rax
488B55F0 mov rdx, gword ptr [rbp-10H]
8B5234 mov edx, dword ptr [rdx+52]
F7C200006001 test edx, 0x1600000
7559 jne SHORT G_M53132_IG05
488B5510 mov rdx, bword ptr [rbp+10H]
33C9 xor ecx, ecx
890A mov dword ptr [rdx], ecx
488B5510 mov rdx, bword ptr [rbp+10H]
488D4A10 lea rcx, bword ptr [rdx+16]
488B55F0 mov rdx, gword ptr [rbp-10H]
E8CF33A95F call CORINFO_HELP_CHECKED_ASSIGN_REF
488B5510 mov rdx, bword ptr [rbp+10H]
3912 cmp dword ptr [rdx], edx
488B5510 mov rdx, bword ptr [rbp+10H]
488D4A08 lea rcx, bword ptr [rdx+8]
488D55F0 lea rdx, bword ptr [rbp-10H]
4C8B4510 mov r8, bword ptr [rbp+10H]
E82CF5FFFF call AsyncTaskMethodBuilder`1:AwaitUnsafeOnCompleted(byref,byref):this
E993000000 jmp G_M53132_IG08
G_M53132_IG04:
488B4D10 mov rcx, bword ptr [rbp+10H]
488B4910 mov rcx, gword ptr [rcx+16]
48894DF0 mov gword ptr [rbp-10H], rcx
488B4D10 mov rcx, bword ptr [rbp+10H]
33C0 xor rax, rax
48894110 mov qword ptr [rcx+16], rax
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FFFFFFFF mov dword ptr [rcx], -1
G_M53132_IG05:
488B4DF0 mov rcx, gword ptr [rbp-10H]
8B4134 mov eax, dword ptr [rcx+52]
2500000011 and eax, 0x11000000
3D00000001 cmp eax, 0x1000000
7406 je SHORT G_M53132_IG06
E87FE1FFFF call TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref)
90 nop
G_M53132_IG06:
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FEFFFFFF mov dword ptr [rcx], -2
488B4D10 mov rcx, bword ptr [rbp+10H]
3909 cmp dword ptr [rcx], ecx
488B4D10 mov rcx, bword ptr [rbp+10H]
488D7108 lea rsi, bword ptr [rcx+8]
48B920301514F97F0000 mov rcx, 0x7FF914153020
BA3A050000 mov edx, 0x53A
E8BA4CA95F call CORINFO_HELP_GETSHARED_NONGCSTATIC_BASE
48BA6022957369020000 mov rdx, 0x26973952260
488B12 mov rdx, gword ptr [rdx]
48833E00 cmp gword ptr [rsi], 0
750A jne SHORT G_M53132_IG07
488BCE mov rcx, rsi
E82F33A95F call CORINFO_HELP_CHECKED_ASSIGN_REF
EB11 jmp SHORT G_M53132_IG08
G_M53132_IG07:
C645E800 mov byte ptr [rbp-18H], 0
488BCE mov rcx, rsi
480FBE55E8 movsx rdx, byte ptr [rbp-18H]
E814E7FFFF call AsyncTaskMethodBuilder`1:SetExistingTaskResult(struct):this
G_M53132_IG08:
90 nop
G_M53132_IG09:
488D65F8 lea rsp, [rbp-08H]
5E pop rsi
5D pop rbp
C3 ret
G_M53132_IG10:
55 push rbp
56 push rsi
4883EC28 sub rsp, 40
488B6920 mov rbp, qword ptr [rcx+32]
48896C2420 mov qword ptr [rsp+20H], rbp
488D6D40 lea rbp, [rbp+40H]
G_M53132_IG11:
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FEFFFFFF mov dword ptr [rcx], -2
488B4D10 mov rcx, bword ptr [rbp+10H]
3909 cmp dword ptr [rcx], ecx
488B4D10 mov rcx, bword ptr [rbp+10H]
4883C108 add rcx, 8
E874E1FFFF call AsyncTaskMethodBuilder:SetException(ref):this
488D05C1FFFFFF lea rax, G_M53132_IG08
G_M53132_IG12:
4883C428 add rsp, 40
5E pop rsi
5D pop rbp
C3 ret
; Total bytes of code 346, prolog size 29 for method <IntermediateAsync>d__3:MoveNext():this
; ============================================================Post Inlines into 06000010 <IntermediateAsync>d__3:MoveNext():this
[0 IL=0016 TR=000063 06000003] [FAILED: unprofitable inline] Program:DelayedAsync(int):ref
[1 IL=0021 TR=000067 06002329] [below ALWAYS_INLINE size] Task:GetAwaiter():struct:this
[2 IL=0001 TR=000140 060044FD] [below ALWAYS_INLINE size] TaskAwaiter:.ctor(ref):this
[3 IL=0029 TR=000077 060044FE] [below ALWAYS_INLINE size] TaskAwaiter:get_IsCompleted():bool:this
[4 IL=0006 TR=000162 060022FE] [below ALWAYS_INLINE size] Task:get_IsCompleted():bool:this
[5 IL=0010 TR=000174 060022FF] [below ALWAYS_INLINE size] Task:IsCompletedMethod(int):bool
[6 IL=0061 TR=000107 060044D7] [below ALWAYS_INLINE size] AsyncTaskMethodBuilder:AwaitUnsafeOnCompleted(byref,byref):this
[0 IL=0008 TR=000195 060044E2] [FAILED: too many il bytes] AsyncTaskMethodBuilder`1:AwaitUnsafeOnCompleted(byref,byref):this
[7 IL=0098 TR=000044 06004501] [below ALWAYS_INLINE size] TaskAwaiter:GetResult():this
[8 IL=0006 TR=000207 06004502] [aggressive inline attribute] TaskAwaiter:ValidateEnd(ref)
[9 IL=0001 TR=000213 060022E2] [aggressive inline attribute] Task:get_IsWaitNotificationEnabledOrNotRanToCompletion():bool:this
[0 IL=0009 TR=000223 06004503] [FAILED: noinline per IL/cached result] TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref):ref
[0 IL=0121 TR=000128 060044DA] [FAILED: within catch region] AsyncTaskMethodBuilder:SetException(ref):this
[10 IL=0142 TR=000055 060044D9] [profitable inline] AsyncTaskMethodBuilder:SetResult():this
[11 IL=0011 TR=000271 060044EB] [profitable inline] AsyncTaskMethodBuilder`1:SetResult(ref):this
[0 IL=0026 TR=000293 060044E9] [FAILED: noinline per IL/cached result] AsyncTaskMethodBuilder`1:SetExistingTaskResult(struct):this
Budget: initialTime=504, finalTime=700, initialBudget=5040, currentBudget=5040
Budget: discretionary inline caused a force inline
Budget: initialSize=3505, finalSize=3969
; Assembly listing for method <IntermediateAsync>d__3:MoveNext():this
; Emitting BLENDED_CODE for X64 CPU with AVX
; optimized code
; rbp based frame
; fully interruptible
; Final local variable assignments
;
; V00 this [V00,T00] ( 18, 15 ) byref -> [rbp+0x10] do-not-enreg[H] this
; V01 loc0 [V01,T08] ( 2, 2 ) int -> rcx
; V02 loc1 [V02 ] ( 6, 6 ) struct ( 8) [rbp-0x10] do-not-enreg[XS] must-init addr-exposed ld-addr-op
;* V03 loc2 [V03 ] ( 0, 0 ) ref -> zero-ref class-hnd
;* V04 tmp0 [V04 ] ( 0, 0 ) int -> zero-ref
; V05 tmp1 [V05,T12] ( 2, 0 ) ref -> rdx class-hnd
; V06 tmp2 [V06,T02] ( 3, 6 ) ref -> rax class-hnd
;* V07 tmp3 [V07 ] ( 0, 0 ) struct ( 8) zero-ref
; V08 tmp4 [V08,T04] ( 2, 4 ) ref -> rdx ld-addr-op class-hnd
; V09 tmp5 [V09,T09] ( 2, 2 ) int -> rdx
; V10 tmp6 [V10,T05] ( 2, 4 ) byref -> rcx
; V11 tmp7 [V11,T03] ( 3, 5 ) ref -> rcx ld-addr-op class-hnd
; V12 tmp8 [V12,T11] ( 3, 1 ) ref -> rax class-hnd
;* V13 tmp9 [V13 ] ( 0, 0 ) ref -> zero-ref ld-addr-op class-hnd
; V14 tmp10 [V14,T06] ( 2, 4 ) byref -> rsi
; V15 tmp11 [V15,T01] ( 4, 8 ) byref -> rsi
; V16 tmp12 [V16,T10] ( 2, 2 ) struct ( 8) [rbp-0x18] do-not-enreg[SF] must-init ld-addr-op
; V17 tmp13 [V17,T07] ( 2, 4 ) ref -> rdx class-hnd
; V18 tmp14 [V18 ] ( 6, 6 ) ref -> [rbp-0x10] do-not-enreg[X] addr-exposed V02.m_task(offs=0x00) P-DEP
;* V19 tmp15 [V19 ] ( 0, 0 ) ref -> zero-ref V07.m_task(offs=0x00) P-INDEP
; V20 OutArgs [V20 ] ( 1, 1 ) lclBlk (32) [rsp+0x00]
; V21 PSPSym [V21 ] ( 1, 1 ) long -> [rbp-0x20] do-not-enreg[X] addr-exposed
;* V22 tmp18 [V22 ] ( 0, 0 ) byref -> zero-ref
;
; Lcl frame size = 56
G_M53132_IG01:
55 push rbp
56 push rsi
4883EC38 sub rsp, 56
488D6C2440 lea rbp, [rsp+40H]
33C0 xor rax, rax
488945F0 mov qword ptr [rbp-10H], rax
488945E8 mov qword ptr [rbp-18H], rax
488965E0 mov qword ptr [rbp-20H], rsp
48894D10 mov bword ptr [rbp+10H], rcx
G_M53132_IG02:
488B4D10 mov rcx, bword ptr [rbp+10H]
8B09 mov ecx, dword ptr [rcx]
G_M53132_IG03:
85C9 test ecx, ecx
7462 je SHORT G_M53132_IG05
488B4D10 mov rcx, bword ptr [rbp+10H]
8B4904 mov ecx, dword ptr [rcx+4]
E865DCFFFF call Program:DelayedAsync(int):ref
8B10 mov edx, dword ptr [rax]
488945F0 mov gword ptr [rbp-10H], rax
488B55F0 mov rdx, gword ptr [rbp-10H]
8B5234 mov edx, dword ptr [rdx+52]
F7C200006001 test edx, 0x1600000
7561 jne SHORT G_M53132_IG06
488B5510 mov rdx, bword ptr [rbp+10H]
33C9 xor ecx, ecx
890A mov dword ptr [rdx], ecx
488B5510 mov rdx, bword ptr [rbp+10H]
488D4A10 lea rcx, bword ptr [rdx+16]
488B55F0 mov rdx, gword ptr [rbp-10H]
E84F35A65F call CORINFO_HELP_CHECKED_ASSIGN_REF
488B5510 mov rdx, bword ptr [rbp+10H]
3912 cmp dword ptr [rdx], edx
488B5510 mov rdx, bword ptr [rbp+10H]
488D4A08 lea rcx, bword ptr [rdx+8]
488D55F0 lea rdx, bword ptr [rbp-10H]
4C8B4510 mov r8, bword ptr [rbp+10H]
E8FCF4FFFF call AsyncTaskMethodBuilder`1:AwaitUnsafeOnCompleted(byref,byref):this
E99F000000 jmp G_M53132_IG09
G_M53132_IG04:
488BC8 mov rcx, rax
E8B732A15F call CORINFO_HELP_THROW
G_M53132_IG05:
488B4D10 mov rcx, bword ptr [rbp+10H]
488B4910 mov rcx, gword ptr [rcx+16]
48894DF0 mov gword ptr [rbp-10H], rcx
488B4D10 mov rcx, bword ptr [rbp+10H]
33C0 xor rax, rax
48894110 mov qword ptr [rcx+16], rax
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FFFFFFFF mov dword ptr [rcx], -1
G_M53132_IG06:
488B4DF0 mov rcx, gword ptr [rbp-10H]
8B4134 mov eax, dword ptr [rcx+52]
2500000011 and eax, 0x11000000
3D00000001 cmp eax, 0x1000000
740A je SHORT G_M53132_IG07
E8F7E2FFFF call TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref):ref
4885C0 test rax, rax
75BB jne SHORT G_M53132_IG04
G_M53132_IG07:
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FEFFFFFF mov dword ptr [rcx], -2
488B4D10 mov rcx, bword ptr [rbp+10H]
3909 cmp dword ptr [rcx], ecx
488B4D10 mov rcx, bword ptr [rbp+10H]
488D7108 lea rsi, bword ptr [rcx+8]
48B920304E1AF97F0000 mov rcx, 0x7FF91A4E3020
BA3A050000 mov edx, 0x53A
E82E4EA65F call CORINFO_HELP_GETSHARED_NONGCSTATIC_BASE
48BA602299AC66010000 mov rdx, 0x166AC992260
488B12 mov rdx, gword ptr [rdx]
48833E00 cmp gword ptr [rsi], 0
750A jne SHORT G_M53132_IG08
488BCE mov rcx, rsi
E8A334A65F call CORINFO_HELP_CHECKED_ASSIGN_REF
EB11 jmp SHORT G_M53132_IG09
G_M53132_IG08:
C645E800 mov byte ptr [rbp-18H], 0
488BCE mov rcx, rsi
480FBE55E8 movsx rdx, byte ptr [rbp-18H]
E888E8FFFF call AsyncTaskMethodBuilder`1:SetExistingTaskResult(struct):this
G_M53132_IG09:
90 nop
G_M53132_IG10:
488D65F8 lea rsp, [rbp-08H]
5E pop rsi
5D pop rbp
C3 ret
G_M53132_IG11:
55 push rbp
56 push rsi
4883EC28 sub rsp, 40
488B6920 mov rbp, qword ptr [rcx+32]
48896C2420 mov qword ptr [rsp+20H], rbp
488D6D40 lea rbp, [rbp+40H]
G_M53132_IG12:
488B4D10 mov rcx, bword ptr [rbp+10H]
C701FEFFFFFF mov dword ptr [rcx], -2
488B4D10 mov rcx, bword ptr [rbp+10H]
3909 cmp dword ptr [rcx], ecx
488B4D10 mov rcx, bword ptr [rbp+10H]
4883C108 add rcx, 8
E8E8E2FFFF call AsyncTaskMethodBuilder:SetException(ref):this
488D05C1FFFFFF lea rax, G_M53132_IG09
G_M53132_IG13:
4883C428 add rsp, 40
5E pop rsi
5D pop rbp
C3 ret
; Total bytes of code 358, prolog size 29 for method <IntermediateAsync>d__3:MoveNext():this
; ============================================================ |
|
Is that "pre" version correct? "[8 IL=0006 TR=000207 06004501] [aggressive inline attribute] TaskAwaiter:ValidateEnd(ref)" suggests that ValidateEnd was marked with MethodImplOptions.AggressiveInlining (or am I misunderstanding?), but it's not in the original code. |
hm... no Actual changes are 346 vs 358 diff here Updated asm, main change looks to be G_M53132_IG04:
+ mov rcx, rax
+ call CORINFO_HELP_THROW
...
call TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref)
- nop
+ test rax, rax
+ jne SHORT G_M53132_IG04 |
|
Still issue with line numbers in pre and post in Debug; though worse with this change Pre Post |
benaadams
changed the title
|
Don't know how to answer/resolve: Issues/Questions
|
|
/cc @pranavkm |
|
I'd propose that rather than changing the execution path we handle this in a similar manner to VS debugger's "Just My Code" feature. The idea is that all code is bucketed as either being interesting to a developer or not interesting to the developer. The distinction can be quite subjective, but for the moment lets assume we define the few helper frames in Task that throw the Exception as not interesting and everything else remains interesting. When printing a stack trace all frames running 'not interesting' code are omitted. Sorry @benaadams I know its a completely different direction than your effort here, but this is why I think it might be a more effective choice:
Thoughts? |
|
@noahfalk I agree this approach is very reasonable. For what it's worth, that's the way we currently post-process stack traces (as strings) already, some pictures in: https://github.com/dotnet/corefx/issues/24627#issuecomment-336327971 I wouldn't object to an API on |
|
These "string fix-up" solutions don't address the state machine leakage problem. I don't have a method called |
|
@mattzink This is somewhat orthogonal problem. The compiler generates mangled names for various metadata entities that implement high-level language features such as lambdas, local functions, state machines, etc. In VS the debugger uses the appropriate language service to format the names of these frames. The language service recognizes the special names and is able to reconstruct the original name used in source code (possibly using extra debugging information stored in the PDB). The problem is that the CLR doesn't have a language service that could do that. It uses method names found in metadata. The same names you see when using System.Reflection. Rather than hard-code language specific compiler generated name recognition in the CLR or CoreFX, it'd be better to have a separate library that formats stack traces that can defer to language specific plug-ins (note that you can have any number of languages involved in a single stack trace). |
|
@noahfalk We already have custom attributes that can be used to mark methods as "not interesting when debugging": |
|
@mattzink An alternative solution to consider could be for the compiler to emit code into the assembly that performs the formatting for compiler generated member names that appear in that assembly. We could establish some convention that would allow the CLR to find a method that implements the formatting and invoke it with the MethodInfo whose name needs to be formatted. I would expect the emitted code be very small thus the extra overhead should be negligible. |
|
I do think it is currently throwing in the wrong place; and the stack trace just reflects this. Diagrammatically this just changes where it throws
This change shouldn't have any significant effect over the hot or cold paths
While that maybe a useful switch - it will have cost; for example reflecting on each method in the stack trace to see if its marked "not interesting". Also what is "not interesting" might be hard to get consensus on. I don't think outputting the above is actually correct as it has nothing to do with the exception; its just working out what the exception was so it can be thrown correctly. The exception resolving functions are not a participant of the exception or trace - nothing wrong has happened in or before them (they are not in the direct path) - they are orthogonal to it - so having the throw where it currently is doesn't add value. It currently throws as soon as it finds out what the exception is - rather than returning to where the exception should be thrown and throwing there. So I think the correct output would be: I also removed the lines as they are noisy (is 50% of the trace high value?), but can put them back |
|
Please improve this. No one needs to see this text repeated half a dozen times in the stacktrace: |
|
Bonus points if you can clean up the to |
That's a different beast; similar to other suggestions like "not interesting" in this thread or an api on the stack trace i.e. its interpreting or parsing the trace - which I'm explicitly not doing here. It could be a valuable addition; however I'd argue I'm making a bug fix rather than an improvement in this PR 😉 |
|
I'd like to strongly discourage from parsing and interpreting compiler generated names in any way. They are compiler implementation details that can be changed in future compilers. I'm not saying we can't improve the stack formatting but it needs to be done carefully. See my previous comments on this thread: #14564 (comment), #14564 (comment) |
I agree. In my number (4) I alluded to needing other StackTrace changes as well. Handling the state machines was included in that. However I limited the Just My Code suggestion to match the scope of the current issue and acknowledging that partial progress would still probably be appreciated by many folks.
I think that would be a route worthy of investigation at least. However maybe we do that in a separate issue? I was just attempting to describe the JMC-like approach with minimal detail so we could discuss the overall principle.
I may not be understanding your intent accurately, but it sounds like you are claiming the location where the exception is thrown is wrong when evaluated by some metric independent of stack trace behavior. I'm not sure what other metric that would be (performance, code readability, adhering to a particular design pattern, etc.) but if that was the case help me clarify the metric so I can get back on the same page with you.
I agree that outputting these methods in a StackTrace isn't useful to the overwhelming majority of our users, but I disagree that throwing from within the helper method is somehow inherently coded wrong or bad design. I want to let library designers write their code in a way that they feel best captures their intentions or that satisfies other considerations such as code size, good design, performance, maintainability, etc. If it happens that their design needs to throw an exception with certain functions on the stack I'd like to let them do that. So far the only bad effect I see of throwing from a certain location is that it produces a stack trace the community doesn't find useful, and we can attack that problem by changing the way we generate stack traces.
Certainly running extra code will always have a cost, though I suspect in the total costs of throwing + catching exceptions and then formatting the stack trace it may be negligible. In general I'd treat paths that handle exceptions as cold paths which can get much more performance leeway vs. the async-await call which is treated perf critical. To be fair if @stephentoub is OK with the change I'm not opposed to it, but I'm still not convinced this is representative of the long term direction to best solve the problem. |
I'm saying what is doing is incorrect; by some definition of incorrect 😄 When you get a stack trace, its generally expected to be the direct flow out from where its thrown to where its caught. If you catch a non-async exception you expect each step in the trace to be be getting higher in the stack; moving up from caller to caller. However in the current async exceptions it actually gets deeper in the stack: Because the exception is (re)thrown at step However the steps Going deeper into the stack is confusing because steps Looking at as a traditional [MethodImpl(MethodImplOptions.NoInlining)]
static void HandleNonSuccessAndDebuggerNotification(Exception innerException)
=> ThrowForNonSuccess(innerException);
[MethodImpl(MethodImplOptions.NoInlining)]
static void ThrowForNonSuccess(Exception innerException)
{
throw new Exception("", innerException);
}
static void DoThing()
{
try
{
// ...
throw new Exception();
}
catch(Exception ex)
{
// Glue work
HandleNonSuccessAndDebuggerNotification(ex); // rethrowing in here, 2 functions deeper
}
}And the [MethodImpl(MethodImplOptions.NoInlining)]
static Exception HandleNonSuccessAndDebuggerNotification(Exception innerException)
=> ThrowForNonSuccess(innerException);
[MethodImpl(MethodImplOptions.NoInlining)]
static Exception ThrowForNonSuccess(Exception innerException)
{
return new Exception("", innerException);
}
static void DoThing()
{
try
{
// ...
throw new Exception();
}
catch(Exception ex)
{
// Glue work
var wrappedException = HandleNonSuccessAndDebuggerNotification(ex);
throw wrappedException; // continue throw from here, same level
}
}So you are always getting higher in the stack at each level |
|
Mainly its just about the extra lines in the stack trace; I came up with the justification after 😆 But I do also think it makes sense 😄 |
|
Stack traces for example 1 & 2 above Example 1 Example 2 Example 1 exhibiting same stack trace behavior as async exceptions |
|
I agree with @noahfalk - there should be a long term solution to stack trace formatting that supports all sorts of scenarios. My vote is for an API; it would allow users to tailor the format to their own needs, and without having to wait for the framework to catch up on new features (such as async). |
|
Changing to pass the EDI and je SHORT G_M53133_IG06
call TaskAwaiter:HandleNonSuccessAndDebuggerNotification(ref):ref
- nop
+ mov rsi, rax
+ test rsi, rsi
+ je SHORT G_M53133_IG06
+ mov rcx, gword ptr [rsi+8]
+ mov rdx, rsi
+ cmp dword ptr [rcx], ecx
+ call Exception:RestoreExceptionDispatchInfo(ref):this
+ mov rcx, gword ptr [rsi+8]
+ call CORINFO_HELP_THROW
+ int3 Also have to change the Jit to get Is in branch https://github.com/benaadams/coreclr/tree/use-edi (including Jit change) |
|
Using the EDI has better line numbers... :-/ |
|
@benaadams - Thanks for taking the time to write up a nice explanation! I think I follow what you were using as a metric of 'correctness' now. I'll admit other than its impact on the exception stacktrace I'm not convinced following this metric makes code better. I assume you meant:
[to the developer who is looking at the exception stack trace]. As the developer writing the implementation of those code snippets it seems pretty subjective that either version is more confusing or complex than the other. I realized that aside from causing a ruckus on your PR I didn't answer the questions you were originally asking which was not good of me! Apologies. My thoughts on those:
In optimized jitted code (which the framework libraries typically would be) source line mapping is best effort so small deviations aren't surprising. IMO those helper frames are sufficiently disliked that errors in source line mapping remaining are worth it.
Yes in this case, in a general case it depends. Technically you are slightly enlarging the size of a pre-existing race window, but practically I don't see this degree of change making a meaningful difference. The issue EDI is trying to solve is what happens when multiple threads are all allowed to throw the same exception object? In the time in-between when you restore the EDI on the Exception and when you throw it some other thread could restore its EDI on that same Exception which might completely invalidate the callstack. However even EDI.Throw() has the same race, as does the code in any exception handler that attempts inspect the stack trace.
I didn't realize that was part of your change at first, I thought you were only changing the code inside the Task library. That part does concern me and I don't think that you should include it if you do wind up submitting the rest of this PR. I'm not fundamentally opposed to eliminating this indicator of exception rethrow (though that alone at least causes me pause), but doing it based on the number of frames in between rethrows seems particularly likely to have unintended side-effects and feels like a pretty arbitrary heuristic. |
👍 Ok will pass the Exception back as it causes the least distruption to the hot path
Ok, backing this bit out - as it does loose some meaning (that an async fold happened) and the heuristic was a bit arbitrary :) Can look at it separately, and they are easy enough lines to identify as not being code line all starting with There are other items related to stack traces mentioned on this thread - this change shouldn't rule them out or make them more difficult; equaly its not particularly trying to address them So, in summary this PR now should cut an async stack trace of between 66 and 82 lines (depending if 2 or 3 extra entries) to 35 lines; as below: It shouldn't cause any compat issues as the structure is still maintained; as is the async folding From my side I'm happy with PR with these changes |
|
@davkean's example in https://github.com/dotnet/corefx/issues/24627 should be reduced from 56 lines to 28 lines |
|
Final two diagrams to express what I was getting at; as I think they show it better Stack trace current Stack trace PR |
|
@stephentoub - I'm OK with this (though as above I don't think it is indicative of ideal long term direction). If you are as well then Ben can merge. |
|
Exploring an alternative approach |
|
@noahfalk I have something more along the lines you were suggesting; hadn't realized the |
11 participants
Currently the only way to drop something from a stack trace is if it inlines; or if it isn't in the stack. So this change changes the stack when the exception is thrown.
It passes the exceptions back to be thrown at the location, rather than throwing in place (removing from stack)
The exception resolving functions are not a participant of the exception or trace - nothing wrong has happened in or before them (and they are not in the direct path) - they are orthogonal to it - so having the
throwwhere it currently is doesn't add value.Make sure
ValidateEndinlines with the extra exception check (remove by inlining, as now)So outputs
Instead of
Main call site change (extra in async method) looks to be
Issues/Questions
Contributes to https://github.com/dotnet/corefx/issues/24627
Contributes to https://github.com/dotnet/corefx/issues/1370
/cc @joperezr @noahfalk @tmat @davidfowl @davkean @NickCraver