100% CPU usage with AlternateNumberFormat plugin

[Philonous]

After upgrading haskell-language-server to b7949aa I noticed that it used 100% CPU while staying otherwise responsive. I found this in the logs

2021-12-14 13:33:11.542240523 [ThreadId 8807] INFO hls:	finish: AlternateNumberFormat.CollectLiterals (took 1m32s)
2021-12-14 13:33:11.542255151 [ThreadId 975] DEBUG hls:	"Literals: [IntLiteral SrcSpanOneLine \"/home/phil/projects/nejla/app/backend/src/Handlers/Job.hs\" 173 27 34 \"1000000\" 1000000,IntLiteral SrcSpanOneLine \"/home/phil/projects/nejla/app/backend/src/Handlers/Job.hs\" 259 13 14 \"0\" 0,IntLiteral SrcSpanOneLine \"/home/phil/projects/nejla/app/backend/src/Handlers/Job.hs\" 260 55 56 \"1\" 1]"

• The mentioned line is just a threadDelay 1000000 and haskell-language-server seems to produce one of these log lines every few minutes for a different literal in my code base.
• It's a 350 line module in a medium-sized project (14kloc)
• Light use of Template Haskell and QuasiQuotes (some $logDebugs and quotes for string interpolation)
• No NumericalUnderscores

Unfortunately I can't link the code since it's proprietary.

Your environment

Which OS do you use:
NixOS

Which lsp-client do you use:
emacs with lsp-mode
Describe your project (alternative: link to the project):
stack.yaml

Steps to reproduce

Run haskell-language-server on my project as normal

Expected behaviour

0% CPU usage after initial setup

Actual behaviour

100% CPU usage permanently (or at least multiple hours)

Include debug information

I don't have access to the machine right now but I'll reproduce them if required.

Execute in the root of your project the command haskell-language-server-wrapper --debug . and paste the logs here:
(if you are using the vscode extension check the executable location here)

Debug output:

<paste your logs here>

Paste the logs from the lsp-client, you can check instructions about for VS Code here

LSP logs:

<paste your logs here>

[pepeiborra]

Does the CPU abuse go away if you disable the plugin?

[Philonous]

I wanted to try that but I couldn't find a way to accomplish it; apparently the only way to disable plugins is by changing a setting in the client. However, emac's lsp-mode doesn't have a toggle for this plugin (presumably since it's not released yet).

[Ailrun]

@Philonous You can disable the plugin somewhat manually as in this issue or this PR. You need to change haskell.plugin.alternateNumberFormat.globalOn.

[jneira]

Many thanks for the report, would be good to fix it before release the plugin (if we confirmed the plugin is the responsible)

// @drsooch

[drsooch]

This is new for me. The RefineImports one happens very rarely but I can reproduce the AlternateFormat line more often. I don't think I ever had a problem with greater than 0.01s, but I will rollback my local tonight to see if I can find a difference.

Created a new file and was greeted with this:

EDIT:

I'd for now assume it's the plugin. I'm in the process of trying to track down any delta. If I had to guess the SYB parsing has drastically reduced performance.

In the meantime, @Philonous, do you see something similar happening for RefineImports? Maybe not as bad as AlternateFormat but does it take > 1s?

[drsooch]

So taking a look, it seems as though it is related to the SYB package introduced in 71f1d4c95. This commit (I'm not sure if it exists in the main branch, it's on alternate-number-format in my fork) extends SYB to traverse the entire AST. prior to this commit it did a naive traversal which didn't capture every literal.

@fendor I'm not sure how well versed you are with SYB, but if you know of any tricks to possibly speed this up. That would be great.

I was unable to replicate the 100% cpu usage for hours at a time, I imagine if I was coding full time maybe I'd experience it but, wasn't able to duplicate.

[pepeiborra]

The Tactics plugin also uses SYB, even HLS itself uses SYB for various things, so I'm not convinced this is the problem.
The issue is more likely to be around caching and efficiency:

1. After an edit, only the current file should be rescanned right? Did you check that?

2. the scan should not perform any conversions, those should be delayed until the user requests them. Is that the case already?

[Philonous]

• I can confirm that the problem (100% CPU usage for a long time) goes away when I run (lsp-register-custom-settings '(("haskell.plugin.alternateNumberFormat.globalOn" :json-false)))
• I looked for additional instances of long-running plugins and found multiple instances of
  • RefineImports (took 3.21s)
  • QualifyImportedNames.TypeCheck (took 3.38s)
  • Wingman.judgementForHole.GetHieAst (took 3.36s)
  • Wingman.judgementForHole.GetHieAst (took 3.17s)
• However, all of them happen before InitialLoad and none of them are longer than a couple of seconds, so it's not a problem for me in any case.

Thanks for looking into this!

[drsooch]

The Tactics plugin also uses SYB, even HLS itself uses SYB for various things, so I'm not convinced this is the problem. The issue is more likely to be around caching and efficiency:

1. After an edit, only the current file should be rescanned right? Did you check that?

2. the scan should not perform any conversions, those should be delayed until the user requests them. Is that the case already?

1. I'm not sure? I believe it's only the file that is changed gets scanned. Is there a way to check that explicitly? -- I naively tested it and it seems to only rescan the file currently being worked on.
2. The scan only performs conversion in the codeActionHandler It should only convert literals that are in the current codeAction range.

In the commit I referenced, it is technically half-working. That SYB parser only captures a small portion of Literals. I still am not sure why it does that, but I updated it to look for more patterns and that seemed to do the trick (at the cost of performance).

collectLiterals' :: (Data ast, Typeable ast) => ast -> Set Literal
collectLiterals' = everything (<>) (mkQ2 (S.empty :: Set Literal)  traverseLExpr traverseLPat)

-- Located Patterns for whatever reason don't get picked up when using `(mkQ (S.empty :: Set Literal) traverseLExpr)
-- as such we need to explicit traverse those in order to pull out any literals
mkQ2 :: (Typeable a, Typeable b, Typeable c) => r -> (b -> r) -> (c -> r) -> a -> r
mkQ2 def left right datum = case cast datum of
        Just datum' -> left datum'
        Nothing     -> maybe def right (cast datum)

You'll notice the use of a Set as with the addition of the second pattern duplicates began showing up (a lot of duplicates) I should've realized that would case a performance drop... I feel silly for not really noticing it earlier.