Quick open is very slow #130479

Timmmm · 2021-08-10T09:24:08Z

Does this issue occur when all extensions are disabled?: Yes

VS Code Version: 1.59.0
OS Version: MacOS 11.4 / CentOS Linux release 7.9.2009 (Core)

I am using VSCode on Mac to edit a large workspace (75k files) on a remote Linux machine. The Linux machine is a beast (48 core Xeon, 376 GB RAM) but it does have some limitations

The filesystem is remote, via NFS
ulimit -n is only 65535.

Opening files in the workspace on my local machine via Ctrl-P is basically instant, but on the remote machine it takes about 10 seconds (unless it was open recently). find . -name ... is much faster (it takes 1-2 seconds).

Steps to Reproduce:

Open a large workspace mounted via NFS on a remote machine over SSH
Try to open a file via Ctrl-P (Quick Open).

I appreciate that this is probably a worst case situation, but surely VSCode could scan the workspace and maintain a cache of all the filenames it has seen even if the filesystem itself is very slow? And I don't see why it is so much slower than find.

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

Timmmm · 2021-08-10T11:46:02Z

I did a small amount of research into this and found that there is a proposal to allow Quick Open to be supplied by extensions. It's called FileSearchProvider (or FileIndexProvider). It's pretty old, it would be good to stabilise it!

Also there is an extension that uses this API to do exactly what I wanted cache the file list and return it quickly (well, maybe anyway):

#64274

Unfortunately it hasn't been updated for 3 years so I'd be surprised if it still works.

Timmmm · 2021-08-10T11:46:48Z

Here is the issue to stabilise FileSearchProvider: #73524

roblourens · 2021-08-10T16:34:23Z

You would probably be interested in the Remote-SSH extension which would let you run extensions and search directly on the remote, instead of over a slow network drive.

What should happen is that we would keep the cache of files and search in that on subsequent searches. Not sure why it isn't working. You could follow the steps on this page to get the search logs which might tell us something. https://github.com/microsoft/vscode/wiki/Search-Issues

Btw the extension you point to was a test extension that doesn't do anything different than what the built-in code does now.

Timmmm · 2021-08-10T19:14:08Z

You would probably be interested in the Remote-SSH extension which would let you run extensions and search directly on the remote, instead of over a slow network drive.

Sorry I probably wasn't clear - I am using the remote SSH extension to connect to a machine that itself uses NFS mounts.

You could follow the steps on this page to get the search logs which might tell us something.

Ah I will try that, thanks for the hint.

the extension you point to was a test extension that doesn't do anything different than what the built-in code does now.

Also very useful information, thanks!

Timmmm · 2021-08-10T19:30:29Z

Hmm unfortunately the logs don't show anything interesting.

[2021-08-10 20:23:10.594] [renderer6] [trace] CommandService#executeCommand workbench.output.action.clearOutput
[2021-08-10 20:23:14.578] [renderer6] [trace] KeybindingService#dispatch ⌘P workbench.action.quickOpen
[2021-08-10 20:23:14.578] [renderer6] [trace] CommandService#executeCommand workbench.action.quickOpen
[2021-08-10 20:23:14.581] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":0,"type":1,"filePattern":"","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:15.410] [renderer6] [trace] KeybindingService#dispatch X undefined
[2021-08-10 20:23:15.655] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"x","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:15.816] [renderer6] [trace] KeybindingService#dispatch M undefined
[2021-08-10 20:23:16.055] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:16.320] [renderer6] [trace] KeybindingService#dispatch ⇧- undefined
[2021-08-10 20:23:16.559] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm_","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:16.568] [renderer6] [trace] KeybindingService#dispatch P undefined
[2021-08-10 20:23:16.590] [renderer6] [trace] SearchService#search: 1ms
[2021-08-10 20:23:16.595] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:16.770] [renderer6] [trace] KeybindingService#dispatch P undefined
[2021-08-10 20:23:16.987] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm_pp","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:17.001] [renderer6] [trace] KeybindingService#dispatch O undefined
[2021-08-10 20:23:17.022] [renderer6] [trace] SearchService#search: 0ms
[2021-08-10 20:23:17.029] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:17.218] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm_ppo","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:17.737] [renderer6] [trace] KeybindingService#dispatch R undefined
[2021-08-10 20:23:17.957] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm_ppor","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:17.971] [renderer6] [trace] KeybindingService#dispatch T undefined
[2021-08-10 20:23:17.994] [renderer6] [trace] SearchService#search: 0ms
[2021-08-10 20:23:17.996] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:18.192] [renderer6] [trace] SearchService#search {"_reason":"openFileHandler","folderQueries":[{"folder":{"$mid":1,"fsPath":"/work/foo","external":"vscode-remote://ssh-remote%2Bxterm_inter/work/foo","path":"/work/foo","scheme":"vscode-remote","authority":"ssh-remote+xterm_inter"},"excludePattern":{"**/.git":true,"**/.svn":true,"**/.hg":true,"**/CVS":true,"**/.DS_Store":true,"**/node_modules":true,"**/bower_components":true,"**/*.code-search":true},"fileEncoding":"utf8","disregardIgnoreFiles":false,"disregardGlobalIgnoreFiles":false,"ignoreSymlinks":false}],"usingSearchPaths":false,"maxResults":512,"type":1,"filePattern":"xm_pport","sortByScore":true,"cacheKey":"id#4"}
[2021-08-10 20:23:26.055] [renderer6] [trace] SearchService#search: 11388ms
[2021-08-10 20:23:26.056] [renderer6] [trace] SearchService#search: 10375ms
[2021-08-10 20:23:26.056] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:26.056] [renderer6] [trace] SearchService#search: 9969ms
[2021-08-10 20:23:26.056] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:26.056] [renderer6] [trace] SearchService#search: 8822ms
[2021-08-10 20:23:26.057] [renderer6] [trace] SearchService#searchError: Canceled
[2021-08-10 20:23:32.115] [renderer6] [trace] SearchService#search: 13897ms

