Fsharp: Improve async stack traces

[vasily-kirichenko]

C#

F#

1. The stack trace is completely lost between main and bazz.
2. [email protected](Microsoft.FSharp.Core.Unit unitVar = null)

Why not ConsoleApplication1.exe!Program.bazz@6-1()?
Why that unit and Invoke noise? Is this something we can fix on VFT side?

3.

FSharp.Core.dll!Microsoft.FSharp.Control.AsyncBuilderImpl.callA@841<int, System.__Canon>.Invoke(Microsoft.FSharp.Control.AsyncParams<int> args = {Microsoft.FSharp.Control.AsyncParams<int>})   Unknown
FSharp.Core.dll!<StartupCode$FSharp-Core>.$Control.loop@427-51(Microsoft.FSharp.Control.Trampoline this = {Microsoft.FSharp.Control.Trampoline}, Microsoft.FSharp.Core.FSharpFunc<Microsoft.FSharp.Core.Unit, Microsoft.FSharp.Control.FakeUnitValue> action)   Unknown
FSharp.Core.dll!Microsoft.FSharp.Control.Trampoline.ExecuteAction(Microsoft.FSharp.Core.FSharpFunc<Microsoft.FSharp.Core.Unit, Microsoft.FSharp.Control.FakeUnitValue> firstAction) Unknown

Why it's shown at all? Can we hide it, always?

4.

FSharp.Core.dll!Microsoft.FSharp.Control.CancellationTokenOps.RunSynchronouslyInCurrentThread<int>(System.Threading.CancellationToken token, Microsoft.FSharp.Control.FSharpAsync<int> computation) Unknown
FSharp.Core.dll!Microsoft.FSharp.Control.CancellationTokenOps.RunSynchronously<int>(System.Threading.CancellationToken token, Microsoft.FSharp.Control.FSharpAsync<int> computation, Microsoft.FSharp.Core.FSharpOption<int> timeout)   Unknown
FSharp.Core.dll!Microsoft.FSharp.Control.FSharpAsync.RunSynchronously<int>(Microsoft.FSharp.Control.FSharpAsync<int> computation, Microsoft.FSharp.Core.FSharpOption<int> timeout, Microsoft.FSharp.Core.FSharpOption<System.Threading.CancellationToken> cancellationToken)    Unknown
ConsoleApplication1.exe!Program.main(string[] argv = {string[0]}) Line 23   F#

Looks OK, but too verbose.

[vasily-kirichenko]

https://eiriktsarpalis.wordpress.com/2015/12/27/reconciling-stacktraces-with-computation-expressions/

[vasily-kirichenko]

@Pilchie Do you know how such nice stack traces for async C# code are implemented? Is it open sourced?

[cloudRoutine]

@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'



md5-11e8d45c2a594c692920dc090ab4e11d

System.Exception: bug!
at Program.[email protected](Unit unitVar) in C:\Users\eirik\devel\public\cont\Program.fs:line 119
at Program.sc'@54-1.Invoke(a t) in C:\Users\eirik\devel\public\cont\Program.fs:line 54
at odd in C:\Users\eirik\devel\public\cont\Program.fs:line 114
at even in C:\Users\eirik\devel\public\cont\Program.fs:line 121
at odd in C:\Users\eirik\devel\public\cont\Program.fs:line 114
at even in C:\Users\eirik\devel\public\cont\Program.fs:line 121
at odd in C:\Users\eirik\devel\public\cont\Program.fs:line 114
at Program.ContModule.[email protected](SymbolicException se) in C:\Users\eirik\devel\public\cont\Program.fs:line 102
at Program.ContModule.runT in C:\Users\eirik\devel\public\cont\Program.fs:line 103
at .$Program.main@() in C:\Users\eirik\devel\public\cont\Program.fs:line 106
```
https://eiriktsarpalis.wordpress.com/2016/11/19/reconciling-stacktraces-with-computation-expressions-revisited/

cc: @eiriktsarpalis

[vasily-kirichenko]

@dsyme is it possible to use this ^^^ approach right in FSharp.Core to improve async stack traces?

[dsyme]

@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

[eiriktsarpalis]

@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.

[vasily-kirichenko]

+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?

[cartermp]

I think this is a very important feature to have.

[Pilchie]

@Pilchie Do you know how such nice stack traces for async C# code are implemented? Is it open sourced?

No idea, but @tmat, @cston, or @kevinh-ms might.

[tmat]

It's implemented in the debugger. Not open sourced.

[0x53A]

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#:__

```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#:__

