search

haskell / vscode-haskell

VS Code extension for Haskell, powered by haskell-language-server
https://marketplace.visualstudio.com/items?itemName=haskell.haskell
Other
561 stars 90 forks source link

Slowdown in `stack test` when VSCode is running #274

Closed pjonsson closed 4 years ago

pjonsson commented 4 years ago

I'm not sure where to submit this issue so please move it to the correct component.

Recently stack test on my tasty tests started to take 20+ seconds instead of the regular 7-8 seconds when using VSCode. It does not matter if I run stack test in the integrated terminal in VSCode or a separate terminal, the runtime is still the same. If I close VSCode the test time goes back down to 7-8 seconds. I am not sure what changed, I got an automatic update to 0.2.2 a few days ago and then to 0.3.0 this morning.

I have the CPU usage on the bar at the bottom of the screen in VSCode and I can see that I use more than 25% CPU on a 4 core CPU when I run my tests so something is running in parallel. If I close down VSCode and change ghc-options: -threaded -with-rtsopts=-maxN4 to ghc-options: -threaded -with-rtsopts=-maxN1 for my testsuite in the cabal file, running the tests single-threaded takes 13 seconds.

lukel97 commented 4 years ago

Is the "Processing x/y" message visible in the status bar in VS Code when you are running stack test? Could be that ghcide/hie-bios is doing some setup or type checking in the meantime

pjonsson commented 4 years ago

No, the "Processing x/y" is usually not there. The performance is unfortunately 100% repeatable, even if I run stack test 3 times in a row without leaving the terminal between them I get the same numbers. I have also tried configuring the plugin to only perform checks on file save and that gave me a better experience when typing but it did not change the performance when running tests.

This is all a big black box to me and I'm very happy with that but it's hard to narrow things down for you. My hie-8.8.3 binary that I was using before the automatic binary download was added to the plugin was built from commit a9005b2ba2050bdfdd4438f1d471a3f7985492cd of haskell-ide-engine.

lukel97 commented 4 years ago

Ah, in the output log can you confirm that the server that vs code is running is indeed haskell-ide-engine? Forgot to mention, the output log is in the output window of vscode and there is a dropdown menu you can select for the haskell extension

pjonsson commented 4 years ago

I don't understand the details and differences of servers so I have left that setting as it came. Here is what the log you mention starts with after a fresh start of VSCode:

[client] debug command: "/home/pj/.config/Code/User/globalStorage/haskell.haskell/haskell-language-server-0.3.0-linux-8.8.4 --lsp"
[client] server cwd: undefined
haskell-language-server version: 0.3.0.0 (GHC: 8.8.4) (PATH: /home/pj/.config/Code/User/globalStorage/haskell.haskell/haskell-language-server-0.3.0-linux-8.8.4) (GIT hash: d36bb9929fdd0df76f86d3635067400272f68497)
Starting (haskell-language-server)LSP server...
  with arguments: LspArguments {argLSP = True, argsCwd = Nothing, argFiles = [], argsShakeProfiling = Nothing, argsTesting = False, argsExamplePlugin = False, argsDebugOn = False, argsLogFile = Nothing, argsThreads = 0, argsProjectGhcVersion = False}
  with plugins: [PluginId "brittany",PluginId "eval",PluginId "floskell",PluginId "fourmolu",PluginId "ghcide",PluginId "ormolu",PluginId "pragmas",PluginId "retrie",PluginId "stylish-haskell"]
  in directory: /home/pj/<source directory>
If you are seeing this in a terminal, you probably should have run ghcide WITHOUT the --lsp option!
 Started LSP server in 0.01s

After that there are two lines of "Opened a text document: .." for the two documents that are visible on my split editor followed by:

CallStack (from HasCallStack):
  error, called at ./Data/HashMap/Internal.hs:753:16 in unordered-containers-0.2.12.0-2e3fe165d2481c3a755449eca3083a286519fe98ac20523b8f479e0645004f51:Data.HashMap.Internal
  !, called at src/Development/IDE/Import/DependencyInformation.hs:107:40 in ghcide-0.2.0-inplace:Development.IDE.Import.DependencyInformation
2020-08-12 10:10:38.719447447 [ThreadId 86] - Data.HashMap.Internal.(!): key not found
CallStack (from HasCallStack):
  error, called at ./Data/HashMap/Internal.hs:753:16 in unordered-containers-0.2.12.0-2e3fe165d2481c3a755449eca3083a286519fe98ac20523b8f479e0645004f51:Data.HashMap.Internal
  !, called at src/Development/IDE/Import/DependencyInformation.hs:107:40 in ghcide-0.2.0-inplace:Development.IDE.Import.DependencyInformation

