fsharp
fsharp copied to clipboard
dotnet
Improve async stack traces
C#
F#
- The stack trace is completely lost between
mainandbazz. [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?
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?
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.
https://eiriktsarpalis.wordpress.com/2015/12/27/reconciling-stacktraces-with-computation-expressions/
@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.run
System.Exception: bug!
at [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 [email protected](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
@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?
@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.
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 @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?
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()
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.
@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:
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.
@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 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
> 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
@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.
@jack-pappas Thanks. I tried to log exceptions in FirstChanceException. It always causes SO exception :(
@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
@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?
@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,callerFilePathandcallerLineNumber, 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.
It's clearly impossible to implement. If anybody is ready to do it, please open a new issue.
