Performance: adding an import retriggers a long "Processing"

[guibou]

Your environment

Which OS do you use? Linux / NixOS
Which version of GHC do you use and how did you install it? GHC 9.10.1, installed using nix/nixpkgs.
How is your project built (alternative: link to the project)? A custom build system based on nix.

Which LSP client (editor/plugin) do you use? Neovim builtin lsp
Which version of HLS do you use and how did you install it? 2.9.0.0
Have you configured HLS in any way (especially: a hie.yaml file)?

My hie.yaml contains:

cradle:
  bios:
    shell: "nix run .#haskell_hie_bios"

And the nix target haskell_hie_bios lists all the required build flags used by GHC to build one monolithic packages composed of 1089 modules. It also contains the listing of the 1089 modules, eg:

-XFoo
-XBar
-ipath/to/src
-ipath/to/src2
-ffoo
path/to/src/Module/Module.hs
path/to/src2/Module2/Module2.hs

Steps to reproduce

I don't know how to reproduce that outside of our large codebase, but what do I observe:

• I've turned --debug --log /path/to/a/file.log
• I start my editor (neovim, note that my collegues using vscode observes the same problem), load a file (for the example, I loaded a file which is at the end of the dependency tree, it contains a main function and no other module depends on that module).
• After a bit of time, I can see:

2024-11-02T08:45:19.194755Z | Debug | Finished: C:GetHieAst:/home/guillaume/jinko/jinko/simwork/core-webservice/app/Local/Main.hs Took: 2m34s

In the log.

• I can edit my file, do some change, that's super reactive. I can add function, hover for documentation, go to definition, everything is smooth and fast. Code action works fine, everything works great.
• If I go to the top of the module, import section, I can add/remove symbols in the currently existing imported module, but if I add (or remove) an import statment, it starts Processing for a long time. For example, after adding import Data.Functor on top of my file, I can see Processing and Indexing (and actually, a few, sometime 2 or 3 Processing) and for a few seconds, HLS is not reactive anymore. Here is the message in the log:

2024-11-02T08:48:35.124980Z | Debug | Finished: C:GetHieAst:/home/guillaume/jinko/jinko/simwork/core-webservice/app/Local/Main.hs Took: 36.24s
2024-11-02T08:48:35.125044Z | Debug | Finished: C:GetHieAst:/home/guillaume/jinko/jinko/simwork/core-webservice/app/Local/Main.hs Took: 36.24s
2024-11-02T08:48:35.125125Z | Debug | Finished: C:GetHieAst:/home/guillaume/jinko/jinko/simwork/core-webservice/app/Local/Main.hs Took: 36.24s

