Apparent formatter speed regression #381

mattbaker · 2020-10-11T18:55:25Z

Editing a simple .exs test file (340 lines) is taking around 3 seconds to format on save with no other edited files. I get a loading bar and a notification at bottom right mentioning the "ElixirLS: Elixir support and debugger" formatter running.

I installed 0.5.0 manually from the vsix and the problem is gone, so it looks like a regression in the latest release.

Any guesses on what happened between versions? Any particular logs or other diagnostic information can I provide to help debug?

This is an umbrella project of a fair size. Pure Elixir, so no large node_modules directories, etc.

Possible relation to #378?

Environment

Elixir & Erlang versions (elixir --version): Elixir 1.9.4 (compiled with Erlang/OTP 22)
Operating system: MacOS Mojave
Editor or IDE name (e.g. Emacs/VSCode): VSCode
Editor Plugin/LSP Client name: elixir-lsp/elixir-ls

Troubleshooting

Restart your editor (which will restart ElixirLS) sometimes fixes issues
Stop your editor, remove the entire .elixir_ls directory, then restart your editor
- NOTE: This will cause you to have to re-run the dialyzer build for your project

Logs

Wasn't sure exactly what to provide in this case but happy to include what I can.

The text was updated successfully, but these errors were encountered:

BlueHotDog · 2020-10-12T11:45:25Z

