Improve async stack traces

[vasily-kirichenko]

C#

F#

1. The stack trace is completely lost between main and bazz.
2. ConsoleApplication1.exe!Program.bazz@6-1.Invoke(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'

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

System.Exception: bug!
   at Program.even@119.Invoke(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.ec@102-1.Invoke(SymbolicException se) in C:\Users\eirik\devel\public\cont\Program.fs:line 102
   at Program.ContModule.run[T](FSharpFunc`2 cont) in C:\Users\eirik\devel\public\cont\Program.fs:line 103
   at <StartupCode$ConsoleApplication3>.$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#:

    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

[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>.$ISqlCommand.clo@80-3.GenerateNext(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>.$ISqlCommand.AsyncExecuteReader@222.Invoke(Unit unitVar) in C:\Users
\dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 222
   at Microsoft.FSharp.Control.AsyncBuilderImpl.callA@851.Invoke(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>.$Control.loop@426-38.Invoke(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>.$Control.AwaitWaitHandle@1768-3.Invoke(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>.$ISqlCommand.clo@80-3.GenerateNext(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>.$ISqlCommand.AsyncExecuteReader@222.Invoke(Unit unitVar) in C:\Users\dmitry\Documents\GitHub\FSharp.Data.SqlClient\src\SqlClient\ISqlCommand.fs:line 222
   at Microsoft.FSharp.Control.AsyncBuilderImpl.callA@839.Invoke(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 Microsoft.FSharp.Control.AsyncBuilderImpl.callA@839.Invoke(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" notifications@github.com:

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 A.async3@3.Invoke(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 A.async3@2-2.Invoke(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 A.async2@9-3.Invoke(AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at A.async2@7-4.Invoke(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 A.async1@16-3.Invoke(AsyncParams`1 args) in C:\GitHub\dsyme\visualfsharp\a.fs:line 0
   at A.async1@14-4.Invoke(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 notifications@github.com 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 Program.executeReader@69.Invoke(Unit unitVar) in /Users/vaskir/git/AsyncStacks2/AsyncStacks2/Program.fs:line 69
   at Microsoft.FSharp.Control.AsyncBuilderImpl.callA@522.Invoke(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>.$Control.AwaitWaitHandle@1337-2.Invoke(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?