Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Go to Symbol in Workspace" (⌘T) becomes very slow in seemingly inconsistent ways due to indexing #997

Closed
klbostee opened this issue Feb 27, 2021 · 9 comments
Assignees
Labels
waiting for user response Requires more information from user

Comments

@klbostee
Copy link

Environment data

  • Language Server version: 2021.2.4
  • OS and version: both macOS Catalina (when running without dev container) and Ubuntu Focal (with dev container)
  • Python version: 3.7.10
  • Multi-root workspace containing several sizeable Python codebases

Expected behaviour

With python.analysis.indexing set to true, I would expect "Go to Symbol in Workspace" (⌘T) to always be fast and not become unusably slow intermittently.

Additionally, I'd also expect to see some sort of visual indication for when indexing is taking place so that I can know that lookup performance might temporarily be affected.

Actual behaviour

Initially (e.g. after a window reload) ⌘T is very slow while the indexing is being performed (which is something I was only able to figure out after setting python.analysis.logLevel to Trace and looking at the Python Language Server output) and after that it gets slow again intermittently whenever Pylance decides to do some more indexing. It's not entirely clear to me what exactly triggers the additional indexing, but initiating a "Go to Symbol in Workspace" (⌘T) also seems to trigger it sometimes (which is kind of unfortunate, because that then makes the ⌘T very slow).

Logs

The initial indexing (e.g. after window reload) eventually stops with this message in the logs:

[Warn  - 5:02:35 PM] Workspace indexing has hit its upper limit: 2000 files

And then whenever ⌘T gets slow again it's pretty obvious from the logs that more indexing is being done.

Additional information

At first I thought the slowness might've been related to the fact that I was working in a dev container, but it turns out I'm getting the same issues when developing directly on macOS. The dev container does add a noticeable delay to ⌘T that makes it a bit less instant, but that's a very short and consistent delay that doesn't impede fluent navigation. The intermittent (extreme) slowness due to indexing happens for both setups.

I've already tried setting python.analysis.indexing to false by the way, but that basically makes ⌘T too slow pretty much all of the time. In fact, I was very excited when I found out about the possibility of enabling indexing because that actually gets us quite a bit closer to having usable symbol-based code navigation in VS Code. It's definitely looking very promising, as does Pylance in general!

@judej judej added the needs investigation Could be an issue - needs investigation label Mar 1, 2021
@github-actions github-actions bot removed the triage label Mar 1, 2021
@judej judej added waiting for user response Requires more information from user and removed needs investigation Could be an issue - needs investigation labels Mar 1, 2021
@judej
Copy link
Contributor

judej commented Mar 1, 2021

Thanks for the report. We will investigate this performance issue. Could you please provide the logs? Or at least the top of the logs. I'm concerned the devcontainer is opening at the top of the root of the container.

@klbostee
Copy link
Author

klbostee commented Mar 1, 2021

I just reloaded the window and this is the top of the logs:

[Info  - 6:55:57 PM] Pylance language server 2021.2.4 (pyright a18e6fb4) starting
[Info  - 6:55:57 PM] Server root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:55:59 PM] No configuration file found.
[Info  - 6:56:01 PM] Setting pythonPath for service "api": "/workspaces/itemwise/api/venv/bin/python"
Search paths found for configured python interpreter:
  /usr/lib/python3.7
  /usr/lib/python3.7/lib-dynload
  /workspaces/itemwise/api/venv/lib/python3.7/site-packages
[Error - 6:56:01 PM] stubPath /workspaces/itemwise/api/typings is not a valid directory.
[Info  - 6:56:01 PM] Assuming Python version 3.7
[Info  - 6:56:01 PM] Assuming Python platform Linux
[Info  - 6:56:01 PM] Searching for source files
[Info  - 6:56:01 PM] Auto-excluding /workspaces/itemwise/api/venv
[Info  - 6:56:01 PM] Found 2756 source files
[Info  - 6:56:01 PM] Background analysis(1) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(1) started
Background analysis message: setConfigOptions
Background analysis message: setTrackedFiles
[Info  - 6:56:01 PM] Background analysis(2) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(2) started
[Info  - 6:56:01 PM] Background analysis(3) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(3) started
[Info  - 6:56:01 PM] Background analysis(4) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(4) started
[Info  - 6:56:01 PM] Background analysis(5) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(5) started
[Info  - 6:56:01 PM] Background analysis(6) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(6) started
[Info  - 6:56:01 PM] Background analysis(7) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(7) started
[Info  - 6:56:01 PM] Background analysis(8) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(8) started
[Info  - 6:56:01 PM] Background analysis(9) root directory: /home/vscode/.vscode-server/extensions/ms-python.vscode-pylance-2021.2.4/dist
[Info  - 6:56:01 PM] Background analysis(9) started
Background analysis message: markAllFilesDirty
Background analysis message: analyze

This is what I get when grepping the initial logs for for service |Found :

[Info  - 6:56:01 PM] Setting pythonPath for service "api": "/workspaces/itemwise/api/venv/bin/python"
[Info  - 6:56:01 PM] Found 2756 source files
[Info  - 6:56:01 PM] Setting pythonPath for service "site": "/workspaces/itemwise/site/venv/bin/python"
[Info  - 6:56:01 PM] Found 190 source files
[Info  - 6:56:01 PM] Setting pythonPath for service "core": "/workspaces/itemwise/core/venv/bin/python"
[Info  - 6:56:02 PM] Found 41 source files
[Info  - 6:56:02 PM] Setting pythonPath for service "hosting": "/workspaces/itemwise/hosting/venv/bin/python"
[Info  - 6:56:02 PM] Found 18 source files
[Info  - 6:56:02 PM] Setting pythonPath for service "processing": "/workspaces/itemwise/processing/venv/bin/python"
[Info  - 6:56:03 PM] Found 135 source files
[Info  - 6:56:03 PM] Setting pythonPath for service "dashboard": "/workspaces/itemwise/dashboard/venv/bin/python"
[Info  - 6:56:03 PM] Found 14 source files
[Info  - 6:56:03 PM] Setting pythonPath for service "cli-tools": "/workspaces/itemwise/cli-tools/.venv/bin/python"
[Info  - 6:56:03 PM] Found 2 source files
[Info  - 6:56:03 PM] Setting pythonPath for service "helpers": "/usr/bin/python3.7"
[Info  - 6:56:04 PM] Setting pythonPath for service ".devcontainer": "/usr/bin/python3.7"

And this is the result of grepping for index :

[IDX(10)] index libraries /workspaces/itemwise/api ...
[IDX(10)]   index execution environment /workspaces/itemwise/api ...
[IDX(12)] index libraries /workspaces/itemwise/core ...
[IDX(11)] index libraries /workspaces/itemwise/site ...
[IDX(13)] index libraries /workspaces/itemwise/hosting ...
[IDX(14)] index libraries /workspaces/itemwise/processing ...
[IDX(15)] index libraries /workspaces/itemwise/dashboard ...
[IDX(16)] index libraries /workspaces/itemwise/cli-tools ...
[IDX(17)] index libraries /workspaces/itemwise/helpers ...
[IDX(18)] index libraries /workspaces/itemwise/.devcontainer ...
[IDX(12)]   index execution environment /workspaces/itemwise/core ...
[IDX(11)]   index execution environment /workspaces/itemwise/site ...
[IDX(13)]   index execution environment /workspaces/itemwise/hosting ...
[IDX(17)]   index execution environment /workspaces/itemwise/helpers ...
[IDX(18)]   index execution environment /workspaces/itemwise/.devcontainer ...
[IDX(15)]   index execution environment /workspaces/itemwise/dashboard ...
[IDX(16)]   index execution environment /workspaces/itemwise/cli-tools ...
[IDX(14)]   index execution environment /workspaces/itemwise/processing ...
[IDX(12)]   index execution environment /workspaces/itemwise/core [found 7490 in 404 files] (10418ms)
[Info  - 6:56:21 PM] [IDX(12)] Long operation: index execution environment /workspaces/itemwise/core (10418ms)
[IDX(12)] index libraries /workspaces/itemwise/core [found 7490 in 1 exec envs] (15461ms)
[Info  - 6:56:21 PM] [IDX(12)] Long operation: index libraries /workspaces/itemwise/core (15461ms)
[IDX(18)]   index execution environment /workspaces/itemwise/.devcontainer [found 7423 in 404 files] (10974ms)
[Info  - 6:56:23 PM] [IDX(18)] Long operation: index execution environment /workspaces/itemwise/.devcontainer (10974ms)
[IDX(18)] index libraries /workspaces/itemwise/.devcontainer [found 7423 in 1 exec envs] (13906ms)
[Info  - 6:56:23 PM] [IDX(18)] Long operation: index libraries /workspaces/itemwise/.devcontainer (13906ms)
[IDX(17)]   index execution environment /workspaces/itemwise/helpers [found 7423 in 404 files] (11240ms)
[Info  - 6:56:24 PM] [IDX(17)] Long operation: index execution environment /workspaces/itemwise/helpers (11240ms)
[IDX(17)] index libraries /workspaces/itemwise/helpers [found 7423 in 1 exec envs] (14134ms)
[Info  - 6:56:24 PM] [IDX(17)] Long operation: index libraries /workspaces/itemwise/helpers (14134ms)
[IDX(16)]   index execution environment /workspaces/itemwise/cli-tools [found 7473 in 403 files] (11607ms)
[Info  - 6:56:24 PM] [IDX(16)] Long operation: index execution environment /workspaces/itemwise/cli-tools (11607ms)
[IDX(16)] index libraries /workspaces/itemwise/cli-tools [found 7473 in 1 exec envs] (14968ms)
[Info  - 6:56:24 PM] [IDX(16)] Long operation: index libraries /workspaces/itemwise/cli-tools (14968ms)
[IDX(15)]   index execution environment /workspaces/itemwise/dashboard [found 7743 in 412 files] (13665ms)
[Info  - 6:56:26 PM] [IDX(15)] Long operation: index execution environment /workspaces/itemwise/dashboard (13665ms)
[IDX(15)] index libraries /workspaces/itemwise/dashboard [found 7743 in 1 exec envs] (17045ms)
[Info  - 6:56:26 PM] [IDX(15)] Long operation: index libraries /workspaces/itemwise/dashboard (17045ms)
[IDX(13)]   index execution environment /workspaces/itemwise/hosting [found 7816 in 415 files] (14926ms)
[Info  - 6:56:27 PM] [IDX(13)] Long operation: index execution environment /workspaces/itemwise/hosting (14926ms)
[IDX(13)] index libraries /workspaces/itemwise/hosting [found 7816 in 1 exec envs] (19237ms)
[Info  - 6:56:27 PM] [IDX(13)] Long operation: index libraries /workspaces/itemwise/hosting (19237ms)
[IDX(11)]   index execution environment /workspaces/itemwise/site [found 8402 in 436 files] (25504ms)
[Info  - 6:56:37 PM] [IDX(11)] Long operation: index execution environment /workspaces/itemwise/site (25504ms)
[IDX(11)] index libraries /workspaces/itemwise/site [found 8402 in 1 exec envs] (31306ms)
[Info  - 6:56:37 PM] [IDX(11)] Long operation: index libraries /workspaces/itemwise/site (31306ms)
[IDX(10)]   index execution environment /workspaces/itemwise/api [found 9099 in 486 files] (40229ms)
[Info  - 6:56:42 PM] [IDX(10)] Long operation: index execution environment /workspaces/itemwise/api (40229ms)
[IDX(10)] index libraries /workspaces/itemwise/api [found 9099 in 1 exec envs] (41052ms)
[Info  - 6:56:42 PM] [IDX(10)] Long operation: index libraries /workspaces/itemwise/api (41052ms)
[IDX(14)]   index execution environment /workspaces/itemwise/processing [found 8542 in 451 files] (29358ms)
[Info  - 6:56:42 PM] [IDX(14)] Long operation: index execution environment /workspaces/itemwise/processing (29358ms)
[IDX(14)] index libraries /workspaces/itemwise/processing [found 8542 in 1 exec envs] (33451ms)
[Info  - 6:56:42 PM] [IDX(14)] Long operation: index libraries /workspaces/itemwise/processing (33451ms)

