Improve async stack traces #2741
Comments
|
@Pilchie Do you know how such nice stack traces for async C# code are implemented? Is it open sourced? |
|
@vasily-kirichenko that's the old one ^^ member __.Bind(f : Cont<'T>, g : 'T -> Cont<'S>,
[<CallerMemberName>]?callerName : string,
[<CallerFilePath>]?callerFilePath : string,
[<CallerLineNumber>]?callerLineNumber : int) : Cont<'S> =
fun sc ec ->
let sc' (t : 'T) =
match (try Ok(g t) with e -> Error e) with
| Ok g -> g sc ec
| Error e -> ec (SymbolicException.capture e)
let ec' (se : SymbolicException) =
let stackMsg =
sprintf " at %s in %s:line %d"
callerName.Value
callerFilePath.Value
callerLineNumber.Value
ec (SymbolicException.append stackMsg se)
f sc' ec'member __.ReturnFrom(f : Cont<'T>,
[<CallerMemberName>]?callerName : string,
[<CallerFilePath>]?callerFilePath : string,
[<CallerLineNumber>]?callerLineNumber : int) : Cont<'T> =
fun sc ec ->
let ec' (se : SymbolicException) =
let stackMsg =
sprintf " at %s in %s:line %d"
callerName.Value
callerFilePath.Value
callerLineNumber.Value
ec (SymbolicException.append stackMsg se)
f sc ec'let rec odd (n : int) =
cont { if n = 0 then return false
else return! even (n - 1) }
and even (n : int) =
cont { if n = 0 then return failwith "bug!"
else return! odd (n - 1) }
odd 5 |> Cont.runcc: @eiriktsarpalis |
|
@dsyme is it possible to use this ^^^ approach right in FSharp.Core to improve async stack traces? |
|
@vasily-kirichenko I'm not sure - I haven't looked closely, particualrly about whether it would be breaking change Erik did some important work in improving things but it looks like we need to do more. Marking more FSharp.Core things with relevant "do not show this in the debugger" attributes may bee a huge help |
|
@dsyme @vasily-kirichenko From a production point of view, I think that the value offered by such an addition far outweighs any backward compatibility concerns. |
|
+1000 for the last @eiriktsarpalis message. It's really terrible to find meaningless stack trace in a log file. Do I understand correctly that all we need is just apply Eirik's approach to Async CE? |
|
I think this is a very important feature to have. |
No idea, but @tmat, @cston, or @KevinH-MS might. |
|
It's implemented in the debugger. Not open sourced. |
|
I think one big difference is that F# computation expressions use an external state machine (the CE builder), and C# async / await compiles down to a specialized state machine. So in the C# case it is "easy" to just generate the correct sequence points in the pdb, to point back to the correct source. In the F# case, all frames are from the external state machine, not from the actual expression. This is how it looks when debugging the following code with dnSpy, which does NOT have the special Visual Studio async extension: Notice how, even though it does show a little bit of garbage, you get a 1:1 mapping of callstack to source.
This is in constrast to the F# callstack, where there are no frames for async1/async2: C#: class Program
{
public static async Task Async1()
{
await Async2();
}
public static async Task Async2()
{
await Async3();
}
public static async Task Async3()
{
await Task.Delay(1000);
}
static void Main(string[] args)
{
Async1().Wait();
}
}F#: let async3() = async {
return 1
}
let async2() = async {
return! async3()
}
let async1() = async {
return! async2()
}
[<EntryPoint>]
let main argv =
printfn "%i" (async3() |> Async.RunSynchronously)
0 // return an integer exit code |
cartermp
added
Area-Compiler
Area-Library
Well, FSharp.Core has to be binary backwards-compatible, that's the bottom line. If the change can be made with that (and no performance loss for retail code) then I'd imagine we'd go for it. PR anyone? |
|
Not today I'm afraid. @cloudRoutine go for it if you have time today. |
|
FWIW, the lack of async stack traces was a huge problem for my team, and this is a simplified version of the hack that we are currently using: [<AutoOpen>]
module Async =
type AsyncWithStackTraceBuilder() =
member __.Zero() = async.Zero()
member __.Return t = async.Return t
member inline __.ReturnFrom a =
async {
try
return! async.ReturnFrom a
with e ->
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Capture(e).Throw()
return raise <| Exception() // this line is unreachable as the prior line throws the exception
}
member inline __.Bind a =
async {
try
return! async.Bind a
with e ->
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Capture(e).Throw()
return raise <| Exception() // this line is unreachable as the prior line throws the exception
}
member __.Combine(u, t) = async.Combine(u, t)
member __.Delay f = async.Delay f
member __.For(s, body) = async.For(s, body)
member __.While(guard, computation) = async.While(guard, computation)
member __.Using(resource, binder) = async.Using(resource, binder)
member __.TryWith(a, handler) = async.TryWith(a, handler)
member __.TryFinally(a, compensation) = async.TryFinally(a, compensation)
let async = AsyncWithStackTraceBuilder()
|
|
@dsyme I think binary compat can be preserved. The main issue is that I don't know of a good way to append lines to the stacktrace without resorting to reflection. I have been nagging at the coreclr team to add this functionality to ExceptionDispatchInfo. |
|
An app crashes on start. This is in the console: Question for $1M: what code is called it? Ideas? No? I'm gonna rewrite all async code in C# for this reason. |
|
@eiriktsarpalis Didn't the ExcceptionDispatchInnfo work on FSharp.Core 4.4.1.0 (?) improve these stack traces for exceptions? Is this a case we missed, or was that work never going to improve this particular stack trace? Thanks |
|
@vasily-kirichenko Does applying this techniqe improve things for this example? |
|
@dsyme AFAIK ExceptionDispatchInfo is useful for preserving existing stacktraces in threaded exceptions, however it does not provide functionality for appending new lines at the builder level. |
|
@dsyme I cannot find the code that raises that exception. I failed replacing async CE with that custom CE globally. |
|
@vasily-kirichenko Just to say I've been getting plenty of difficult stack traces too - both from "async" and "Cancellable". And I'm getting very motivated to do something about it. Here's an example. It's not easy in general, and I suspect even harder in the case you show because the async code is presumably in a user library |
|
@vasily-kirichenko Not that it solves the actual problem here with the async stack traces, but to help with diagnosis: have you tried adding an event handler to the |
|
@jack-pappas Thanks. I tried to log exceptions in |
|
@dsyme What should be done concretely to improve the situation? It's #1 problem for me for now. Just today an app is crashing on production with this trace and I have absolutely no idea what code is actually the problem (except it's a |
|
@eiriktsarpalis as @dsyme seems to be busy doing some other work, could you please help me with progress on this? Am I right I should go straight to Would it work on .NET Core? |
|
@vasily-kirichenko I've been mulling over what might allow us to make progress on non-exceptional stack traces in F# computation expressions. The vague idea I have is best first explained for a simpler CE, say the The thought I have is roughly this
This might involve adding a new primitive The code for the closure generated for the let f () = option { .... } Now, this would still give a stack trace that included a method name that indicated a "Delay" closure - but at least double clicking on the stack frame would go to the right source location where the I'm not at all sure this idea works out in practice, but it gives me the feeling that it may handle the "staged" construct-then-execute structures that are so common in functional programming. It's kind of like a fully static equivalent to the dynamically-augment-the-exception-stack-trace-with-better-static-information used by @eiriktsarpalis above. That trick can't be used in the non-exceptional case because it is too expensive - it's only once the exception has happened that we can afford to pay the static price. So I'm looking for a static way to push the information into the code generation process. While I can imagine this working for cleanly re-implemented CE builders, it may be much trickier to apply to Async - and may perhaps require the generation of too many closures on the callside. And it may not prevent the bad loss of causality information in trampolining and other fundamental situations. For example, looking at your stacktrace above, I think this would only improve this call frame: and perhaps not even that. However perhaps this case of yours would be better improved by the exception-stack dynamic augmentation technique. Vague thoughts - sorry - but I'm trying to think through better statically-generated debugging information for delayed CEs (and even more general forms of delayed computations) in general, not just async. |
|
Hugs
Don Syme <[email protected]> schrieb am Mi., 9. Mai 2018, 16:12:
… @vasily-kirichenko <https://github.com/vasily-kirichenko> I'm going to
work on this a bit today.
Re this:
OK, I have an exception and have absolutely no idea how to find the line
of code that raises it
If you have a specific micro example like the one above
<#2741 (comment)>
then please include it here. I mean something really simple using
System.Diagnostics.StackTrace to grab the crappy stack.
I'll try some obvious things like stack traces in with and finally blocks.
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#2741 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/AADgNEyuW684cJwVq7b8z43i6xYQxtTaks5twvljgaJpZM4Mus7A>
.
|
|
@dsyme I'll try to make one, however, that stack trace was from several levels of asyncs with an async call to SqlClient type provider. @dsyme BTW, I have a strange problem testing your PR. I launch an exp VS instance (Ctrl+F5) and it freezes forever after typing a couple of characters. It reproduces easily and always. May it be caused by changes in asyncs? |
|
@dsyme It turns out that my case is more complicated: we use open System
type AsyncResultBuilder () =
member __.Return value : Async<Result<'T, 'Error>> =
Ok value
|> async.Return
member __.ReturnFrom (asyncResult : Async<Result<'T, 'Error>>) =
asyncResult
member inline this.Zero () : Async<Result<unit, 'Error>> =
this.Return ()
member inline this.Delay (generator : unit -> Async<Result<'T, 'Error>>) : Async<Result<'T, 'Error>> =
async.Delay generator
member __.Combine (r1, r2) : Async<Result<'T, 'Error>> =
async {
let! r1' = r1
match r1' with
| Error error ->
return Error error
| Ok () ->
return! r2
}
member __.Bind (value : Async<Result<'T, 'Error>>, binder : 'T -> Async<Result<'U, 'Error>>)
: Async<Result<'U, 'Error>> =
async {
let! value' = value
match value' with
| Error error ->
return Error error
| Ok x ->
return! binder x
}
member inline __.TryWith (computation : Async<Result<'T, 'Error>>, catchHandler : exn -> Async<Result<'T, 'Error>>)
: Async<Result<'T, 'Error>> =
async.TryWith(computation, catchHandler)
member inline __.TryFinally (computation : Async<Result<'T, 'Error>>, compensation : unit -> unit)
: Async<Result<'T, 'Error>> =
async.TryFinally (computation, compensation)
member inline __.Using (resource : ('T :> System.IDisposable), binder : _ -> Async<Result<'U, 'Error>>)
: Async<Result<'U, 'Error>> =
async.Using (resource, binder)
member this.While (guard, body : Async<Result<unit, 'Error>>) : Async<Result<_,_>> =
if guard () then
this.Bind (body, (fun () -> this.While (guard, body)))
else
this.Zero ()
member this.For (sequence : seq<_>, body : 'T -> Async<Result<unit, 'Error>>) =
this.Using (sequence.GetEnumerator (), fun enum ->
this.While (
enum.MoveNext,
this.Delay (fun () ->
body enum.Current)))
let asyncResult = AsyncResultBuilder()
type AsyncResult<'a> = Async<Result<'a, exn>>
let executeReader() =
async {
printfn "%s" (System.Diagnostics.StackTrace(true).ToString())
return Ok [1..10]
}
let exec (count: int) : AsyncResult<int list> =
asyncResult {
return! executeReader()
}
let getTasks() =
asyncResult {
let! records = exec 1
return records.Length
}
let loadTasksAsync() =
asyncResult {
return! getTasks()
}
let createMailboxProcessor() = MailboxProcessor.Start <| fun inbox ->
let rec loop (period: TimeSpan) =
async {
let! msg = inbox.TryReceive(int period.TotalMilliseconds)
let! loadResult = loadTasksAsync()
return! loop (TimeSpan.FromSeconds 10.)
}
loop TimeSpan.Zero
[<EntryPoint>]
let main _ =
let _ = createMailboxProcessor()
Console.ReadLine() |> ignore
0output |
|
With #4867 completed (since 2018), should this be considered resolved and closed? |
|
@abelbraaksma as you wish, but the stack traces as useless as before. |
|
@vasily-kirichenko, it's not my wish, I'm just not certain of the state of the improvements. If they aren't useful still, we should keep this open. |
|
@vasily-kirichenko Task is not so different in this regard Try the following example based on yours. open System
open System.Threading.Tasks
open FSharp.Control.Tasks.Builders
let executeReader() =
task {
do! Task.Yield()
printfn "%s" (System.Diagnostics.StackTrace(true).ToString())
return Ok [1..10]
}
let exec (count: int) =
task {
return! executeReader()
}
let getTasks() =
task {
return! exec 1
}
let loadTasksAsync() =
task {
return! getTasks()
}
[<EntryPoint>]
let main _ =
(task {
let! _ = loadTasksAsync()
return ()
}).Result
Console.ReadLine() |> ignore
0output No trace of exec, getTasks, or loadTasksAsync for Tasks either. However if you remove However the real thing to understand here is the difference between StackTrace and how async exceptions build a stacktrace. Task and as far as I know Async (EDIT: nope it does not at all) both handle exception traces very well and will return the full trace, this comes down to a difference in how the trace is constructed. StackTrace only has the native frames to inspect, for an async function that yields by unwinding its (native) stack completely this will be fairly useless. Regardless of Async or Task allowing continuations to run inline, a yield will destroy the native frames. For exceptions this path is a bit different; to understand it you have to think of the async operations representing a logical stack, one that after yielding never exists in full as a native stack again, but we can reify it with cooperation of the async primitive! I will use Task as an example as I'm a bit hazy on the details for Async but the general concept should transfer well. The difference between Async and Task here is that instead of handing off the result or exception to the continuation like Async does (more or less), Task instead carries any result or exception around as a value on itself, just as it also carries any continuations it is expected to run once completed, it is a mutable thing. So as our Task is done it calls into the continuation we registered earlier as part of yielding — Note, in the case of async await, the continuation always ends up in the same method that was initially responsible for calling the method that produced the Task that it then awaited on, meaning we can use this to reconstruct our lost stack! Exceptions to this are cases like Tasks that were started by one method, stored in a field, and awaited by another, fairly uncommon cases. Though the general rule is important for what comes next. — we are expected to inspect the Task for a result (if you are somewhat familiar this is As our continuation method is itself a Task returning method (virality of async) we are again expected to store any exceptions, we call GetResult on the Task, catch any exception and this cause our current frame to be appended before we store this on the Task. As it is stored it completes the Task causing it to call its own continuation which catches the same exception and adds another frame, stores it, and so on and so forth. As the logical stack is unwound forward through the continuations the trace accumulates all frames, et voilà you have a full trace again. EDIT: This is however distinctly different from how Async works today, I'm looking into ways to get closer to what Task does but it may not be backwards compatible, to be continued. Happy to answer any questions if something is unclear! |
let rec odd (n : int) =
async {
if n = 0 then return false
else
return! even (n - 1)
}
and even (n : int) =
async {
if n = 0 then return failwith "bug!"
else
return! odd (n - 1)
}I think that as long as that simple use case (along with any other relevant cases) is not covered we can consider that we should keep that issue opened. |
|
I've just fixed the last remaining piece of this issue in Ply, meaning code like this: module PlyProgram
open System.Threading.Tasks
open FSharp.Control.Tasks
open System
let findDingbobbleById(x: int) = vtask {
let! x = Task.Yield() // Force the Task to unwind the native stack
return invalidOp "Oh no"
}
let dingbobbleFeature() = vtask {
return! findDingbobbleById 1
}
let dingbobbleRoute() = vtask {
return! dingbobbleFeature()
}
[<EntryPoint>]
let main argv =
try dingbobbleRoute().GetAwaiter().GetResult() |> ignore
with ex -> Console.WriteLine(ex)
0will show a trace like: The changes to do this were fairly small (though Async is probably quite a bit more involved) When I have some spare time I'm going to prototype this approach for Async as well. |
|
I checked some of the cases on this thread asyncResultFor the case here: #2741 (comment), the example CE code needs two changes to activate marginal improvements which at least mean the stack shows causality
member inline __.ReturnFrom (asyncResult : Async<Result<'T, 'Error>>) =
#if DEBUG
async { let! res = asyncResult in return res }
#else
asyncResult
#endifThis then gives marginally improved stack traces that at least show the correct causal trace in terms of lines of code:
However the variables available in stack frames do not show values correctly (because async is fundamentally two-phase execution - create then phase - and the closures generated in the "create" phase lose the debug environment association in the "run" phase). On discussion with @TIHan believe we should add a general feature for CEs authors where they can request that the debug environment be fully captured by within crucial closures that represent the execution stacks. To give an example from the F# compiler: let inline bind f comp1 =
Cancellable (fun ct ->
FSharp.Core.CompilerServices.RuntimeHelpers.InlineDebbugerEnvironment();
match run ct comp1 with
| ValueOrCancelled.Value v1 -> run ct (f v1)
| ValueOrCancelled.Cancelled err1 -> ValueOrCancelled.Cancelled err1)This mechanism would inject fake bindings in debug mode to rebind the full captured environment at the point of final inlining. async add/evenThe case here #2741 (comment) involves tailcalling asyncs. In DEBUG mode the F# async apparatus still takes tailcalls. This can be manually disabled through the same technique: let rec odd (n : int) =
async {
if n = 0 then return false
else
let! res = even (n - 1)
return res
}
and even (n : int) =
async {
if n = 0 then return failwith "bug!"
else
let! res = odd (n - 1)
return res
}
even 100 |> Async.RunSynchronouslygiving a long stack trace showing causality There is as yet no way to disable async tailcalls across your codebase in debug mode without making these intrusive code changes. |
|
Such call stacks are real PITA, I'm trying to push F# more in my company but things like this are really holding me back :-( |
|
@petrkoutnycz one purported benefit of the F# 6 |
|
@cartermp thanks for the tip, I'll give it a shot |
|
Also if for some reason you cannot use F# 6, Ply's stacktraces are also really good for a 'classic' computation expression. |
dsyme
added
Area-Async
|
Here's an interesting compounding factor. Take this program, which attempts to manually improve stack traces by using a helper function to rethrow things: open System
open System.Diagnostics
open System.IO
open System.Runtime.ExceptionServices
module ThirdPartyLibrary =
// Represents some low-level async "primitive" which is used in many many places and which may fail. This type of
// method/function is not typically what you're interested in when examining stacktraces.
// Example: a database query function from a thid-party library
let doWorkAsync crash = ExtraTopLevelOperators.async {
do! Async.Sleep 100
if crash then
raise (IOException("Oh no!"))
}
// Helper function to improve stacktraces. This is the recommended way to augment (not replace) exception stacktraces
// with the caller's stack frame information
// See: https://stackoverflow.com/a/17091351/1231925
let inline rethrowAsync (computation: Async<'a>) = async {
try
return! computation
with e ->
// aids in debugging - you wouldn't include this in a real implementation
let s = StackTrace()
Debug.WriteLine $"StackTrace: %O{s}"
Debug.WriteLine $"Rethrowing: %s{e.StackTrace}"
Debug.WriteLine ""
ExceptionDispatchInfo.Throw e
return Unchecked.defaultof<_> // unreachable, but the compiler doesn't realize that
}
// Application function. We need this to show up in stack traces
let doLoopAsync (n: int) = async {
for n in n .. -1 .. 0 do
printfn "n = %d" n
let crash = n = 6
do! rethrowAsync (ThirdPartyLibrary.doWorkAsync crash)
}
// Higher level application function. We also need this to show up in stacktraces
let mainAsync () = async {
let n = 10
printfn "Starting with iterations: %d" n
do! rethrowAsync (doLoopAsync n)
printfn "Done."
}
[<EntryPoint>]
let main _ =
Async.RunSynchronously (mainAsync ())
0Even with the explicit rethrows, we still somehow lose all the intermediate functions: I'm fairly certain that this worked at some point in the past. Interestingly, if you "transfer" the exception across the // ... same from before
type Async =
static member RunSynchronouslyRethrow (computation, ?timeout, ?cancellationToken) =
let result = Async.RunSynchronously (Async.Catch computation, ?timeout = timeout, ?cancellationToken = cancellationToken)
match result with
| Choice1Of2 x -> x
| Choice2Of2 exn ->
ExceptionDispatchInfo.Throw(exn)
raise (UnreachableException())
[<EntryPoint>]
let main _ =
Async.RunSynchronouslyRethrow (mainAsync ())you get better stack traces again: Does anybody have any clue what the culprit is? Is it the thread pool itself losing the information, or is |
github-project-automation
bot
moved this from Done
to In Progress
in F# Compiler and Tooling
C#
F#
mainandbazz.[email protected](Microsoft.FSharp.Core.Unit unitVar = null)Why not
ConsoleApplication1.exe!Program.bazz@6-1()?Why that
unitandInvokenoise? Is this something we can fix on VFT side?Why it's shown at all? Can we hide it, always?
Looks OK, but too verbose.
The text was updated successfully, but these errors were encountered: