From 27486f3f1811694de0135b2760d2a1b6840bafc0 Mon Sep 17 00:00:00 2001 From: Abel Braaksma Date: Mon, 31 Oct 2022 21:52:49 +0100 Subject: [PATCH] Improve logging --- src/FSharpy.TaskSeq/TaskSeqBuilder.fs | 226 +++++++++++++------------- 1 file changed, 112 insertions(+), 114 deletions(-) diff --git a/src/FSharpy.TaskSeq/TaskSeqBuilder.fs b/src/FSharpy.TaskSeq/TaskSeqBuilder.fs index 5545218b..e9f03eac 100644 --- a/src/FSharpy.TaskSeq/TaskSeqBuilder.fs +++ b/src/FSharpy.TaskSeq/TaskSeqBuilder.fs @@ -33,6 +33,15 @@ module Internal = // cannot be marked with 'internal' scope with _ -> false + let log format = + if verbose then + Printf.ksprintf + (fun s -> + printfn "%i (%b): %s" Thread.CurrentThread.ManagedThreadId Thread.CurrentThread.IsThreadPoolThread s) + format + else + Printf.ksprintf ignore format + /// Call MoveNext on an IAsyncStateMachine by reference let inline moveNextRef (x: byref<'T> when 'T :> IAsyncStateMachine) = x.MoveNext() @@ -91,9 +100,9 @@ type TaskSeqStateMachineData<'T>() = member data.PushDispose(disposer: unit -> Task) = if isNull data.disposalStack then - data.disposalStack <- ResizeArray() + data.disposalStack <- null - data.disposalStack.Add disposer + //data.disposalStack.Add disposer member data.PopDispose() = if not (isNull data.disposalStack) then @@ -202,29 +211,28 @@ and [] TaskSeq<'Machine, 'T member this.GetResult(token: int16) = match this.hijack () with | Some tg -> - if verbose then - printfn - "Getting result for token on 'Some' branch, status: %A" - ((tg :> IValueTaskSource).GetStatus(token)) + log + "Getting result for token on hijacked branch, status: %A" + ((tg :> IValueTaskSource).GetStatus(token)) (tg :> IValueTaskSource).GetResult(token) | None -> try - if verbose then - printfn - "Getting result for token on 'None' branch, status: %A" - (this._machine.Data.promiseOfValueOrEnd.GetStatus(token)) + log + "Getting result for token on normal branch, status: %A" + (this._machine.Data.promiseOfValueOrEnd.GetStatus(token)) - this._machine.Data.promiseOfValueOrEnd.GetResult(token) + let x = this._machine.Data.promiseOfValueOrEnd.GetResult(token) + this._machine.Data.promiseOfValueOrEnd.Reset() + x with e -> // FYI: an exception here is usually caused by the CE statement (user code) throwing an exception // We're just logging here because the following error would also be caught right here: // "An attempt was made to transition a task to a final state when it had already completed." - if verbose then - printfn "Error '%s' for token: %i" e.Message token - + log "Error '%s' for token: %i" e.Message token reraise () + member this.OnCompleted(continuation, state, token, flags) = match this.hijack () with | Some tg -> (tg :> IValueTaskSource).OnCompleted(continuation, state, token, flags) @@ -234,7 +242,15 @@ and [] TaskSeq<'Machine, 'T /// The MoveNext method is called by builder.MoveNext() in the resumable code member this.MoveNext() = match this.hijack () with - | None -> moveNextRef &this._machine + | None -> + log "at IAsyncStateMatchine.MoveNext" + + try + moveNextRef &this._machine + with e -> + log "at IAsyncStatemachine EXCEPTION!!!" + log "%A" e + | Some tg -> // jump to the hijacked method (tg :> IAsyncStateMachine).MoveNext() @@ -247,30 +263,30 @@ and [] TaskSeq<'Machine, 'T member this.GetAsyncEnumerator(ct) = // if this is null, it means it's the first time for this Enumerable to create an Enumerator // so, to prevent extra allocations, we just return 'self', with the iterator vars set appropriately. - match this._machine.Data :> obj with - | null when initialThreadId = Environment.CurrentManagedThreadId -> - this.InitMachineData(ct, &this._machine) - this // just return 'self' here - - | _ -> - if verbose then - printfn "GetAsyncEnumerator, cloning..." - - // We need to reset state, but only to the "initial machine", resetting the _machine to - // Unchecked.defaultof<_> is wrong, as the compiler uses this to track state. However, - // we do need a zeroed ResumptionPoint, otherwise we would continue after the last iteration - // returning an empty sequence. - // - // Solution: we shadow the initial machine, which we then re-assign here: - // - let clone = TaskSeq<'Machine, 'T>() // we used MemberwiseClone, TODO: test difference in perf, but this should be faster - - // _machine will change, _initialMachine will not, which can be used in a new clone. - // we still need to copy _initialMachine, as it has been initialized by the F# compiler in AfterCode<_, _>. - clone._machine <- this._initialMachine - clone._initialMachine <- this._initialMachine // TODO: proof with a test that this is necessary: probably not - clone.InitMachineData(ct, &clone._machine) - clone + //match this._machine.Data :> obj with + //| null when initialThreadId = Environment.CurrentManagedThreadId -> + // this.InitMachineData(ct, &this._machine) + // this // just return 'self' here + + //| _ -> + log "GetAsyncEnumerator, start cloning..." + + // We need to reset state, but only to the "initial machine", resetting the _machine to + // Unchecked.defaultof<_> is wrong, as the compiler uses this to track state. However, + // we do need a zeroed ResumptionPoint, otherwise we would continue after the last iteration + // returning an empty sequence. + // + // Solution: we shadow the initial machine, which we then re-assign here: + // + let clone = TaskSeq<'Machine, 'T>() // we used MemberwiseClone, TODO: test difference in perf, but this should be faster + + // _machine will change, _initialMachine will not, which can be used in a new clone. + // we still need to copy _initialMachine, as it has been initialized by the F# compiler in AfterCode<_, _>. + clone._machine <- this._initialMachine + clone._initialMachine <- this._initialMachine // TODO: proof with a test that this is necessary: probably not + clone.InitMachineData(ct, &clone._machine) + log "GetAsyncEnumerator, finished cloning..." + clone interface System.Collections.Generic.IAsyncEnumerator<'T> with member this.Current = @@ -298,38 +314,32 @@ and [] TaskSeq<'Machine, 'T (tg :> IAsyncEnumerator<'T>).MoveNextAsync() | None -> - if verbose then - printfn "MoveNextAsync..." + log "MoveNextAsync..." if this._machine.ResumptionPoint = -1 then // can't use as IAsyncEnumerator before IAsyncEnumerable - if verbose then - printfn "at MoveNextAsync: Resumption point = -1" + log "at MoveNextAsync: Resumption point = -1" ValueTask() elif this._machine.Data.completed then - if verbose then - printfn "at MoveNextAsync: completed = true" + log "at MoveNextAsync: completed = true" // return False when beyond the last item this._machine.Data.promiseOfValueOrEnd.Reset() ValueTask() else - if verbose then - printfn "at MoveNextAsync: normal resumption scenario" + log "at MoveNextAsync: normal resumption scenario" let data = this._machine.Data data.promiseOfValueOrEnd.Reset() let mutable ts = this - if verbose then - printfn "at MoveNextAsync: start calling builder.MoveNext()" + log "at MoveNextAsync: start calling builder.MoveNext()" data.builder.MoveNext(&ts) - if verbose then - printfn "at MoveNextAsync: done calling builder.MoveNext()" + log "at MoveNextAsync: done calling builder.MoveNext()" // If the move did a hijack then get the result from the final one match this.hijack () with @@ -341,8 +351,7 @@ and [] TaskSeq<'Machine, 'T match this.hijack () with | Some tg -> (tg :> IAsyncDisposable).DisposeAsync() | None -> - if verbose then - printfn "DisposeAsync..." + log "DisposeAsync..." task { match this._machine.Data.disposalStack with @@ -371,8 +380,7 @@ and [] TaskSeq<'Machine, 'T match status with | ValueTaskSourceStatus.Succeeded -> - if verbose then - printfn "at MoveNextAsyncResult: case succeeded..." + log "at MoveNextAsyncResult: case succeeded..." let result = data.promiseOfValueOrEnd.GetResult(version) @@ -385,14 +393,12 @@ and [] TaskSeq<'Machine, 'T | ValueTaskSourceStatus.Faulted | ValueTaskSourceStatus.Canceled - | ValueTaskSourceStatus.Pending -> - if verbose then - printfn "at MoveNextAsyncResult: case pending/faulted/cancelled..." + | ValueTaskSourceStatus.Pending as state -> + log "at MoveNextAsyncResult: case %A..." state ValueTask(this, version) // uses IValueTaskSource<'T> | _ -> - if verbose then - printfn "at MoveNextAsyncResult: Unexpected state" + log "at MoveNextAsyncResult: Unexpected state" // assume it's a possibly new, not yet supported case, treat as default ValueTask(this, version) // uses IValueTaskSource<'T> @@ -416,29 +422,24 @@ type TaskSeqBuilder() = //-- RESUMABLE CODE START __resumeAt sm.ResumptionPoint - if verbose then - printfn "Resuming at resumption point %i" sm.ResumptionPoint + log "Resuming at resumption point %i" sm.ResumptionPoint try - if verbose then - printfn "at Run.MoveNext start" + log "at Run.MoveNext start" let __stack_code_fin = code.Invoke(&sm) - if verbose then - printfn $"at Run.MoveNext, __stack_code_fin={__stack_code_fin}" + log $"at Run.MoveNext, __stack_code_fin={__stack_code_fin}" if __stack_code_fin then - if verbose then - printfn $"at Run.MoveNext, done" + log $"at Run.MoveNext, done" sm.Data.promiseOfValueOrEnd.SetResult(false) sm.Data.builder.Complete() sm.Data.completed <- true elif sm.Data.current.IsSome then - if verbose then - printfn $"at Run.MoveNext, yield" + log $"at Run.MoveNext, yield" sm.Data.promiseOfValueOrEnd.SetResult(true) @@ -446,15 +447,13 @@ type TaskSeqBuilder() = // Goto request match sm.Data.tailcallTarget with | Some tg -> - if verbose then - printfn $"at Run.MoveNext, hijack" + log $"at Run.MoveNext, hijack" let mutable tg = tg moveNextRef &tg | None -> - if verbose then - printfn $"at Run.MoveNext, await" + log $"at Run.MoveNext, await" // don't capture the full object in the next closure (won't work because: byref) // but only a reference to itself. @@ -467,8 +466,9 @@ type TaskSeqBuilder() = ) with exn -> - if verbose then - printfn "Setting exception of PromiseOfValueOrEnd to: %s" exn.Message + log "Exception dump:" + log "%A" exn + log "Setting exception of PromiseOfValueOrEnd to: %s" exn.Message sm.Data.promiseOfValueOrEnd.SetException(exn) sm.Data.builder.Complete() @@ -476,8 +476,7 @@ type TaskSeqBuilder() = )) (SetStateMachineMethodImpl<_>(fun sm state -> ())) // not used in reference impl (AfterCode<_, _>(fun sm -> - if verbose then - printfn "at AfterCode<_, _>, after F# inits the sm, and we can attach extra info" + log "at AfterCode<_, _>, after F# inits the sm, and we can attach extra info" let ts = TaskSeq, 'T>() ts._initialMachine <- sm @@ -497,14 +496,11 @@ type TaskSeqBuilder() = member inline _.Zero() : TaskSeqCode<'T> = - if verbose then - printfn "at Zero()" - + log "at Zero()" ResumableCode.Zero() member inline _.Combine(task1: TaskSeqCode<'T>, task2: TaskSeqCode<'T>) : TaskSeqCode<'T> = - if verbose then - printfn "at Combine(.., ..)" + log "at Combine(.., ..)" ResumableCode.Combine(task1, task2) @@ -522,14 +518,12 @@ type TaskSeqBuilder() = let __stack_vtask = condition () if __stack_vtask.IsCompleted then - if verbose then - printfn "at WhileAsync: returning completed task" + log "at WhileAsync: returning completed task" __stack_condition_fin <- true condition_res <- __stack_vtask.Result else - if verbose then - printfn "at WhileAsync: awaiting non-completed task" + log "at WhileAsync: awaiting non-completed task" let task = __stack_vtask.AsTask() let mutable awaiter = task.GetAwaiter() @@ -538,15 +532,11 @@ type TaskSeqBuilder() = let __stack_yield_fin = ResumableCode.Yield().Invoke(&sm) __stack_condition_fin <- __stack_yield_fin - if verbose then - printfn - "at WhileAsync: after Yield().Invoke(sm), __stack_condition_fin=%b" - __stack_condition_fin + log "at WhileAsync: after Yield().Invoke(sm), __stack_condition_fin=%b" __stack_condition_fin if __stack_condition_fin then condition_res <- task.Result else - //if verbose then printfn "calling AwaitUnsafeOnCompleted" sm.Data.awaiter <- awaiter sm.Data.current <- ValueNone @@ -557,8 +547,7 @@ type TaskSeqBuilder() = ) member inline b.While([] condition: unit -> bool, body: TaskSeqCode<'T>) : TaskSeqCode<'T> = - if verbose then - printfn "at While(...), calling WhileAsync()" + log "at While(...), calling WhileAsync()" b.WhileAsync((fun () -> ValueTask(condition ())), body) @@ -653,13 +642,11 @@ type TaskSeqBuilder() = TaskSeqCode<'T>(fun sm -> // This will yield with __stack_fin = false // This will resume with __stack_fin = true - if verbose then - printfn "at Yield, before Yield().Invoke(sm)" + log "at Yield, before Yield().Invoke(sm)" let __stack_fin = ResumableCode.Yield().Invoke(&sm) - if verbose then - printfn "at Yield, __stack_fin = %b" __stack_fin + log "at Yield, __stack_fin = %b" __stack_fin sm.Data.current <- ValueSome v sm.Data.awaiter <- null @@ -675,8 +662,7 @@ type TaskSeqBuilder() = let mutable awaiter = task.GetAwaiter() let mutable __stack_fin = true - if verbose then - printfn "at Bind" + log "at Bind" if not awaiter.IsCompleted then // This will yield with __stack_fin2 = false @@ -684,22 +670,36 @@ type TaskSeqBuilder() = let __stack_fin2 = ResumableCode.Yield().Invoke(&sm) __stack_fin <- __stack_fin2 - if verbose then - printfn "at Bind: with __stack_fin = %b" __stack_fin + log "at Bind: with __stack_fin = %b" __stack_fin + log "at Bind: this.completed = %b" sm.Data.completed if __stack_fin then - if verbose then - printfn "at Bind: with getting result from awaiter" + let uninitialized = Unchecked.defaultof> + log "at Bind: awaiter is initialized: %b" (uninitialized <> awaiter) - let result = awaiter.GetResult() + if uninitialized = awaiter then + log "at Bind: task is null: %b" (isNull task) + awaiter <- task.GetAwaiter() - if verbose then - printfn "at Bind: calling continuation" + log "at Bind: awaiter is initialized: %b" (uninitialized <> awaiter) + log "at Bind: with getting result from awaiter, completed: %b" awaiter.IsCompleted - (continuation result).Invoke(&sm) + let result = + try + awaiter.GetResult() + with e -> + log "at Bind: EXCEPTION getting result from awaiter: %A" e + Unchecked.defaultof<_> + + log "at Bind: calling continuation" + + try + (continuation result).Invoke(&sm) + with e -> + printfn "Exception!!! %s" e.Message + reraise () else - if verbose then - printfn "at Bind: calling AwaitUnsafeOnCompleted" + log "at Bind: calling AwaitUnsafeOnCompleted" sm.Data.awaiter <- awaiter sm.Data.current <- ValueNone @@ -710,8 +710,7 @@ type TaskSeqBuilder() = let mutable awaiter = task.GetAwaiter() let mutable __stack_fin = true - if verbose then - printfn "at BindV" + log "at BindV" if not awaiter.IsCompleted then // This will yield with __stack_fin2 = false @@ -723,8 +722,7 @@ type TaskSeqBuilder() = let result = awaiter.GetResult() (continuation result).Invoke(&sm) else - if verbose then - printfn "at BindV: calling AwaitUnsafeOnCompleted" + log "at BindV: calling AwaitUnsafeOnCompleted" sm.Data.awaiter <- awaiter sm.Data.current <- ValueNone