Use AsyncLocal to keep diagnostics instead of ThreadStatic

[majocha]

Introduction of Transparent Compiler revealed some instability w.r.t. DiagnosticsThreadStatics:
#16576 (comment)
#16576
#16589

Turns out we used [<ThreadStatic>] to keep a compilation-global DiagnosticsLogger, and a custom NodeCode CE to flow it across threads during execution.
AsyncLocal is a BCL class that provides exactly that functionality: flowing state along the async execution path.

This replaces the ThreadStatic diagnostics state for AsyncLocal.
NodeCode<'T> is no longer needed. For now we make it into an alias for Async<'T>, and the node CE is an alias for async builder. To be decided if we want to remove it in this or a separate PR.

[github-actions]

❗ Release notes required

---

✅ Found changes and release notes in following paths:

Change path	Release notes path	Description
src/Compiler	docs/release-notes/.FSharp.Compiler.Service/8.0.300.md

[majocha]

Ok, I replaced it with AsyncLocal and for now tried to noop NodeCode. Let's see what breaks.
I have no idea if AsyncLocal works with F# async tbh.

[vzarytovskii]

Ok, I replaced it with AsyncLocal and for now tried to noop NodeCode. Let's see what breaks. I have no idea if AsyncLocal works with F# async tbh.

I am not sure tbh. AsyncLocal manages locals via ExecutionContext, which is somewhat tied to the thread. I would expect it not to rely in the IAsyncStateMachine or anything task-related.

References: https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Threading/AsyncLocal.cs,ef9ce034697240ba
https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs,33788b02dd361e94

[majocha]

This looks promising. Only one test fails.

[0101]

I will be amazed if this works.

🤞

[majocha]

That one error indicates a case where the AsyncLocal fails us where the normal ThreadStatic worked. It's worth it to dive to the bottom of this:

fsharp/tests/service/MultiProjectAnalysisTests.fs

Line 835 in b3a7e29

let``In-memory cross-project references to projects using generative type provides should fallback to on-disk references`` ()=

[vzarytovskii]

@majocha getting rid of additional builder abstractions which are essentially just async is a good call I think. Wanted to do it for some time. Wondering if @0101 has any objections to that?

It will make it even easier to move to some state-machines based ones in future (or at least experiment with those).

[0101]

Definitely no objections. The whole point of it was just managing the thread statics. If we can solve it without the extra builder it will be a great improvement.

[majocha]

That one test fail is possibly something related to type providers in the checker.

[majocha]

Comparing the test in question with main, there are two diagnostics missing that should be there:

Error opening binary file 'E:\repos\fsharp\tests\service/DUMMY/TestProject.dll': Could not find a part of the path 'E:\repos\fsharp\tests\service\DUMMY\TestProject.dll'.

and

Problem reading assembly 'E:\repos\fsharp\tests\service/DUMMY/TestProject.dll': The exception has been reported. This internal exception should now be caught at an error recovery point on the stack. Original message: Error opening binary file 'E:\repos\fsharp\tests\service/DUMMY/TestProject.dll': Could not find a part of the path 'E:\repos\fsharp\tests\service\DUMMY\TestProject.dll'.)

That's some starting point for figuring this out.

[0101]

Looks like after the change the errors go to FinalizeTypeCheckTask logger instead of CombineImportedAssembliesTask one.

Before (works):

After (diagnostics lost):

[vzarytovskii]

@majocha If you know which test are failing (or were failing rather) specifically, I can run them tomorrow on my Mac in the loop, they're quite fast here.

[majocha]

@vzarytovskii the original test is fixed now, with the holder. A few others popped up. I'll take a closer look later.

[vzarytovskii]

Currently failing tests indicate that we are not (re)storing logger correctly somewhere and it hides issues.

[majocha]

Actually it looks worse.:

Why does the ExecutionContext set null there?

I'm also wondering, the ExecutionContext implementation changed quite a bit over the time:
https://referencesource.microsoft.com/#mscorlib/system/threading/executioncontext.cs,33788b02dd361e94
Which version do we actually have when we target netstandard2.0?

[vzarytovskii]

Which version do we actually have when we target netstandard2.0?

The one from the target runtime. In VS it would be the one from .NET 4.7.2, in tests - either the same or 8.0.101

[majocha]

OK, now I'm stumped.
In a code like this, I would expect the static do and static let to run before the getter executes:

/// Type holds thread-static globals for use by the compiler.typeDiagnosticsThreadStatics=static letdiagnosticsLogger=new AsyncLocal<DiagnosticsLogger option>()static letbuildPhase=new AsyncLocal<BuildPhase option>()
static do
diagnosticsLogger.Value <- Some AssertFalseDiagnosticsLogger
buildPhase.Value <- Some BuildPhase.DefaultPhase
static memberBuildPhasewith get ()= buildPhase.Value |> Option.get
andset v = buildPhase.Value <- Some v
static memberDiagnosticsLoggerwith get ()= diagnosticsLogger.Value |> Option.get
andset v = diagnosticsLogger.Value <- Some v

