uom frequently results in check on save looping indefinitely

[oeed]

IDE: VS Code

In some of my projects when check on save runs RA will frequently hang on checking indefinitely (or at least as long as I've had the patience to leave it). After quitting the RA process it'll check just fine. It doesn't always happen, some sessions it happens almost every save, others hardly at all.

The main commonality I've found between projects is the use of uom which I know has seen some issues. I've done my best to try and isolate and debug the issue, but I need further help; so if anyone has suggestions for things to try I'm all ears.

I've tried collecting samples, spindumps and logs with RA_LOG=info and CHALK_LOG=info. Notably, during this indefinite check the logs go so fast that the output window can't keep up.

RA Log Snippet
In the sample of output I managed to copy paste only mentions Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) the whole way through (all 97 thousand lines starting at 34106ms ending 35053ms). So I suspect it's getting stuck. Here's a small snippet of that:

[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: ParseMacroExpansionQuery(MacroFile { macro_call_id: MacroCallId(22104) }): returning memoized value changed at R10290    
├─34106ms INFO ParseMacroExpansionQuery(MacroFile { macro_call_id: MacroCallId(22104) }): returning memoized value changed at R10290
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: MacroArgTextQuery(MacroCallId(22104)): invoked at R10302    
├─34106ms INFO MacroArgTextQuery(MacroCallId(22104)): invoked at R10302
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: MacroArgTextQuery(MacroCallId(22104)): returning memoized value changed at R10290    
├─34106ms INFO MacroArgTextQuery(MacroCallId(22104)): returning memoized value changed at R10290
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: HygieneFrameQuery(HirFileId(FileId(FileId(1829)))): invoked at R10302    
├─34107ms INFO HygieneFrameQuery(HirFileId(FileId(FileId(1829)))): invoked at R10302
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: HygieneFrameQuery(HirFileId(FileId(FileId(1829)))): returning memoized value changed at R1    
├─34107ms INFO HygieneFrameQuery(HirFileId(FileId(FileId(1829)))): returning memoized value changed at R1
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: HygieneFrameQuery(HirFileId(MacroFile(MacroFile { macro_call_id: MacroCallId(22103) }))): invoked at R10302    
├─34107ms INFO HygieneFrameQuery(HirFileId(MacroFile(MacroFile { macro_call_id: MacroCallId(22103) }))): invoked at R10302
[INFO salsa::derived::slot] solve_goal{goal=UCanonical { canonical: Canonical { value: InEnvironment { environment: Env([]), goal: Implemented(HydraulicGraph<[?0 := _Builder<[]>]>: Deref) }, binders: [] }, universes: 1 }}: HygieneFrameQuery(HirFileId(MacroFile(MacroFile { macro_call_id: MacroCallId(22103) }))): returning memoized value changed at R10290

Process Sample Snippet
Every time I've sampled it always seems to be spending all its time in chalk_recursive::solve:

...
    2660 chalk_recursive::solve::SolveIteration::solve_iteration::hdb72846378521f71  (in rust-analyzer) + 4061  [0x1035b223d]
        1533 chalk_recursive::fulfill::Fulfill$LT$I$C$Solver$GT$::solve::he3055ce5487d2cc9  (in rust-analyzer) + 2475  [0x1035ada6b]
            ...
        1124 chalk_recursive::fulfill::Fulfill$LT$I$C$Solver$GT$::solve::he3055ce5487d2cc9  (in rust-analyzer) + 1764  [0x1035ad7a4]
            ...

Next Steps?
I'm rather lost as to what would be helpful to narrow down this issue from here. I'd love to make a minimum reproduction, but I can't even tell what's causing it. It's also somewhat intermittent making debugging harder. Any guidance for how to better debug this would be great.

[oeed]

@bjorn3 any suggestions for how to debug this and find more useful information? I'm quite happy to do the work – but I need to know where to start as these logs don't provide many clues.

This issue occurs every 5 or 10 minutes and is rather frustrating as I'm sure you can imagine!

[oeed]

@matklad did you have suggestions as to how to debug this? It's impacting multiple repos now and is getting rather painful to work wth.

[flodiebold]

Possibly rust-lang/chalk#688 again. You can try running rust-analyzer analysis-stats . in the repository, and if that hangs as well remove code and items to make a minimal reproduction. (You should also be able to see on which function it hangs, if it does. If so, you can probably remove all other item bodies.)