microsoft
"Search files by name" is slow when using remote
Does this issue occur when all extensions are disabled?: Yes/No
- VS Code Version: 1.78.2
- OS Version: MacOs Ventura 13.3.1
Steps to Reproduce:
- Use VSCode in remote mode and use "Search files by name" (with telemetry enabled)
- Compare the results within the same folder when not using remote
The bigger the repository, the worse it gets, and in subsequent calls, the gap narrows (I'm assuming this happens because of some in-memory cache being populated).
I've already followed Search Issues · microsoft/vscode Wiki to troubleshoot known cases, and tweaked the configuration to exclude as many files as I could, but in my codebase, it takes a really long time to perform searches.
Here is an example of me trying to use cmd+p and entering a query, waiting for it to resolve, and then trying the exact same query:
2023-05-25 17:34:42.321 [trace] telemetry/searchComplete {"properties":{"reason":"openFileHandler","scheme":"other","common.machineId":"66a593bf48622b3d8732d01f98fa2c27a72345606331167b14474051cdbccf7b","sessionID":"9d6c1d73-9a19-4e78-afb1-d7d8e95a90141685057185375","commitHash":"b3e4e68a0bc097f0ae7907b217c1119af9e03435","version":"1.78.2","common.platformVersion":"22.4.0","common.platform":"Mac","common.nodePlatform":"darwin","common.nodeArch":"arm64","common.product":"desktop","timestamp":"2023-05-25T23:34:42.320Z","common.version.shell":"22.5.2","common.version.renderer":"108.0.5359.215","common.firstSessionDate":"Mon, 12 Sep 2022 16:11:14 GMT","common.lastSessionDate":"Fri, 12 May 2023 17:29:33 GMT","common.isNewSession":"0","common.remoteAuthority":"ssh-remote","common.sandboxed":"0"},"measurements":{"resultCount":0,"workspaceFolderCount":1,"endToEndTime":8812,"sortingTime":-1,"fileWalkTime":8780,"directoriesWalked":0,"filesWalked":0,"cmdTime":8780,"cmdResultCount":368085,"common.timesincesessionstart":496945,"common.sequence":7,"common.cli":1}}
2023-05-25 17:35:20.492 [trace] telemetry/cachedSearchComplete {"properties":{"reason":"openFileHandler","scheme":"other","common.machineId":"66a593bf48622b3d8732d01f98fa2c27a72345606331167b14474051cdbccf7b","sessionID":"9d6c1d73-9a19-4e78-afb1-d7d8e95a90141685057185375","commitHash":"b3e4e68a0bc097f0ae7907b217c1119af9e03435","version":"1.78.2","common.platformVersion":"22.4.0","common.platform":"Mac","common.nodePlatform":"darwin","common.nodeArch":"arm64","common.product":"desktop","timestamp":"2023-05-25T23:35:20.491Z","common.version.shell":"22.5.2","common.version.renderer":"108.0.5359.215","common.firstSessionDate":"Mon, 12 Sep 2022 16:11:14 GMT","common.lastSessionDate":"Fri, 12 May 2023 17:29:33 GMT","common.isNewSession":"0","common.remoteAuthority":"ssh-remote","common.sandboxed":"0"},"measurements":{"resultCount":110872,"workspaceFolderCount":1,"endToEndTime":7734,"sortingTime":3375,"cacheWasResolved":1,"cacheLookupTime":0,"cacheFilterTime":125,"cacheEntryCount":368086,"common.timesincesessionstart":535116,"common.sequence":22,"common.cli":1}}
Sorry for the late reply! Is your network connection to your SSH host fast? Also, I could be curious what the performance trace on this looks like. You can see how to make one here: https://github.com/microsoft/vscode/wiki/Performance-Issues#sluggish-ui
The SSH host is fast, and everything else works without problems.
The UI is not sluggish at all: it's snappy as usual, it's just that coming back with the search results takes a long time.
You can find the profile output in https://gist.github.com/marianosimone/d82c40eb697787e045afbdfeeb0a1b0b
Hmm. Have you tried disabling the other extensions on your remote machine? Perhaps one of your extensions is over-using the extension host.
Yes, I've tried with a bare installation, and no extensions, and the problem persists.
Arguably, the repo is big (124,786,494 lines, across 378,814 files), but using VSCode locally has no trouble with it at all.
Can you log on your remote machine whether there's a rg process with high CPU consumption? Also, is there anything (ie: antivirus) that could be making filesystem access of many files slow? What OS is your remote machine?
OS: Ubuntu 20.04.6 LTS (Focal)
I've checked with htop, and there's nothing there competing for CPU consumption, nor any software that makes accessing many files slow.
I used ps to find rg, and found:
mariano+ 1255051 153 0.0 107784 55200 ? Sl 20:37 0:06 ~/.vscode-server/bin/b3e4e68a0bc097f0ae7907b217c1119af9e03435/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive -g !**/.git -g !**/.svn -g !**/.hg -g !**/CVS -g !**/.DS_Store -g !**/Thumbs.db -g !/bazel-*/** -g !/build/** -g !/src_transform_out/** -g !**/node_modules -g !**/bower_components -g !**/*.code-search --no-config
It's worth noticing that after a while, the results end up being faster (still not as fast as local... but usable), so I suspect there's some kind of memory cache that gets populated. If that's the case, is there a way to pre-warm that?
If you ran the executable ~/.vscode-server/bin/b3e4e68a0bc097f0ae7907b217c1119af9e03435/node_modules/@vscode/ripgrep/bin/rg directly to search, then do you get bad performance?
I've tried this both in the remote host and in my laptop.
In both cases, I'm doing:
time $VSCODE_LOCATION/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!/bazel-*/**' -g '!/build/**' -g '!/src_transform_out/**' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-config &> /dev/null
(note that I pipe to /dev/null to avoid paying the penalty for writing to stdout and, in the case of the remote, transferring over ssh to display it in my terminal)
The results are:
| Location | User Time | System Time | CPU Usage | Total Time |
|---|---|---|---|---|
| Remote Host | 4.04s | 2.31s | 1047% | 0.606 |
| Laptop | 2.30s | 10.48s | 699% | 1.827 |
Given that, in VSCode itself the search is slower in the remote host (when ripgrep is faster), I'm inclined to think that the problem is with what is done with the results, and not with ripgrep itself.
I've also tried looking at the results without redirecting to /dev/null, which shows how worse the performance gets on remote when transferring the data over ssh:
| Location | User Time | System Time | CPU Usage | Total Time |
|---|---|---|---|---|
| Remote Host | 4.50s | 4.27s | 114% | 7.694 |
| My Laptop | 2.45s | 11.27s | 605% | 2.267 |
This makes me think that the results of ripgrep are being transferred over SSH as-is, and then filtered in the client, which is extremely slow when the list of files is big (in my case, ~370k)
I just want to make sure I'm understanding this correctly: the first table was just using ripgrep to perform the task, and the second table is using ripgrep and letting the output go to stdout (which sends it over ssh in the Remote Host case)? And the performance in the latter case is still faster than searching in vscode?
Is this something that started recently?
The first table is running the ripgrep command, without outputting the results (to test that ripgrep itself is faster in remote, and that the time it takes locally roughly matches the local experience inside VSCode of 0-2s)
The second table is ripgrep sending the results over SSH. In this case, remote is way slower than local, and roughly matches the experience inside VSCode (5-7s). This is what makes me think that the problem is in the VSCode implementation, which seems to be getting the full results of ripgrep over the network and then filtering locally.
The second table is ripgrep sending the results over SSH. In this case, remote is way slower than local, and roughly matches the experience inside VSCode (5-7s). This is what makes me think that the problem is in the VSCode implementation, which seems to be getting the full results of ripgrep over the network and then filtering locally.
I'm having difficulty understanding this. Filtering happens on the ripgrep side (remote), then results are sent over. For example, you can see in the command that file exclusions are accounted for when we run ripgrep. To me, it makes sense that not outputting the results would run similarly to local, since you're not sending output through the network. Could you help me with your understanding of this?
Ripgrep is being called with --files, which according to the docs:
Print the files that ripgrep would search, but don't actually search them.
As I understand this, what the VSCode implementation is doing is listing all the files included in the project, and then performing the search on that results, to display which files' names match the search query. Given the results that I observe, and how the times match, I think that the problem is that the actual filtering happens in the frontend, after transferring the full list over SSH.
I might be wrong, though, and it would be super helpful if you could check the actual implementation :)
Oh right, you're talking about the fuzzy search filtering; for some reason, I was thinking about the exclude/include filtering. Could you do the following?
- In the command palette,
Show Running Extensions. - Press the record button to start a profile. Run a search, then stop the recording and save the profile to a file.
Then, can you send the perf profile here?
Here it is: CPU-20230619T181335.406Z.cpuprofile.txt
Have you had a chance to verify my hypothesis, though? I think we have a smoking gun there!
For reference, you can see what the search looks like:
Some of the search filtering happens at the extension (remote) side, but it still might send a lot of matches locally if there are many results (although we still have a limit there of ~500 results).
Perhaps this has to do with the tree-walking logic that we do on the extension side, but I don't think there's an easy way to profile the remote extension host. On the remote side, if you open the Process explorer in VS Code, is the remote extension host consuming lots of CPU when you do a search?
I don't see anything particularly spiky here:
https://github.com/microsoft/vscode/assets/104916/6cd428bc-c11b-4e80-8e0c-c51428586e14
Hmm, there doesn't seem to be anything spiking there. If you use the Developer: Measure Extension Host Latency command, what do you get? Apologies for the delayed response.
Roundtrip latency: 0.330ms
Up: 3587.4 Mbps
Down: 2693.6 Mbps
Authority: ssh-remote+speed
Roundtrip latency: 160.520ms
Up: 334.9 Mbps
Down: 228.2 Mbps
Some of the search filtering happens at the extension (remote) side, but it still might send a lot of matches locally if there are many results (although we still have a limit there of ~500 results).
What number is that ~500. I just tried
$VSCODE_LOCATION/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!/bazel-*/**' -g '!/build/**' -g '!/src_transform_out/**' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-config | head -n500 -
and it's immediate (<1s)
Hey @andreamah, this issue might need further attention.
@marianosimone, you can help us out by closing this issue if the problem no longer exists, or adding more information.
This issue has been closed automatically because it needs more information and has not had recent activity. See also our issue reporting guidelines.
Happy Coding!
@andreamah please consider re-opening this issue, as it hasn't been fixed, and I don't know what other information you need from me. Happy to provide more!
Just FYI, this issue is mentioned frequently internally as a sore spot with remote development, especially for power users. Some folks are hesitating to switch to remote development despite many other benefits because of it. It would be a huge deal if it were fixed.
Hi, apologies for the long wait. For this, I've added some extra logging to see if the bottleneck is truly on result post-processing.
If you do the following:
- Run
Developer: Set Log Levelin the command palette and setDebug. - Do a search.
- In the bottom panel, check logs in the
Extension Host (Remote)channel in theOutputstab.
I added logs that look like:
2023-12-12 14:43:12.007 [debug] ExtHostSearch Search finished. Stats: {"cmdTime":59,"fileWalkTime":59,"directoriesWalked":0,"filesWalked":0,"cmdResultCount":17}
2023-12-12 14:43:12.008 [debug] Ext host file search time: 60ms
2023-12-12 14:43:12.261 [debug] Ext host file search time: 4ms
What do you see when you do this?
This is great, thanks for following up! I'll report back in the next couple of days, as the new version trickles down to our users
Edit: @andreamah , was this released in 1.85.1? I'm using:
Version: 1.85.1 (Universal)
Commit: 0ee08df0cf4527e40edc9aa28f4b5bd38bbff2b2
And I still don't see those log lines. I only get:
2023-12-21 15:29:57.814 [debug] ExtHostSearch /pay/home/marianosimone/.vscode-server/bin/0ee08df0cf4527e40edc9aa28f4b5bd38bbff2b2/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive --no-require-git -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!/bazel-*/**' -g '!/build/**' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-config
- cwd: /<my_dir>
- Sibling clauses: {}
Sorry, it looks like the log is only available on the Insiders version. Can you try that?
Got it working on Insiders:
2024-01-02 19:12:50.992 [debug] ExtHostSearch /<my_root>/.vscode-server-insiders/cli/servers/Insiders-9621add46007f7a1ab37d1fce9bcdcecca62aeb0/server/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive --no-require-git -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!/bazel-*/**' -g '!/build/**' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-ignore-parent --no-config --no-ignore-global
- cwd: /<my_src_root>
- Sibling clauses: {}
2024-01-02 19:12:57.127 [debug] Ext host file search time: 5478ms
2024-01-02 19:12:57.279 [debug] ExtHostSearch Search finished. Stats: {"cmdTime":6314,"fileWalkTime":6314,"directoriesWalked":0,"filesWalked":0,"cmdResultCount":434732}
2024-01-02 19:12:57.279 [debug] Ext host file search time: 6314ms
@andreamah any updates on this? This problem keeps being a showstopper for us to get widespread adoption of remote VSCode development.
I actually started looking at this again today (apologies again for popping in and out), and I found that the cancellation going into the extension host side wasn't going through properly (?). Therefore, when you type many characters, this might be causing backlog on the extension host thread. However, I need to look a little more into why this might be happening (or whether it is actually the cause, since this code seems quite old).
One question I had for you though: does your project have lots of symlinks? The behavior above would describe issues when typing out a word, but not if you did something like paste the whole word.
Thanks for looking into this!
Some observations from my testing:
- This happens regardless of typing 1, 2, or many characters
- This happens regardless of typing vs pasting
- We do not have lots of symlinks
I'd really like you to reconsider the findings in this comment, as it indicates that the searching itself is not the issue, but the network transfer.
2024-01-02 19:12:50.992 [debug] ExtHostSearch /<my_root>/.vscode-server-insiders/cli/servers/Insiders-9621add46007f7a1ab37d1fce9bcdcecca62aeb0/server/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive --no-require-git -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!/bazel-*/**' -g '!/build/**' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-ignore-parent --no-config --no-ignore-global - cwd: /<my_src_root> - Sibling clauses: {} 2024-01-02 19:12:57.127 [debug] Ext host file search time: 5478ms 2024-01-02 19:12:57.279 [debug] ExtHostSearch Search finished. Stats: {"cmdTime":6314,"fileWalkTime":6314,"directoriesWalked":0,"filesWalked":0,"cmdResultCount":434732} 2024-01-02 19:12:57.279 [debug] Ext host file search time: 6314ms
Hmm... If you try to fetch those logs again, is this only a sliver of your wait time? This is the process of actually 'finding' the files on the target machine, meaning that it doesn't include any of the logic on the main process. We transfer ~512 file results through the wire at max, which shouldn't be too intensive, but I could be wrong.