But it doesn't happen.😶

[vzarytovskii]

OK, now I'm stumped. In a code like this, I would expect the static do and static let to run before the getter executes:

/// Type holds thread-static globals for use by the compiler.typeDiagnosticsThreadStatics=static letdiagnosticsLogger=new AsyncLocal<DiagnosticsLogger option>()static letbuildPhase=new AsyncLocal<BuildPhase option>()
static do
diagnosticsLogger.Value <- Some AssertFalseDiagnosticsLogger
buildPhase.Value <- Some BuildPhase.DefaultPhase
static memberBuildPhasewith get ()= buildPhase.Value |> Option.get
andset v = buildPhase.Value <- Some v
static memberDiagnosticsLoggerwith get ()= diagnosticsLogger.Value |> Option.get
andset v = diagnosticsLogger.Value <- Some v

But it doesn't happen.😶

What happens instead?

In the following code:

openSystem.ThreadingtypeDiagnosticsThreadStatics()=static letdiagnosticsLogger=new AsyncLocal<int option>()static letbuildPhase=new AsyncLocal<int option>()
static do
diagnosticsLogger.Value <- Some (1)
buildPhase.Value <- Some (2)static memberBuildPhasewith get ()= buildPhase.Value |> Option.get
andset v = buildPhase.Value <- Some v
static memberDiagnosticsLoggerwith get ()= diagnosticsLogger.Value |> Option.get
andset v = diagnosticsLogger.Value <- Some v

Initialisation will roughly happens in this order (via external (likely) static initializer):

DiagnosticsThreadStatics.diagnosticsLogger =new AsyncLocal<FSharpOption<int>>();
DiagnosticsThreadStatics.buildPhase =new AsyncLocal<FSharpOption<int>>();
DiagnosticsThreadStatics.diagnosticsLogger.Value = FSharpOption<int>.Some(1);
DiagnosticsThreadStatics.buildPhase.Value = FSharpOption<int>.Some(2);

Both getter and setter for properties will also have an intrinsic initialisation check, which will throw in case if initialization hasn't been done.

Keep in mind, that it will be executed once in the async context, static constructor is "running". So if you first accessed DiagnosticsThreadStatics on the AsyncContext-1, and then calling getter on AsyncContext-2, it will be a default value (None/null).

[majocha]

What happens instead?

Hm, just the debugger somehow does not break. I'm getting nulls just like you predicted so I was wondering what is going on.

[vzarytovskii]

What happens instead?

Hm, just the debugger somehow does not break. I'm getting nulls just like you predicted so I was wondering what is going on.

Since it's kinda "external" init code, I'm not sure we emit any debug points for it. Can be verified by looking at the PDB info, I think.

[majocha]

Thanks @vzarytovskii, I think you clarified it to me now. I've been running in circles about it. This is now green locally, let's see what the CI says. 🤞🤞

[majocha]

Nope, still bad.

[majocha]

Sigh, something is not right. The tests pass locally, but the CI stalls.

Is there a difference in tests run time before and after change locally?

Hard to tell, not noticeable, but I admit I run just the FCS usually, or a subset of failing ones, not the full suite. I'll try to run everything later when I'm on a desktop PC.

[vzarytovskii]

Changes look sane, but I have few concerns/questions.

1. It touches not only new compiler pipeline, but modifies all of them by changing how wrapping works (well, non-wrapping now).
2. Because of 1., I am a bit concerned about how will that work out in fully-async (as in non-task async) context, like FSAC, whether AsyncLocal will still work correctly there. Concern here is that in both tests and VS we launch things from within Task most of the times, whereas FSAC has fully Control.Async based stack.
3. A wild idea (maybe not for this PR though?) - we should probably do the OTEL logging for the build phase and diagnostic loggers, including what do we set and get. By default its noop, but can be helpful when diagnosing some issues.

[vzarytovskii]

To illustrate, in "pure" async stack, when we run async (RunSycnronously and co) we pretty much queue computation via trampoline (one way or another):

However, from my understanding, if we are launched by tasks scheduler (via StartAsTask, as we do in VS and tests), we do use tasks directly, which will make AsyncLocal work as expected.

[majocha]

I did a quick experiment console app:

openSystem.ThreadingopenSystem.Collections.ConcurrenttypeHolder()=letdata= ConcurrentQueue()member_.Add v = data.Enqueue v
member_.GetAll= data |> List.ofSeq
moduleLocals =leta=new AsyncLocal<_>()letinit()= a.Value <- Holder()
Locals.init()letwork tag =async{do! Async.Sleep 10leta= Locals.a.Value
for i in1..5do
a.Add $"{tag} {i}"do! Async.Sleep 10return a.GetAll
}letresult=["A";"B";"C"]|> Seq.map work |> Async.Parallel |> Async.RunSynchronously
printfn "%A" Locals.a.Value.GetAll

It seems to work correctly:

["A 1"; "B 1"; "C 1"; "B 2"; "A 2"; "C 2"; "C 3"; "B 3"; "A 3"; "A 4"; "B 4";
"C 4"; "C 5"; "B 5"; "A 5"]

[majocha]

My understanding it that ExecutionContext operates on ThreadPool level, and does not depend on tasks in any way.

[vzarytovskii]

My understanding it that ExecutionContext operates on ThreadPool level, and does not depend on tasks in any way.

Yeah, that's what I was trying to understand. Regarding the example above, what if you will mix in do! Async.SwitchToNewThread() and some |> AwaitTask

We use the former a lot in stack guards, which can lead to interesting consequences.

[majocha]

OK, my plan to deal with this is to reset everything, leave NodeCodeBuilder in place and only do the minimal changes required, i.e. DiagnosticsLogger.fs, the test fix in CompilerImports.fs.
main testFSharpQA took 14m 38s on my PC. I'll build and run this branch.

[majocha]

openSystem.ThreadingopenSystem.Threading.TasksopenSystem.Collections.ConcurrenttypeHolder(name)=letdata= ConcurrentQueue()member_.Add v = data.Enqueue v
member_.GetAll= name, data |> List.ofSeq
moduleLocals =leta=new AsyncLocal<_>()letinit()= a.Value <- Holder("init")
Locals.init()lett tag i =task{do! Task.Delay 10
Locals.a.Value.Add $"{tag} {i}"}letwork tag =async{do! Async.Sleep 10
Locals.a.Value <- Holder(tag)leta= Locals.a.Value
for i in1..5dodo! Async.SwitchToNewThread()do! t tag i |> Async.AwaitTask
do! Async.Sleep 10return a.GetAll
}letresult=["A";"B";"C"]|> Seq.map work |> Async.Parallel |> Async.RunSynchronously
printfn "%A" result
printfn "%A" Locals.a.Value.GetAll

still works fine, even in FSI.

[majocha]

I think I got it to pass CI: #16634

Is it ok to force push here?

[vzarytovskii]

I think I got it to pass CI: #16634

Is it ok to force push here?

In the branch? Sure thing.

[majocha]

OK, diff looks reasonably small, fingers crossed.

[0101]

This looks really good! I installed it now and will be trying it out.

Wonder if we could come up with some meaningful tests for it. The ProjectWorkflowBuilder produces an Async workflow which can be executed with RunSynchronously (which happens by default) or any other means (specifying autoStart=false). And it can be run either with TransparentCompiler or IncrementalBuilder. We'd just have to come up with a scenario that would stress the diagnostic system somewhat.

[majocha]

NodeCode test we have does it to some extent. There are also some AsyncMemoize tests and BuildGraph tests using DiagnosticsThreadStatics, but a dedicated test would be good.

[majocha]

I'm also working on removal of node from the code base, but I'm hitting the same problem that showed up in this PR:
CI grinds to a halt while locally all tests are fine.
I have a suspicion that I'm trying to test now.

[vzarytovskii]

@0101 does this test failure ring a bell by any chance?

https://dev.azure.com/dnceng-public/public/_build/results?buildId=550637&view=ms.vss-test-web.build-test-results-tab&runId=13090916&resultId=100659&paneView=debug

I recall seeing something similar. If it's just flaky, then we have to either figure out what's going on with it or disable it.

[0101]

@0101 does this test failure ring a bell by any chance?

https://dev.azure.com/dnceng-public/public/_build/results?buildId=550637&view=ms.vss-test-web.build-test-results-tab&runId=13090916&resultId=100659&paneView=debug

I recall seeing something similar. If it's just flaky, then we have to either figure out what's going on with it or disable it.

Yeah it does. If we had merged this #16010 then we'd see what's missing there.

[majocha]

I think before we use this, we must carefully think through and test how this behaves in parallel execution. The one initial test failure in MultiProjectAnalysisTests is indicative of different behavior and although I fixed it in-place, it doesn't fix that behavior in general.

It's possible we need to add something like ExecutionContext.SuppressFlow to any Async.Parallel invocations.

[majocha]

The problems are sorted out in #16645. We can either take this one or just go with #16645.

[T-Gro]

I propose to close this PR and continue with #16645 only.