```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

[dsyme]

@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.

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?

[vasily-kirichenko]

Not today I'm afraid. @cloudRoutine go for it if you have time today.

[dhwed]

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()

ExceptionDispatchInfo.Capture requires .NET 4.5, but the result is that the stack traces from async computation expressions end up looking exactly the same as C# async stack traces.

[eiriktsarpalis]

@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.

[vasily-kirichenko]

An app crashes on start. This is in the console:

System.Data.SqlClient.SqlException (0x80131904): Login failed for user '...'.
   at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionStr
ing connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecu
rePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSe
ssionData, DbConnectionPool pool, String accessToken, Boolean applyTransientFaultHandling)
   at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoo
lKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnection
Options userOptions)
   at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection
owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions us
erOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptio
ns userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMult
ipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbCo
nnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSour
ce`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskComplet
ionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal&
connection)
   at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, Db
ConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.Open()
   at <StartupCode$FSharp-Data-SqlClient>[email protected](IEnumerable`1& next) in C:\Users\
dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 84
   at Microsoft.FSharp.Core.CompilerServices.GeneratedSequenceBase`1.MoveNextImpl()
   at Microsoft.FSharp.Collections.SeqModule.Reduce[T](FSharpFunc`2 reduction, IEnumerable`1 source)
   at <StartupCode$FSharp-Data-SqlClient>[email protected](Unit unitVar) in C:\Users
\dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 222
   at [email protected](AsyncParams`1 args)

Question for $1M: what code is called it? Ideas? No? I'm gonna rewrite all async code in C# for this reason.

[dsyme]

@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

[dsyme]

@vasily-kirichenko Does applying this techniqe improve things for this example?

[eiriktsarpalis]

@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.

[vasily-kirichenko]

@dsyme I cannot find the code that raises that exception. I failed replacing async CE with that custom CE globally.

[dsyme]

@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

>   FSharp.Core.dll!Microsoft.FSharp.Core.Operators.Raise<Microsoft.FSharp.Core.FSharpOption<System.Tuple<Microsoft.FSharp.Compiler.SourceCodeServices.FSharpParseFileResults, Microsoft.FSharp.Compiler.SourceCodeServices.FSharpCheckFileResults>>>(System.Exception exn) Line 3803   F#
    FSharp.Core.dll!Microsoft.FSharp.Control.AsyncBuilderImpl.commitWithPossibleTimeout<Microsoft.FSharp.Core.FSharpOption<System.Tuple<Microsoft.FSharp.Compiler.SourceCodeServices.FSharpParseFileResults, Microsoft.FSharp.Compiler.SourceCodeServices.FSharpCheckFileResults>>>(Microsoft.FSharp.Core.FSharpOption<Microsoft.FSharp.Control.AsyncBuilderImpl.AsyncImplResult<Microsoft.FSharp.Core.FSharpOption<System.Tuple<Microsoft.FSharp.Compiler.SourceCodeServices.FSharpParseFileResults, Microsoft.FSharp.Compiler.SourceCodeServices.FSharpCheckFileResults>>>> res) Line 687 F#
    FSharp.Core.dll!<StartupCode$FSharp-Core>.$Control.AsyncWaitAsyncWithTimeout@1837-4<Microsoft.FSharp.Core.FSharpOption<System.Tuple<Microsoft.FSharp.Compiler.SourceCodeServices.FSharpParseFileResults, Microsoft.FSharp.Compiler.SourceCodeServices.FSharpCheckFileResults>>>.Invoke(bool _arg3) Line 1837    F#
    FSharp.Core.dll!Microsoft.FSharp.Control.AsyncBuilderImpl.cont@823<bool, Microsoft.FSharp.Core.FSharpOption<System.Tuple<Microsoft.FSharp.Compiler.SourceCodeServices.FSharpParseFileResults, Microsoft.FSharp.Compiler.SourceCodeServices.FSharpCheckFileResults>>>.Invoke(bool a) Line 823    F#
    FSharp.Core.dll!<StartupCode$FSharp-Core>[email protected](Microsoft.FSharp.Core.FSharpFunc<Microsoft.FSharp.Core.Unit, Microsoft.FSharp.Control.FakeUnitValue> action) Line 426 F#
    FSharp.Core.dll!Microsoft.FSharp.Control.Trampoline.ExecuteAction(Microsoft.FSharp.Core.FSharpFunc<Microsoft.FSharp.Core.Unit, Microsoft.FSharp.Control.FakeUnitValue> firstAction) Line 441    F#
    FSharp.Core.dll!Microsoft.FSharp.Control.TrampolineHolder.Protect(Microsoft.FSharp.Core.FSharpFunc<Microsoft.FSharp.Core.Unit, Microsoft.FSharp.Control.FakeUnitValue> firstAction) Line 553    F#
    FSharp.Core.dll!<StartupCode$FSharp-Core>[email protected](object state, bool timedOut) Line 1773 F#
    mscorlib.dll!System.Threading._ThreadPoolWaitOrTimerCallback.WaitOrTimerCallback_Context(object state, bool timedOut)   Unknown
    mscorlib.dll!System.Threading._ThreadPoolWaitOrTimerCallback.WaitOrTimerCallback_Context_f(object state)    Unknown

[jack-pappas]

@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 AppDomain.FirstChanceException event? You need to be careful to avoid the self-recursion case (e.g. if something in your handler raises an exception), but you can use it to log the exception information immediately, before the exception is even caught and collected into the ExceptionDiapatchInfo.

[vasily-kirichenko]

@jack-pappas Thanks. I tried to log exceptions in FirstChanceException. It always causes SO exception :(

[vasily-kirichenko]

@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 FSharp.Data.SqlClient.SqlCommand.ExecuteReaderAsync call inside an async CE, which I have a lot in that app):

System.Data.SqlClient.SqlException (0x80131904): Cannot open database "xx" requested by the login. The login failed.
Login failed for user 'xx'.
   at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean
   redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, DbConnectionPool pool, String accessToken, Boolean applyTransientFaultHandling)
   at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnectionowningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.Open()
   at <StartupCode$FSharp-Data-SqlClient>[email protected](IEnumerable`1& next) in C:\Users\dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 84
   at Microsoft.FSharp.Core.CompilerServices.GeneratedSequenceBase`1.MoveNextImpl()
   at Microsoft.FSharp.Collections.SeqModule.Reduce[T](FSharpFunc`2 reduction, IEnumerable`1 source)
   at <StartupCode$FSharp-Data-SqlClient>[email protected](Unit unitVar) in C:\Users\dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 222
   at [email protected](AsyncParams`1 args)