Same here :(

axelson · 2020-10-13T16:32:39Z

Do you have a sample project that exhibits this issue? And what is in your .formatter.exs inputs?

mattbaker · 2020-10-13T17:53:08Z

Unfortunately I don't have a sample repro :/

We're in an umbrella project, so here's the contents of our various formatter configs:

> fd --hidden ".formatter.exs" --exec cat {}
[
  inputs: ["{mix,.formatter}.exs"],
  subdirectories: ["apps/*"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: [
    "{lib,config,test}/**/*.{ex,exs}",
    "{mix,.formatter}.exs"
  ],
  import_deps: [:absinthe, :plug],
  locals_without_parens: [
    forward: 1,
    visibility: 1,
    owning_team: 1,
    experimental_complexity: 1,
    import_autostitched_types: 2,
    import_autostitched_fields: 2
  ]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: [
    "{lib,config,test}/**/*.{ex,exs}",
    "{mix,.formatter}.exs"
  ],
  import_deps: [:absinthe],
  locals_without_parens: [
    forward: 1,
    visibility: 1,
    import_autostitched_types: 2,
    import_autostitched_fields: 2
  ]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: [
    "{lib,config,test}/**/*.{ex,exs}",
    "{mix,.formatter}.exs"
  ],
  import_deps: [:plug]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

[
  inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
]

BlueHotDog · 2020-10-14T10:46:53Z

I'm getting this in the output:

[Trace - 1:44:38 PM] Sending request 'textDocument/formatting - (9569)'.
[Trace - 1:44:38 PM] Received response 'textDocument/formatting - (9569)' in 1ms. Request failed: Cannot format file from current directory (Currently in deps/telemetry_poller/deps/parse_trans) (-32603).
[Error - 1:44:38 PM] Request textDocument/formatting failed.
  Message: Cannot format file from current directory (Currently in deps/telemetry_poller/deps/parse_trans)
  Code: -32603 
[Trace - 1:44:38 PM] Sending notification 'textDocument/didSave'.
[Trace - 1:44:39 PM] Sending notification 'workspace/didChangeWatchedFiles'.
[Trace - 1:44:39 PM] Sending request 'textDocument/hover - (9570)'.
[Trace - 1:44:39 PM] Sending notification '$/cancelRequest'.
[Trace - 1:44:39 PM] Received response 'textDocument/hover - (9570)' in 34ms. Request failed: Request cancelled (-32800).

Maybe it helps.
It resolves itself for a while if i restart the editor

lukaszsamson · 2020-10-14T10:52:34Z

@BlueHotDog do you have any file open from deps/telemetry_poller/deps/parse_trans? Also please post your .formatter.exs

BlueHotDog · 2020-10-14T10:53:43Z

this is my .formatter:

[
  import_deps: [:ecto, :phoenix],
  inputs: ["*.{ex,exs}", "priv/*/seeds.exs", "{config,lib,test}/**/*.{ex,exs}"],
  subdirectories: ["priv/*/migrations"]
]

I do not have any file from deps/delemetry.. open :(

lukaszsamson · 2020-10-14T11:20:22Z

Hmm the code in

elixir-ls/apps/language_server/lib/language_server/providers/formatting.ex

Line 43 in d7208fe

defp can_format?(file_uri, project_dir) do

seems strange. @axelson do you have an idea why is it checkin cwd? It was added in d143772#diff-d695db38f04b7e4e345c6f1341e4b0fd9ec92ab81ae4741577dba5ad9e7d5778 but I'm not convinced by the reasoning in the commit message.

axelson · 2020-10-14T17:47:57Z

@lukaszsamson I am agreed with you. I don't see a reason we can't format regardless of the CWD. Since we have the project dir we can always use that to find the relevant .formatter.exs. But with that said, this is a different issue that is already being tracked as #252

benwilson512 · 2020-10-17T19:42:45Z

Can confirm that this is what we have experienced as well. Perhaps @axelson you could try using the absinthe-graphql/absinthe code base as an example? It's got quite a few files (248, 21k LOC) and test files (212, 19k LOC).

Does elixir-ls compile the full code base before formatting? Does format on save format all files or just the one saved?

mattbaker · 2020-10-18T20:58:40Z

I can repro more specifically by repeatedly changing and saving a file. Eventually it'll block with the notification that the file save action is waiting on Elixir LS to format*.

In the Elixir LS logs I noticed this seemed to occur if I saved right after I saw this message:

 [ElixirLS WorkspaceSymbols] Updating index...

During that time format/save doesn't complete until it finishes. It seems like this may correlate with saving while the workspace symbol update is in progress?

If I make changes really quickly it seems like I can reproduce this in 0.5.0 too. I'm unclear why it's worse in 0.6.0 though. I noticed 0.6.0 bumps Elixir and Erlang, some change there? I didn't see anything obvious in the release notes of either of those though. Is indexing slower, and thus the problem more apparent?

One way or another it seems odd that reindexing the workspace symbols is blocking the format operation. It seems like we'd want to avoid blocking a save operation at all costs.

Is this something the Language Server spec imposes? Is something in indexing causing the formatter to have to wait?

I'm not sure when I'll next have a chance to look into this deeply, but hopefully this helps.

* If I go really fast I get a different error that feels like another issue to address at a later date:

MIX_TARGET: 
[Error - 1:55:12 PM] Request textDocument/formatting failed.
  Message: Cannot format file from current directory (Currently in apps/thrift_services)
  Code: -32603

mattbaker · 2020-10-19T22:20:05Z

@axelson - Should I close this or would you like it to remain open? I don't want to mess with your workflow.

axelson · 2020-10-20T04:12:22Z

I want to do some more testing and collect more feedback before closing this. Also ideally we could change the code to not use Path.wildcard to remove more directory traversal.

mattbaker · 2020-10-20T04:49:27Z

Nice, good call 👍

When dealing with `.formatter.exs` files that are in subdirectories of the main project, the behaviour was incorrect: elixir-lsp#361 And also caused performance problems: elixir-lsp#381 A good example is a project I currently work on. We have a top-level `.formatter.exs`, as well as a `test/.formatter.exs`. The one in `test/` has the `:inputs` option set to `["**/*.{ex,exs}"]`. Before this commit, should_format?/3 would take this pattern and concatenate it with the project directory. This would result in Path.wildcard/2 globbing for all source files in the entire project, rather than just under test/. This causes formatting to take about 5 seconds on our project. This commit fixes the problem by taking the file to be formatted, and finding the `.formatter.exs` file that exists in the closest parent directory (so long as that directory is still within the project root). We then perform the Path.wildcard/2 relative to that directory. I’ve removed the hack that was in place to support umbrella projects, because this is a more general solution to the problem. On our project, I am now able to format a file in 100ms or so, which isn’t a bad speed-up!

jonleighton · 2021-10-01T05:42:30Z

I've proposed a partial fix for this problem in #609 (by also fixing a bug with how :inputs are matched). It delivers a big speed-up on a project I work on, but doesn't fix the underlying problem of relying on Path.wildcard/2.

I plan to also propose a more general solution, but that will take a bit longer. In the mean time, please try out the changes above and let me know if you encounter any problems (other than performance) on your projects.

When dealing with `.formatter.exs` files that are in subdirectories of the main project, the behaviour was incorrect: elixir-lsp#361 And also caused performance problems: elixir-lsp#381 A good example is a project I currently work on. We have a top-level `.formatter.exs`, as well as a `test/.formatter.exs`. The one in `test/` has the `:inputs` option set to `["**/*.{ex,exs}"]`. Before this commit, should_format?/3 would take this pattern and concatenate it with the project directory. This would result in Path.wildcard/2 globbing for all source files in the entire project, rather than just under test/. This causes formatting to take about 5 seconds on our project. This commit fixes the problem by taking the file to be formatted, and finding the `.formatter.exs` file that exists in the closest parent directory (so long as that directory is still within the project root). We then perform the Path.wildcard/2 relative to that directory. I’ve removed the hack that was in place to support umbrella projects, because this is a more general solution to the problem. On our project, I am now able to format a file in 100ms or so, which isn’t a bad speed-up!

The call to Path.wildcard/2 can cause use to traverse a large number of files, which can be very slow depending on the project and the globs used: elixir-lsp#381 I wrote a library that implements a glob parser and allows us to check whether a glob matches a path without touching the filesystem: https://github.com/jonleighton/path_glob This commit switches out the Path.wildcard/2 call to use this library.

…ries (#609) * Convert should_format? test to use format/3 and fixtures This function is really an implementation detail, so let’s test the public API. The function also relies on interaction with the filesystem, so testing without fixtures is a bad idea because it will lead to incorrect results. * Check .formatter.exs :inputs relative to its directory When dealing with `.formatter.exs` files that are in subdirectories of the main project, the behaviour was incorrect: #361 And also caused performance problems: #381 A good example is a project I currently work on. We have a top-level `.formatter.exs`, as well as a `test/.formatter.exs`. The one in `test/` has the `:inputs` option set to `["**/*.{ex,exs}"]`. Before this commit, should_format?/3 would take this pattern and concatenate it with the project directory. This would result in Path.wildcard/2 globbing for all source files in the entire project, rather than just under test/. This causes formatting to take about 5 seconds on our project. This commit fixes the problem by taking the file to be formatted, and finding the `.formatter.exs` file that exists in the closest parent directory (so long as that directory is still within the project root). We then perform the Path.wildcard/2 relative to that directory. I’ve removed the hack that was in place to support umbrella projects, because this is a more general solution to the problem. On our project, I am now able to format a file in 100ms or so, which isn’t a bad speed-up! * Avoid costly Path.wildcard/2 call The call to Path.wildcard/2 can cause use to traverse a large number of files, which can be very slow depending on the project and the globs used: #381 I wrote a library that implements a glob parser and allows us to check whether a glob matches a path without touching the filesystem: https://github.com/jonleighton/path_glob This commit switches out the Path.wildcard/2 call to use this library. Co-authored-by: Jason Axelson <[email protected]>

axelson · 2021-12-05T03:37:23Z

#609 was expanded to fix this issue completely since with that change, ElixirLS no longer requires a call to Path.wildcard/2 for formatting now that PathGlob is used instead 🎊

mattbaker · 2021-12-05T06:54:56Z

That’s amazing! 🎉

On December 4, 2021, GitHub ***@***.***> wrote: #609 <#609> was expanded to fix this issue completely since with that change, ElixirLS no longer requires a call to Path.wildcard/2 for formatting now that PathGlob <https://github.com/jonleighton/path_glob> is used instead 🎊

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#381 (comment)- 986160421>, or unsubscribe <https://github.com/notifications/unsubscribe- auth/AAANRJSMRTYEYQB23ERA4W3UPLM75ANCNFSM4SL6QKNQ>.

lukaszsamson mentioned this issue Oct 13, 2020

Eliixir LS slow since upgrading to elixir 1.11 #385

Closed

mattbaker mentioned this issue Oct 19, 2020

Bypass file_server for some file existence checks #390

Merged

axelson pinned this issue Oct 19, 2020

lukaszsamson mentioned this issue Oct 20, 2020

Change formatter to attempt to acquire a build lock #391

Closed

mattbaker mentioned this issue Oct 20, 2020

ElixirLS hangs on save #289

Closed

benwilson512 mentioned this issue Oct 28, 2020

[WIP] Add an :ets table to cache the list of files that can be formatted #394

Closed

9 tasks

lukaszsamson added the work in progress label Nov 28, 2020

axelson mentioned this issue Dec 22, 2020

Speed regression for elixir 1.11, manifest writing takes between 4 and 6 seconds #439

Closed

jonleighton mentioned this issue Oct 1, 2021

Fix formatting performance problems with .formatter.exs in subdirectories #609

Merged

axelson closed this as completed Dec 5, 2021

axelson unpinned this issue Dec 5, 2021

lukaszsamson removed the work in progress label Mar 18, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Apparent formatter speed regression #381

Apparent formatter speed regression #381

mattbaker commented Oct 11, 2020 •

edited

Loading

BlueHotDog commented Oct 12, 2020

axelson commented Oct 13, 2020

mattbaker commented Oct 13, 2020

BlueHotDog commented Oct 14, 2020

lukaszsamson commented Oct 14, 2020

BlueHotDog commented Oct 14, 2020

lukaszsamson commented Oct 14, 2020

axelson commented Oct 14, 2020

benwilson512 commented Oct 17, 2020 •

edited

Loading

mattbaker commented Oct 18, 2020

mattbaker commented Oct 19, 2020

axelson commented Oct 20, 2020

mattbaker commented Oct 20, 2020

jonleighton commented Oct 1, 2021

axelson commented Dec 5, 2021

mattbaker commented Dec 5, 2021 via email

Apparent formatter speed regression #381

Apparent formatter speed regression #381

Comments

mattbaker commented Oct 11, 2020 • edited Loading

Environment

Troubleshooting

Logs

BlueHotDog commented Oct 12, 2020

axelson commented Oct 13, 2020

mattbaker commented Oct 13, 2020

BlueHotDog commented Oct 14, 2020

lukaszsamson commented Oct 14, 2020

BlueHotDog commented Oct 14, 2020

lukaszsamson commented Oct 14, 2020

axelson commented Oct 14, 2020

benwilson512 commented Oct 17, 2020 • edited Loading

mattbaker commented Oct 18, 2020

mattbaker commented Oct 19, 2020

axelson commented Oct 20, 2020

mattbaker commented Oct 20, 2020

jonleighton commented Oct 1, 2021

axelson commented Dec 5, 2021

mattbaker commented Dec 5, 2021 via email

mattbaker commented Oct 11, 2020 •

edited

Loading

benwilson512 commented Oct 17, 2020 •

edited

Loading