The results appear at the same time as the last line, so it took 13 seconds. Could the reason be that the Remote SSH extension takes over handling of file name searching and doesn't cache them? I think it's closed source so might be hard to tell, but I'll try using VSCode over VNC instead of the Remote SSH extension and see if it makes a difference.

roblourens · 2021-08-11T19:14:58Z

There may be some info in the "Log (Remote Extension)" output channel as well

Timmmm · 2021-08-13T11:08:38Z

I did some more debugging. Firstly it is still slow when running VSCode without the remote SSH extension (I run it via VNC instead). I can only test up to VSCode 1.48.2 because later versions crash with sigtrap on startup. :-/

I did also manage to compile VSCode 1.48.2 from source and run it (I had to compile a more modern version of glibc too and do some funky LD_LIBRARY_PATH stuff; CentOS has very old glibc). I added a load of console.log()s to the search code but I can't seem to find where they go. Possibly nowhere?

There's no logging at all in the existing code (rawSearchService.ts) and when I step through the code in workbench.desktop.main.js it get to some RPC method so I guess it is run in another process anyway. Maybe that's why nobody figured out how to add logging.

Do you know how I can add logging to rawSearchService.js, or add breakpoints in the dev tools? What file does that code end up in?

Timmmm · 2021-08-13T11:10:47Z

Ah wait I found where the code ends up - in both of these files

./resources/app/out/vs/workbench/services/extensions/node/extensionHostProcess.js
./resources/app/out/vs/workbench/services/search/node/searchApp.js

Timmmm · 2021-08-13T11:19:33Z

Ah you can pass --inspect-search --inspect-brk-search on the command line and then connect to port 5876 to debug it, or something like that.

Timmmm · 2021-08-13T11:56:19Z

Hmm it seems like you are supposed to pass either --inspect-search[=port] or --inspect-brk-search[=port] (default port 5876) which I presume get translated to Node's --inspect or --inspect-brk, but they don't seem to work with my compiled version. With the official download they work but aren't very useful because it just goes into a load of JS module loading nonsense and I can't get to the actual code (plus it's minified). :-/

Timmmm · 2021-08-13T12:57:24Z

Aha I had given up on this but then noticed the verbose option. If you run VSCode with --verbose then console.log()s show up in the dev tools.

It seems like the issue is that searches return a lot of results, and then sorting them is really slow:

It's weird because the workspace only has 70k files in it:

$ find . | wc -l
70333

Timmmm · 2021-08-13T13:57:47Z

Aha! If I run the rg command that is logged it does report 903899 files, and about a gazillion symlink loops (not my design!). If I remove --follow it only reports 14841 files. I found I can set "search.followSymlinks": false, and then it fixes this problem!

So, I guess ultimately this isn't exactly a bug (although I reckon fuzzy matching 700k strings should probably take less time than 10 seconds), but it did take me like a whole day to figure out, including having to compile my own version of VSCode with extra logging.

So it would be nice if it was a bit easier to diagnose. Here are a few ideas:

Surface rg's symlink loop warnings to the user.
If there are more than 100k results to sort, or maybe just if the search takes too long then tell the user it may be slow and maybe exclude some folders or don't follow symlinks.
Get rg to report whether or not each file was found via a symlink and then you can tell the user something like "80% of the files we are searching were via a symlink; do you want to disable symlink following?"
Improved visibility of what the search is doing - i.e. when it is actually running ripgrep, or sorting cached results.

I'll close this issue though because I doubt any of those will happen and you have a bazillion bugs already.

roblourens · 2021-08-20T00:17:04Z

Thanks for doing that debugging. I would like to make the symlink issue more apparent but don't have time for it right now. That issue is mentioned in the wiki page I linked above. But really we should just be able to pop up a notification to the user when they may be encountering this.

vscode-triage-bot assigned TylerLeonhardt Aug 10, 2021

TylerLeonhardt assigned roblourens and unassigned TylerLeonhardt Aug 10, 2021

roblourens added the info-needed Issue requires more information from poster label Aug 10, 2021

Timmmm closed this as completed Aug 13, 2021

github-actions bot locked and limited conversation to collaborators Sep 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Quick open is very slow #130479

Quick open is very slow #130479

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

roblourens commented Aug 10, 2021

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

roblourens commented Aug 11, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021 •

edited

Loading

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

roblourens commented Aug 20, 2021 •

edited

Loading

Quick open is very slow #130479

Quick open is very slow #130479

Comments

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

roblourens commented Aug 10, 2021

Timmmm commented Aug 10, 2021

Timmmm commented Aug 10, 2021

roblourens commented Aug 11, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021 • edited Loading

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

Timmmm commented Aug 13, 2021

roblourens commented Aug 20, 2021 • edited Loading

Timmmm commented Aug 13, 2021 •

edited

Loading

roblourens commented Aug 20, 2021 •

edited

Loading