As already mentioned before, the last line of the initial logs is this:

[Warn  - 6:57:00 PM] Workspace indexing has hit its upper limit: 2000 files

And when I then hit ⌘T and tried to search for a class, it was still slow and I started getting a whole bunch of logs starting with [FG] parsing: and [FG] binding:.

I guess this was already quite obvious from the above, but so this is in a multi-root workspace where api is the first root. Here's the top of the .code-workspace file:

{
	"folders": [
		{
			"path": "api"
		},
		{
			"path": "site"
		},
		{
			"path": "core"
		},
		{
			"path": "hosting"
		},
		{
			"path": "processing"
		},
		{
			"path": "dashboard"
		},
		{
			"path": "cli-tools"
		},
		{
			"path": "helpers"
		},
		{
			"path": ".devcontainer"
		}
	],

Hope this helps? Do let me know if you need any further info!

@jakebailey
Copy link
Member

That does help; I was just trying to figure out if your project really contained 2000+ files or if we had the workspace root wrong.

If you look at the trace logs, do you see any files that really shouldn't be analyzed within that api folder? E.g., are there items we should be excluding that we are not? 2756 source files is very high.

@klbostee
Copy link
Author

klbostee commented Mar 2, 2021

No, that number of source files seems to be correct actually. It's just a large codebase I'm afraid.

For what it's worth: I wouldn't mind if the initial indexing takes a while, as long as it only needs to happen once. Afterwards I'd expect it to only be necessary for new or changed files? It'd be good to have something in the status bar or so to make it clear that indexing is going on then though. As far as I know that's basically what PyCharm does, and they do manage to cope with our large codebase in that way.

@jakebailey
Copy link
Member

Most settings changes can significantly change the analysis; any change or file change event in the search paths can change something and our current method is to just about everything away without much granularity. This works fine for most features (as they are lazy and evaluate on the fly), but indexing is of course ahead-of-time.

The 2000 limit is hardcoded, but we could potentially experiment with some configuration there. A spinner for an in-progress indexing job may also be a good idea.

@jakebailey jakebailey added needs investigation Could be an issue - needs investigation and removed waiting for user response Requires more information from user labels Mar 2, 2021
@klbostee
Copy link
Author

klbostee commented Mar 2, 2021

Making the file limit configurable and showing a spinner when indexing is in progress could already be a big step forward I think! I'd definitely be happy to experiment with that and report back on how much it improves things for us.

I also found out today that excluding subpackages in pyrightconfig.json might be a way of mitigating the problem a bit, by the way. It's not the greatest solution as you also can't search in those subpackages anymore via ⌘T then, but at least it gives you a (crude) way to avoid hitting the hardcoded limit and the slowness did seem to become less of an issue when I did that.

@heejaechang
Copy link
Contributor

@klbostee can you check whether this still repo with latest release? one of reason this might have happened before was due to multi root workspace causing re-indexing. we have made a few changes around there so wondering whether it is still reproes.

thank you

@heejaechang heejaechang added waiting for user response Requires more information from user and removed needs investigation Could be an issue - needs investigation labels Apr 12, 2022
@klbostee
Copy link
Author

@heejaechang haven't tested extensively yet, but it does seem to be better now at first sight!

@judej
Copy link
Contributor

judej commented Jun 1, 2022

Closing old issue. If this is still a problem, please reopen the issue. thanks

@judej judej closed this as completed Jun 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
waiting for user response Requires more information from user
Projects
None yet
Development

No branches or pull requests

4 participants