and then it's setting up the cradle. After the Cradle there's this:

2020-08-12 10:10:48.857015292 [ThreadId 3241] - Using interface files cache dir: /home/pj/.cache/ghcide/main-e002e13e0432ca289295dc6b53b659acaa3930c5
2020-08-12 10:10:48.857276918 [ThreadId 3241] - Using interface files cache dir: /home/pj/.cache/ghcide/main-e002e13e0432ca289295dc6b53b659acaa3930c5
2020-08-12 10:10:48.8573545 [ThreadId 3241] - Making new HscEnv[main,main]
2020-08-12 10:10:58.139427795 [ThreadId 5076] - finish: InitialLoad (took 8.82s)
2020-08-12 10:10:58.147698907 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.148004545 [ThreadId 5076] - finish: CodeAction (took 0.00s)
2020-08-12 10:10:58.156098872 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.164011015 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.172029754 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.179876862 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.187885415 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.195741264 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.203646846 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.211442542 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.219244424 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.226914673 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.235126353 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.2430943 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.250794926 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.258485352 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.266240918 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.274247971 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.282088782 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.289952928 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.297914633 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.305721842 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.313403164 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.321167277 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.328895084 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.336564391 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.344238139 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.351931446 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.3595626 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.367271733 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.37519778 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.382703203 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.390514411 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.398265482 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.405986713 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.413649576 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.421612674 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.429503231 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.437322523 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.445146295 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.45316025 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.461754856 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.470233984 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.478105811 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.486560522 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.494759062 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.503369322 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.511568299 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.519536502 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.52748127 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.535392807 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.543247778 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.551101036 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.55882184 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.566617325 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.574454489 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.58227281 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.589940099 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.597607361 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.605367533 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.613028833 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.620707783 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.6284559 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.636188894 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.643852585 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.651612061 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.659367274 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.667122188 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.674929656 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.682731528 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.690784149 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.699021783 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.707837558 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.715825873 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.723946531 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.731892474 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.740336713 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.74857414 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.756540854 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.764998078 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.773357119 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.78229486 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.790423874 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.799162715 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.807922054 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.81664271 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.825481994 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.83371702 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.841674341 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.849687042 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.857865617 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.866184662 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.874444903 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.882687482 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.890622921 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.898562159 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.906614367 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.914487985 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.922481755 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.930312534 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.938168768 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.945993401 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:58.953817081 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.038303615 [ThreadId 5076] - finish: InitialLoad (took 0.08s)
2020-08-12 10:10:59.046441412 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.054520505 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.062817937 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.07154293 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.08085741 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.090121094 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.100404187 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.110431921 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.119230368 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.127745477 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.137875145 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.146313915 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.154846644 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.16284636 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.171578764 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.179727295 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.18865776 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.197337579 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.20629938 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.215207314 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.224449907 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.233557085 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.242991875 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.252539786 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.261417146 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.270786757 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.279796185 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.288606674 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.297301174 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.305970098 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.314365544 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.323205223 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.331802259 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.340635283 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.348868037 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.357589109 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.366007225 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.375347463 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.386745674 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.395794777 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.405331542 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.414073343 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.424423848 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.433515587 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.442034241 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.450661301 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.458988674 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.46810887 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.477059772 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.485925108 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.494498362 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.502787672 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.510863898 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.518852859 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.526841601 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.534878786 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.542874875 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.550798651 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.558733813 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.566684314 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.574534147 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.582505369 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:10:59.590542292 [ThreadId 5076] - finish: InitialLoad (took 0.01s)
2020-08-12 10:11:01.344256655 [ThreadId 5081] - finish: CodeAction:PackageExports (took 1.75s)
2020-08-12 10:11:01.344484017 [ThreadId 5084] - Plugin.makeCodeLens (ideLogger)
2020-08-12 10:11:01.344728211 [ThreadId 5087] - Plugin.makeCodeLens (ideLogger)
2020-08-12 10:11:01.344810608 [ThreadId 5081] - finish: codeLens (took 0.00s)
2020-08-12 10:11:01.344934317 [ThreadId 5081] - finish: codeLens (took 0.00s)

and then it's quiet. I dragged my mouse over something and got "Hover request at position .." so I moved my mouse to the output area, switched to a terminal outside of VSCode and ran the tests. The slowdown remains and there are no additional lines printed to the log when running the tests.

pjonsson commented 4 years ago

This turned out to be the file watcher in MS C/C++ IntelliSense plugin reacting to the output files from the tests. The Haskell plugin was just an innocent bystander that happened to be updated around the time the problem appeared, it did not cause it.