(I'm surprised by the 3 lines of log. but note the 36s.). Note that there may be another problem with my setup or with HLS because 36s is a really long time, but the original problem is that I'm wondering why it is "re-processing" everything.

Expected behavior

Should not Processing for 40s when I had an import. I can understand that it may invalidate the build tree by adding an import, but this file being at the End of the build hierarchy, no module depends on it, so it is surprising.

Debug information

Sorry, I'm opening this issue without much details, in order to start tracking the problem. I'll try to investigate a bit more (especially, it looks like the issue is new at work, so I may be able to find which update triggered it.)

[guibou]

I've bisect our codebase and the problem appeared when upgrading to GHC 9.10 (same version of HLS in both cases).

Do you know how I can evaluate if:

• HLS is doing something different because of the different GHC version, and this something different is slow
• HLS is doing the same thing, but this is now slow with a different ghc version

The log with --debug roughly gives the same information, a Finished: C:GetHieAst, but without much more details.

[fendor]

Generally, it can be rather tricky to identify changes in behaviour across GHC versions... Maybe the open telemetry support we have is useful, see https://haskell-language-server.readthedocs.io/en/stable/contributing/contributing.html#tracing.

[alexmccord]

I ran into a similar problem when starting a new project, and I think this is caused by a mismatch in cabal and stack's build cache. If I modify my package.yaml (which seems to require restarting extension host to reload HLS) and run stack build without running cabal build, then HLS will get stuck at processing. If this is not the same exact issue, I can open a new one.

I have HLS 2.9.0.1, GHC 9.10.1, Stack 3.1.1, Cabal 3.12.1.0, all installed through GHCup. I have no hie.yaml in my project. This happens on Windows 11, and I am using the VSCode extension.

[fendor]

As cabal and stack don't share any build caches, this is almost certainly a different issue.

Please open another issue, and include the information obtained by following the steps here: https://github.com/haskell/vscode-haskell?tab=readme-ov-file#investigating-and-reporting-problems

[guibou]

@alexmccord note that it seems different, but I also observed infinite "Processing" since moving to GHC 9.10, but I had never really be able to understand / track / reproduce it. Most of the time, I restart the lsp, and/or clean the different caches and I'm good again. Sometime I think I had just let HLS run for hours (got bored, decided to leave for a hike) and when back, it was done. So may not be a "lock", but something really long.

Anyway, as @fendor said, maybe another (linked?) issue.

[michaelpj]

I have also observed this. I wonder if the change to the imports is causing us to invalidate an excessive amount of state somehow?

[guibou]

I have also observed this. I wonder if the change to the imports is causing us to invalidate an excessive amount of state somehow?

Do you confirm that it only happen with GHC 9.10? Or did you observed it with another version of GHC and perhaps there are two issues: the invalidation (all ghc versions?) and GHC 9.10 performance regression somewhere else?

[guibou]

I've opened https://github.com/haskell/haskell-language-server/tree/repro_4443 which is a repro of this problem.

The test_invalidation cabal package at the root of the hls worktree contains two modules: MyLib and Lib2.

MyLib is kinda simple and takes 10s to compile:

{-# LANGUAGE TemplateHaskell #-}                                                              
module MyLib (i) where                                                                        
import Control.Concurrent (threadDelay)                                                       
import Language.Haskell.TH.Syntax                                                             
                                                                                              
-- | This code generates a super simple integer, but waits for 10s during                     
-- compilation                                                                                
i = $(do                                                                                      
  runIO (threadDelay 10000000)                                                                
  [e|5|])

It uses TemplateHaskell so that's a specificity. I would like to come with a simpler implementation which takes time to build, but I'm not too sure how to craft that (unless copy pasting a lot of code). I've tried to do type level computation (such as computing Fibonnaci at type level, but looks like GHC is smart enough to keep these type "lazy". Anyway.

The second module, Lib2 contains:

module Lib2 where                                                                             
                                                                                              
import MyLib                                                                                  
import Data.Functor ()                                                                        
                                                                                              
blurk = 20

With suffisant warnings set (-Wall, this module complains about missing signature, things like that.

Once HLS is fully loaded (after a minimum of 10s, when the warning are displayed), just remove the import Data.Functor () line and see how it takes 10s again.

This is perfectly reproducible here, with one gotcha (And I thought I was completly mad): I need to have both Lib2 and MyLib opened in my editor for the complete reevaluation to proceed. If only Lib2 is opened, nothing is happening.

By the way, I'm using neovim.

Next tasks:

• Test with vscode if the same behavior appears
• Test that with a GHC different than 9.10 in order to confirm that this is an issue with GHC 9.10 only.

[guibou]

Same problem with VScode.

Here is a "short" video showing the issue.

hls_invalidation-2024-12-31_22.49.55.mp4

[guibou]

(by the way, I'm using current HLS f09500b)

[guibou]

I'm currently building with ghc 9.8 in order to confirm if ghc version is involved or not. (I'm starting to have doubt, I initially documented that the problem started to appear when we bumped ghc version to 9.10, but maybe because the problem seems to be only reproducible when other files are opened, maybe my bisect session on our codebase was "incorrect").

In the meantime, does this rings a bell to one of you? I've promised to one day take the time to dig in HLS code in more depth, but that's not a promise I'll validate on 2024 (well, I still have 1 hour left... ;) Happy new year when you'll read this message).

A few questions:

• Why adding import / language pragma do trigger an invalidation, but adding some top level bindings does not. I can understand that import may have global effects (type classes) and hence may trigger an invalidation, but I would have bet on the module which depends on the modified files, not the module on which the modified files depends.
• Why having some files opened (I should experiment more in order to understand if there are some specificity on the files which are reevaluated) triggeres a reevaluation of dependencies of the currently modified file. I would bet that "opened files" are tracked with a special state in the dependency graph and that maybe something is incorrect here.

[guibou]

The problem also happen with GHC 9.8 and the repro code I pushed. I will check on my huge / propriotary codebase that I did something wrong when tracking it, but that's really interesting, because that's a bug in HLS and not a bug in ghc.

I'll try to bisect HLS.

[guibou]

I'll stop the investigation on our proprietary codebase, this is not as reproducible as expected, so first let's investigate and understand the "simple" repro we have here, maybe the problem we have on our big codebase is complex and is the sum of multiples bugs.

[guibou]

For the record, here is the current state of my bisect

• Bisect good: ddd16ca (14 may 2023)
• Bisect bad: 0be6fa7 (28 decembre 2023)
• 7 steps remaining.

Step for the bisect:

• Build HLS,
• start editor on Lib2.hs, confirm that I can add/remove the import Data.Functor without triggering a rebuild
• open MyLib.hs and confirm/infirm that adding/removing import Data.Functor in Lib2.hs does indeed trigger a rebuild
• close MyLib.hs and confirm that adding/removing import Data.Functor in Lib2.hs does not trigger rebuild anymore.

I'll continue tomorrow.

note: in all case, opening MyLib.hs after opening Lib2.hs did trigger a rebuild. This is surprising because we could hope that MyLib.hs is already "loaded".

[guibou]

I've bisected to:

9effc56 is the first bad commit

commit 9effc56ef88755f968e3cb44a700f5033a83f732
Author: wz1000 <[email protected]>
Date:   Fri Aug 4 17:28:21 2023 +0530

    Share ModuleGraphs for all files (#3232)
    
    * Remove GetDependencyInformation in favour of GetModuleGraph.
    
    Computing and storing GetDependencyInformation for each file essentially individually means
    that we perform downsweep on each file individually, wasting a lot of work and using an excessive
    amount of memory to store all these duplicated graphs individually.
    
    However, we already have the `GetModuleGraph` rule, which we need to compute before compiling
    files any way due to being depended on by `NeedsCompilation`, which needs to know if any reverse
    dependencies of the module we are compiling requires TH, which meant that each file already depends on
    the results of downsweep for the whole project.
    
    Instead, we can compute the whole graph once when we execute the `GetModuleGraph` rule and even use this inside `HscEnv.hsc_mod_graph` to avoid reconstructing the `ModuleGraph` on each invocation of `GhcSessionDeps`.
    
    There may be concerns about excessive build churn due to any change to the result of `GetModuleGraph`
    invalidating the result of `GhcSessionDeps` too often, but note that this only happens when something
    in the header of a module changes, and this could be solved easily be re-introducing
    a version of `GetDependencyInformation` with early cutoff that essentially returns the result of `GetModuleGraph`
    but includes the hash of only the `ModSummary`s in the downward dependency closure of the file.
    
    * module graph early cutoff
    
    early cutoff for eval plugin
    
    * allow running benchmarks on examples generated via a script
    
    * Add new benchmarks to config
    
    * Allow pathToId to fail
    
    * Errors
    
    ---------
    
    Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

 bench/MultiLayerModules.sh                                 |  34 +++++++++++++++++++++++++++++
 bench/config.yaml                                          |  45 ++++++++++++++++++++++++++++++++++++++
 ghcide-bench/src/Experiments.hs                            |  56 +++++++++++++++++++++++++++++++++++++----------
 ghcide-bench/src/Experiments/Types.hs                      |  33 +++++++++++++++++++++++-----
 ghcide/src/Development/IDE/Core/Compile.hs                 |  63 ++++++++++++++++++++++-------------------------------
 ghcide/src/Development/IDE/Core/RuleTypes.hs               |  14 ++----------
 ghcide/src/Development/IDE/Core/Rules.hs                   | 148 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---------------------------------------------
 ghcide/src/Development/IDE/GHC/Orphans.hs                  |   4 ++++
 ghcide/src/Development/IDE/Import/DependencyInformation.hs |  49 ++++++++++++++++++++++++++++-------------
 plugins/hls-eval-plugin/hls-eval-plugin.cabal              |   1 +
 plugins/hls-eval-plugin/src/Ide/Plugin/Eval/CodeLens.hs    |  36 +++++++++++++++---------------
 plugins/hls-eval-plugin/src/Ide/Plugin/Eval/Rules.hs       |  32 +++++++++++++++++----------
 plugins/hls-eval-plugin/src/Ide/Plugin/Eval/Types.hs       |  12 ++++++++--
 13 files changed, 363 insertions(+), 164 deletions(-)
 create mode 100755 bench/MultiLayerModules.sh

Ping @wz1000, the comment

There may be concerns about excessive build churn due to any change to the result of `GetModuleGraph`

invalidating the result of `GhcSessionDeps` too often, but note that this only happens when something
in the header of a module changes, and this could be solved easily be re-introducing
a version of `GetDependencyInformation` with early cutoff that essentially returns the result of `GetModuleGraph`
but includes the hash of only the `ModSummary`s in the downward dependency closure of the file.

Is especially interesting in the current situation.

[guibou]

I've read a bit the comments / discussion on #3232 which lead to this refactoring and a few additionnal informations:

a) There are two algorithm for dependency detection, one requires to load ALL modules first, the other can do it on the fly. Depending on the size of the codebase and multiples details, one or the other can be more performant.
b) The logic for template haskell is super complex, because a module using template haskell must have access as dynamic object to all its dependencies, this takes memory, and also triggers invalidation. I tried to disable (replace by dummy content) all of our template haskell uses cases in our codebase and suddently HLS started to be way way faster and invalidation happen a lot less. (Note: this is not a critic of HLS, I just realized how template haskell is so much more complex than I initially expected).