Some calls to FCS stops working

[Krzysztof-Cieslak]

I've been trying to investigate ionide/ionide-vscode-fsharp#313. Long story short after using FSAC for a while some requests (autocomplete, tooltips) stops working. As far as I understand issue was there for quite a long time, but only recently I was able to "reproduce" it on my machine.

I've been running FSAC in debug mode to get some additional logging (both FSAC and FCS) and got following results:

• Normally, when tooltips are working FCS is logging reactor operation GetToolTipText and returns result:

• When FSAC "hangs" we still are able to parse file and get errors etc (and all reactor operations are logged by FCS). But when FSAC tries to get tooltips or completions... nothing happens. Nothing is logged by FCS, and operation returns default value FSharpToolTipText []. Following gif shows this behavior

Sorry for lack of good reproduction, but I don't have it yet. Will try to debug it more later today / tomorrow, but if anyone has any ideas of the top of the head I'd be grateful.

[dsyme]

@Krzysztof-Cieslak That's very odd - particularly that nothing is logged by FCS - no reactor thread operation

Will definitely need to pin down a consistent repro though...

[Krzysztof-Cieslak]

I've managed to build FCS at last, so I can do some more debugging (but I guess will need some directions)

When FCS "hangs" it hits https://github.com/fsharp/FSharp.Compiler.Service/blob/master/src/fsharp/vs/service.fs#L2032

[dsyme]

@Krzysztof-Cieslak Yeah I was wondering if it was that

However I don't understand why/how that reference count is going to zero. For example there's an increment when the FSharpCheckFileResults object gets created and a decrement is here:

    override info.Finalize() = dispose() 

So how can the reference count on the builder go to zero in between? There must be a bug somewhere else in the increment/decrement logic on these reference counts.

If you can find a repro that is a direct set of calls to the FCS API that would be ideal. But any details about how to generate a repro would be great.

[Krzysztof-Cieslak]

https://github.com/fsharp/FSharp.Compiler.Service/blob/b95f6fa386405ffba0cae9e3d6d60302dcaf2a2c/src/fsharp/vs/IncrementalBuild.fs#L1667-L1677

IncrementUsageCount and DecrementUsageCount are not atomic, maybe there is some race condition somewhere?

FSAC / Ionide does some operations in parallel such as:

• Parsing projects on file save to get cross project errors - https://github.com/ionide/FsAutoComplete/blob/master/src/FsAutoComplete.Core/CompilerServiceInterface.fs#L260-L263
• Ionide sends multiple GetTooltip requests at same time to obtain signatures for code lenses after each file parsing.