ClientConnectionId:98f68b25-ae8a-43a8-907e-d5a8bc7c9fba
Error Number:4060,State:1,Class:11

[vasily-kirichenko]

@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 control.fs and add

[<CallerMemberName>]?callerName : string,
[<CallerFilePath>]?callerFilePath : string,
[<CallerLineNumber>]?callerLineNumber : int) 

Would it work on .NET Core?

[dsyme]

@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 option { ... } CE where the unit of composition is delayed unit -> U option functions - I'll use type O<'T> = unit -> 'T option below . The problem here is always that composition is, in most situations, separate from execution, and all you see are a mess of closures from the CE builder implementation on the stack.

The thought I have is roughly this

when we use "inline" on a CE method with information such as callerName, callerFilePath and callerLineNumber, we will statically know these values at the point of code generation. Perhaps we can use this to emit better sequence points or adjust the names of methods we emit to give better debugging and/or stack traces.

This might involve adding a new primitive sequencepoint that, when compiled with fully static information, emits a sequence point at a source code location rather than the actual location. Like # "foo.fs" 5 but integrated with the inline and CallerFilePath machinery to allow the source location of the caller to be pushed into the inner lambdas. For example:

member inline __.Delay(f : O<'T>,  [<CallerMemberName>]?callerName : string, [<CallerFilePath>]?callerFilePath : string, [<CallerLineNumber>]?callerLineNumber : int) : O<'T> =
fun () ->
    sequencepoint callerFilePath callerLineNumber
    f()

The code for the closure generated for the Invoke method would have debugger source code associated with the point of composition where the use of Delay is implied, e.g. this point:

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 Delay node was constructed. You could also imagine using this to affect the names of methods generated - though that's a bit messier and the stack traces will still always look odd I think.

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:

  at [email protected](AsyncParams`1 args)

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.

[vasily-kirichenko]

Scala stack traces are great

[vasily-kirichenko]

It's clearly impossible to implement. If anybody is ready to do it, please open a new issue.

[eiriktsarpalis]

I don't agree with this being closed. It's important.

[matthid]

Yes, IMHO it is even worth a bit of performance if required

[eiriktsarpalis]

FWIW I have a prototype async implementation which takes a significant performance hit due to RyuJIT not playing nice with stacktrace augmentations in ReturnFrom

[matthid]

Sometimes it could make sense to have something like open FSharp.Control.Debug which enables the improved stack traces (if performance is not acceptable for general use)

[eiriktsarpalis]

Given that async shouldn't be used for anything other than IO bound computations, maybe that could turn out to be acceptable for prod. But it certainly doesn't solve the problem for CEs in general.

[vasily-kirichenko]

Of course it's important.The problem is that Don finds other things more important (like, ... ehh... no idea really because everybody's been doing nothing at MS for months. Maybe marketing or something like than?..)

[forki]

I think the c# side just pushed for cleaning up stack traces in c# async.
Maybe they have something to learn from

Am 28.01.2018 15:47 schrieb "Vasily Kirichenko" [e-mail]:

Of course it's important.The problem is that Don finds other things more
important (like, ... ehh... no idea really because everybody's been doing
nothing at MS for months. Maybe marketing or something like than?..)

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/Microsoft/visualfsharp/issues/2741#issuecomment-361068353,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AADgNEnvT9XwZ6Byi0cOb3SHSx86M-T9ks5tPIhxgaJpZM4Mus7A
.

[dsyme]

I'm experimenting with the use of inlining to concretize user code to the point that we get better stack traces in the async-st branch compare

The experiment also keeps normal stack traces on let! bindings, so that

let async3() = async {
    printfn "%s" (System.Diagnostics.StackTrace(true).ToString())
    return 1
}

let async2() = async {
    printfn "next"
    let! res =  async3()
    printfn "next"
    return res
}

let async1() = async {
    printfn "next"
    let! res = async2()
    printfn "next"
    return res
}


[<EntryPoint>]
let main argv = 
    printfn "%i" (async1() |> Async.RunSynchronously)
    0 // return an integer exit code

gives

   at [email protected](Unit unitVar) in C:\GitHub\dsyme\visualfsharp\a.fs:line 3
   at Microsoft.FSharp.Control.AsyncActions.ExecuteUserCode[T,TResult](AsyncParams`1 args, FSharpFunc`2 f, TResult x)
   at [email protected](AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at Microsoft.FSharp.Control.AsyncActions.BindUserCode[T,TResult](Boolean keepStack, AsyncParams`1 args, FSharpAsync`1 p1, FSharpFunc`2 f)
   at [email protected](AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at [email protected](AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at Microsoft.FSharp.Control.AsyncActions.BindUserCode[T,TResult](Boolean keepStack, AsyncParams`1 args, FSharpAsync`1 p1, FSharpFunc`2 f)
   at [email protected](AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at [email protected](AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at Microsoft.FSharp.Control.Trampoline.ExecuteAsyncAction(FSharpFunc`2 firstAction)
   at Microsoft.FSharp.Control.CancellationTokenOps.RunSynchronouslyInCurrentThread[a](CancellationToken token, FSharpAsync`1 computation)
   at Microsoft.FSharp.Control.FSharpAsync.RunSynchronously[T](FSharpAsync`1 computation, FSharpOption`1 timeout, FSharpOption`1 cancellationToken)
   at A.main(String[] argv) in C:\GitHub\dsyme\visualfsharp\a.fs:line 24

The line 0 parts are wrong,

In the debugger this looks like this because some intermediate methods are suppressed:

[dsyme]

Previously this looked like this:

There is lots to do but if we can get the first in debug mode then things are improved

[vasily-kirichenko]

Any plans to close this issue?

[vasily-kirichenko]

OK, I have an exception and _have absolutely no idea how to find the line of code that raises it_

Any tips? Suggestions? I can add any logging code if it'd help.

[zpodlovics]

Take a look at Debug Diag and WinDbg + SOS. You will be able to examine everything, however it has a learning curve. Quick tutorial: https://youtube.com/watch?v=S-jiM07X3fs

In the meantime .NET Core 2.1 now has intelligible async stack traces (at least for C# async generated state machines), while it's a bit off topic for F#, it may also have some useful ideas:

https://www.ageofascent.com/2018/01/26/stack-trace-for-exceptions-in-dotnet-core-2.1/

[vasily-kirichenko]

@zpodlovics Yeah, C# has special support for async stack traces, and it's useless for F# asyncs :(

Thanks for the video! :)

[vasily-kirichenko]

@dsyme I cannot merge master to your branch, there are lots of conflicts and I've no idea how to resolve them. It seems there have been a lot of changes in control.fs in last three months.

[dsyme]

@vasily-kirichenko I'm updating it now.

[dsyme]

I separated out the code cleanup portion in https://github.com/Microsoft/visualfsharp/pull/4866. This makes the branch easier to maintain. The comparison between cleanup and branch is here

[vasily-kirichenko]

@dsyme Thank you! Async stacks is super important to me and my team.

[dsyme]

@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 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.

[forki]

Hugs

Don Syme [e-mail] 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
https://github.com/Microsoft/visualfsharp/issues/2741#issuecomment-361753602
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
https://github.com/Microsoft/visualfsharp/issues/2741#issuecomment-387752533,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AADgNEyuW684cJwVq7b8z43i6xYQxtTaks5twvljgaJpZM4Mus7A
.

[vasily-kirichenko]

@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?

[vasily-kirichenko]

@dsyme It turns out that my case is more complicated: we use asyncResult CE, not just async, and we use a MailboxProcessor to run the async computation periodically (https://github.com/vasily-kirichenko/AsyncStacks2):

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
    0

output

at [email protected](Unit unitVar) in /Users/vaskir/git/AsyncStacks2/AsyncStacks2/Program.fs:line 69
   at [email protected](AsyncParams`1 args)
   at <StartupCode$FSharp-Core>.$Control.loop@124-50(Trampoline this, FSharpFunc`2 action)
   at Microsoft.FSharp.Control.Trampoline.ExecuteAction(FSharpFunc`2 firstAction)
   at <StartupCode$FSharp-Core>[email protected](Object _arg6, Boolean timeOut)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

[abelbraaksma]

With #4867 completed (since 2018), should this be considered resolved and closed?

[vasily-kirichenko]

@abelbraaksma as you wish, but the stack traces as useless as before.

[abelbraaksma]

@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.

[NinoFloris]

@vasily-kirichenko Task is not so different in this regard

Try the following example based on yours.
You need <PackageReference Include="Ply" Version="0.1.8" /> for the task CE.

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
    0

output

   at [email protected](Unit _arg1) in /Users/nfloris/Projects/rep/Program.fs:line 72
   at [email protected](Unit x) in /Users/nfloris/Projects/rep/Program.fs:line 71
   at Ply.TplPrimitives.ContinuationStateMachine`1.System-Runtime-CompilerServices-IAsyncStateMachine-MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecuteFromThreadPool(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()

No trace of exec, getTasks, or loadTasksAsync for Tasks either. However if you remove do! Task.Yield() from executeReader the stacktrace will contain all information. As Task runs binds inline if it can by removing the forced yield causes the execution to never unwind back up to the trampoline (Ply.TplPrimitives.ContinuationStateMachine here). There was nothing intrinsically async to do. Permitting inline binds is a fundamental difference between Tasks and Async today, Async could definitely start doing this within safe limits.

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 Awaiter.GetResult()). Right at this moment the failed Task has the opportunity to help reify a bit of the stack frames that were lost, it does this by throwing an exception via ExceptionDispatchInfo.Throw this serves to keep the original trace intact instead of replacing all frames like raise ex would.

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!

[kerry-perret]

@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.

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)
    }

Unhandled exception. System.Exception: bug!
   at [email protected](Unit unitVar) in C:\Users\Michelle\Desktop\Work\FSharpPlayground\FSharpPlayground\Program.fs:line 10
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvoke[T,TResult](AsyncActivation`1 ctxt, TResult result1, FSharpFunc`2 part2) in E:\A\_work\130\s\src\
fsharp\FSharp.Core\async.fs:line 398
   at Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc`2 firstAction) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 109
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.FSharp.Control.AsyncResult`1.Commit() in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 350
   at Microsoft.FSharp.Control.AsyncPrimitives.RunSynchronouslyInCurrentThread[a](CancellationToken cancellationToken, FSharpAsync`1 computation) in E:\A\_wor
k\130\s\src\fsharp\FSharp.Core\async.fs:line 882
   at Microsoft.FSharp.Control.AsyncPrimitives.RunSynchronously[T](CancellationToken cancellationToken, FSharpAsync`1 computation, FSharpOption`1 timeout) in
E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 890
   at Microsoft.FSharp.Control.FSharpAsync.RunSynchronously[T](FSharpAsync`1 computation, FSharpOption`1 timeout, FSharpOption`1 cancellationToken) in E:\A\_w
ork\130\s\src\fsharp\FSharp.Core\async.fs:line 1154
   at Program.main(String[] _arg1) in C:\Users\Michelle\Desktop\Work\FSharpPlayground\FSharpPlayground\Program.fs:line 17

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.

[NinoFloris]

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)
    0

will show a trace like:

System.InvalidOperationException: Oh no
   at [email protected](FSharpResult`2 r)
   at Ply.TplPrimitives.TplAwaitable`4.GetNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 158
   at Ply.TplPrimitives.ContinuationStateMachine`1.System-Runtime-CompilerServices-IAsyncStateMachine-MoveNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 113
   at Ply.TplPrimitives.ValueTaskAwaiterMethods`1.Ply-TplPrimitives-IAwaiterMethods`2-GetResult(ValueTaskAwaiter`1& awt) in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 392
   at Ply.TplPrimitives.TplAwaitable`4.GetNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 155
--- End of stack trace from previous location where exception was thrown ---
   at [email protected](FSharpResult`2 r)
   at Ply.TplPrimitives.TplAwaitable`4.GetNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 158
   at Ply.TplPrimitives.ContinuationStateMachine`1.System-Runtime-CompilerServices-IAsyncStateMachine-MoveNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 113
   at Ply.TplPrimitives.ValueTaskAwaiterMethods`1.Ply-TplPrimitives-IAwaiterMethods`2-GetResult(ValueTaskAwaiter`1& awt) in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 392
   at Ply.TplPrimitives.TplAwaitable`4.GetNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 155
--- End of stack trace from previous location where exception was thrown ---
   at [email protected](FSharpResult`2 r)
   at Ply.TplPrimitives.TplAwaitable`4.GetNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 158
   at Ply.TplPrimitives.ContinuationStateMachine`1.System-Runtime-CompilerServices-IAsyncStateMachine-MoveNext() in /Users/nfloris/Projects/Crowded/Ply/Ply.fs:line 113
   at PlyProgram.main(String[] argv) in /Users/nfloris/Projects/Crowded/Ply/Program.fs:line 90

The changes to do this were fairly small (though Async is probably quite a bit more involved)
https://github.com/crowded/ply/commit/eae21dbebd0f6d3ebd9021ad2ca31c017831faab

When I have some spare time I'm going to prototype this approach for Async as well.