(Race condition would explain why I can't find any pattern for reproducing it. )

[Krzysztof-Cieslak]

Here's the gist containing whole log of one of my last debugging sessions: https://gist.github.com/Krzysztof-Cieslak/83ea759d4bf8c0dba5ceec11a59456bd. I've also added some additional logging (printing out IncrementUsageCount, DecrementUsageCount operations, and state of counter)

For sake of clarity I've removed long series of Exception thrown: 'Microsoft.FSharp.Compiler.ErrorLogger.UnresolvedPathReferenceNoRange' in FSharp.Core.dll and Exception thrown: 'System.Exception' in FSharp.Core.dll logs since, as far as I understand they're loged beacuse I'm running in Debug mode.

I don't fully understand yet how this part of FCS works...so this tells me nothing...

[Krzysztof-Cieslak]

As for "reproduction" - I'm able to reproduce it pretty consistently by doing lot of random operations (file edits, file saves) on https://github.com/fsharp-editing/FSharp.Editing/blob/master/src/FSharp.Editing.Messages/Serialization.fs

[dsyme]

@Krzysztof-Cieslak Thanks so much for continuing to dig into this.

It could be the race condition, certainly. Though the window for the race is very small.

The log is getting much closer to what we need. Could you add some more diagnostics, e.g.

• for each increment/decrement show the GetHashCode reference object identity of the IncrementalBuilder and perhaps some data such as the project file name
• for each increment/decrement show something about the call stack - either a string passed explicitly from the caller or the actual call stack top 7 entries

Also the log doesn't actually show any reference counts going to zero, which I would expect. Did you put the debug assert when the reference count goes to zero? Having the count go to zero isn't actually an indicator of a bug - though subsequent access is

[Krzysztof-Cieslak]

It's FCS's debug assert - assertNotDisposed() called in IncrementUsageCount and DecrementUsageCount before changing counter (https://github.com/fsharp/FSharp.Compiler.Service/blob/b95f6fa386405ffba0cae9e3d6d60302dcaf2a2c/src/fsharp/vs/IncrementalBuild.fs#L1667-L1677) - which means assertion is hit during next call after builder got disposed (counter got to 0) .

I'll post updated logs later today.

[dsyme]

@Krzysztof-Cieslak I see, thanks, so

FsAutoComplete.Suave.exe Information: 0 : Usage counter disposed

means the counter was decremented and hit zero. (If you could add a link to the commit with the logging added inn the comments of the logging gists that would be helpful)

I'm still confused by this. There's clearly a race condition somewhere - not necessarily a multi-threaded race condition between the update, but perhaps a window between when a builder is fetched from the cache and when its usage count is updated (and in between the cache entry is evicted and disposal happens), e.g. in between getOrCreateBuilder and IncrementalBuilder.KeepBuilderAlive here:

            let! builderOpt,creationErrors,_ = execWithReactorAsync <| fun ctok -> getOrCreateBuilder (ctok, options)
            use _unwind = IncrementalBuilder.KeepBuilderAlive builderOpt

But we really need extra the logging I mentioned to see the sequence of operations and their causes a bit more clearly.

Thanks again - there are a couple of bugs in the visualfsharp repo which look like they may have the same root cause, so I really want to get to the bottom of this.

[Krzysztof-Cieslak]

Uploaded new gist with additional information - HashCode of builder, Project name and stack trace for each IncrementUsageCount and DecrementUsageCount - https://gist.github.com/Krzysztof-Cieslak/83ea759d4bf8c0dba5ceec11a59456bd (file is huge, so it's truncated by GitHub - you need need to click view the full file)

Here's my commit adding logging - https://github.com/Krzysztof-Cieslak/FSharp.Compiler.Service/commit/1209a44f8a1a308dad72aaeb80bc2eb284443922?w=1

[dsyme]

Looking at this... how on earth do we get "Current state: 0" followed by "Current state: 4" on the same builder???

FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter disposed
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter decremented. Current state: 0, ProjectName: FSharp.Editing.Messages
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter disposed
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter decremented. Current state: 4, ProjectName: FSharp.Editing.Messages
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter disposed

[dsyme]

@Krzysztof-Cieslak I suppose those messages aren't particularly in order due to concurrent execution. For example when incrementing we have

FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter decremented. Current state: 3, ProjectName: FSharp.Editing.Messages
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter incremented. Current state: 7, ProjectName: FSharp.Editing.Messages
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter incremented. Current state: 7, ProjectName: FSharp.Editing.Messages
FsAutoComplete.Suave.exe Information: 0 : Builder: 12549444. Usage counter incremented. Current state: 9, ProjectName: FSharp.Editing.Messages

which is just all over the place. It's hard to tell what the before/after state of the increment/decrement operations actually were, since other threads may have jumped in between in the logging process

Anyway could you try just making the reference count state thread safe (Interlocked increment/decrement) and see if the problem goes away? thanks

[Krzysztof-Cieslak]

My anecdotal experience suggest that using increment/decrement from System.Threading.Interlocked solves problem - here's patch: master...Krzysztof-Cieslak:incremental_builder_atomic_counter

I'm not able to reproduce problem on the file I've used for testing (https://github.com/fsharp-editing/FSharp.Editing/blob/master/src/FSharp.Editing.Messages/Serialization.fs) and before the patch I was able to crash it pretty fast with spamming random operations.

On the one hand I don't have any "reliable" reproduction, so can't test it 100% accurately... on the other, I'd need to be super lucky today, and changing it to Interlocked operations doesn't have many drawbacks so maybe it's worth merging.