search

microsoft / WSL

Issues found on WSL
https://docs.microsoft.com/windows/wsl
MIT License
17.45k stars 822 forks source link

Intriguing slow RSYNC issue temporarily fixed by slack call #12043

Open paimfp opened 1 month ago

paimfp commented 1 month ago

Windows Version

Microsoft Windows [Version 10.0.22631.4169]

WSL Version

2.2.4.0

Are you using WSL 1 or WSL 2?

Kernel Version

5.15.153.1-2

Distro Version

Ubuntu 20.04

Other Software

VPN

Repro Steps

I have a dev setup to do a build locally ( Angular) and rsync dist files to a dev server using SSH ( much faster and use less server resources ): The script that I use: rsync -arvzh --del --compress-level=4 --progress "$sourcePath" "$destPath"; where $sourcePath is on my local linux and $destPath is path for dev the server.

Expected Behavior

rsync to upload the files with reasonable speed and time.

Actual Behavior

In the last file and biggest one ( around 13MB ) it takes minutes hanging after it successfully completes.

And the weird part is, if I do a slack call with a colleague, it gets MUCH faster. and keeps fast until reboot.

Diagnostic Logs

My /etc/wsl.conf file:

[network] generateResolvConf = true [interop] enabled = true search ###.com

I logget rsync with super verbose option and with time on each line on each scenario and results are incredibly different.

SLOW:

[13:29:59] opening connection using: ssh dev rsync --server -vvvlogDtprze.iLsfxC --compress-level=4 --delete-during . ###/dist/ (9 args) [13:30:02] sending incremental file list [13:30:02] [sender] make_file(.,,0) [13:30:02] [sender] pushing local filters for ###/dist/ [13:30:02] [sender] make_file(styles.c8c20d060ea3628b.css,,2) [13:30:02] [sender] make_file(app.html,,2) [13:30:02] [sender] make_file(289.054cb82ff4eada84.js,,2) [13:30:02] [sender] make_file(853.581a703fd7e7c0ba.js,,2) [13:30:02] [sender] make_file(vendor.49dc3eb2ff7461e2.js,,2) [13:30:02] [sender] make_file(polyfills-core-js.1a569dc597e4a97b.js,,2) [13:30:02] [sender] make_file(625.2729bbe582944a03.js,,2) [13:30:02] [sender] make_file(113.98fbefcb36e75770.js,,2) [13:30:02] [sender] make_file(polyfills.749b4791c60c08da.js,,2) [13:30:02] [sender] make_file(polyfills-dom.d6f548fbb79677f1.js,,2) [13:30:02] [sender] make_file(763.e6ddd16a01bfd7a0.js,,2) [13:30:02] [sender] make_file(common.50ec3f7169bfc778.js,,2) [13:30:02] [sender] make_file(916.d5470cf48673035d.js,,2) [13:30:02] [sender] make_file(827.e44b63e01c3d5700.js,,2) [13:30:02] [sender] make_file(388.576b50c5744a5a1d.js,,2) [13:30:02] [sender] make_file(901.78013c14c6e332bb.js,,2) [13:30:02] [sender] make_file(runtime.92301a61a136ff44.js,,2) [13:30:02] [sender] make_file(polyfills-css-shim.b7104271783cd4fb.js,,2) [13:30:02] [sender] make_file(main.7ffdc36f0d4a760a.js,,2) [13:30:02] [sender] make_file(570.d2f4ca6ff2a1ab90.js,*,2) [13:30:02] send_file_list done [13:30:02] send_files starting [13:30:34] renaming .app.html.7MKkU9 to app.html [13:30:34] recv_files(common.50ec3f7169bfc778.js) [13:30:34] recv_files(main.7ffdc36f0d4a760a.js) [13:30:34] recv_files(polyfills-core-js.1a569dc597e4a97b.js) [13:30:34] recv_files(polyfills-css-shim.b7104271783cd4fb.js) [13:30:34] recv_files(polyfills-dom.d6f548fbb79677f1.js) [13:30:34] recv_files(polyfills.749b4791c60c08da.js) [13:30:34] recv_files(runtime.92301a61a136ff44.js) [13:30:34] recv_files(styles.c8c20d060ea3628b.css) [13:30:34] recv_files(vendor.49dc3eb2ff7461e2.js) [13:33:13] got file_sum [13:33:13] set modtime of .vendor.49dc3eb2ff7461e2.js.kF9Uvw to (1726072193) Wed Sep 11 12:29:53 2024 [13:33:13] renaming .vendor.49dc3eb2ff7461e2.js.kF9Uvw to vendor.49dc3eb2ff7461e2.js [13:33:13] set modtime of . to (1726072193) Wed Sep 11 12:29:53 2024 [13:33:13] send_files phase=1 [13:33:13] recv_files phase=1 [13:33:13] generate_files phase=2 [13:33:13] send_files phase=2 [13:33:13] send files finished [13:33:13] total: matches=0 hash_hits=0 false_alarms=0 data=13607672 [13:33:14] recv_files phase=2 [13:33:14] recv_files finished [13:33:14] generate_files phase=3 [13:33:14] generate_files finished [13:33:14] sent 2.62M bytes received 6.00K bytes 13.48K bytes/sec [13:33:14] total size is 18.96M speedup is 7.23 [13:33:14] [sender] _exit_cleanup(code=0, file=main.c, line=1205): about to call exit(0)

Omitted part of initial log because it's very fast and big, but notice the time difference between line recv_files(vendor.49dc3eb2ff7461e2.js) and got file_sum. Around 3 minutes!

And this is same log after a slack call:

[12:30:23] sending incremental file list [12:30:23] deleting vendor.f159212e7e88ebc5.js [12:30:23] ./ [12:30:23] app.html [12:30:23] 498 100% 0.00kB/s 0:00:00
498 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=9/21) [12:30:23] vendor.7d63711cb38f9129.js [12:30:24] 32.77K 0% 31.25MB/s 0:00:00
12.78M 93% 10.31MB/s 0:00:00
13.61M 100% 10.91MB/s 0:00:01 (xfr#2, to-chk=0/21) [12:30:26] [12:30:26] Number of files: 21 (reg: 20, dir: 1) [12:30:26] Number of created files: 1 (reg: 1) [12:30:26] Number of deleted files: 1 (reg: 1) [12:30:26] Number of regular files transferred: 2 [12:30:26] Total file size: 18.96M bytes [12:30:26] Total transferred file size: 13.61M bytes [12:30:26] Literal data: 13.61M bytes [12:30:26] Matched data: 0 bytes [12:30:26] File list size: 0 [12:30:26] File list generation time: 0.001 seconds [12:30:26] File list transfer time: 0.000 seconds [12:30:26] Total bytes sent: 2.62M [12:30:26] Total bytes received: 100 [12:30:26] [12:30:26] sent 2.62M bytes received 100 bytes 402.50K bytes/sec [12:30:26] total size is 18.96M speedup is 7.25

Note the whole rsync process takes around 4 seconds!

github-actions[bot] commented 1 month ago

Logs are required for review from WSL team

If this a feature request, please reply with '/feature'. If this is a question, reply with '/question'. Otherwise please attach logs by following the instructions below, your issue will not be reviewed unless they are added. These logs will help us understand what is going on in your machine.

How to collect WSL logs Download and execute [collect-wsl-logs.ps1](https://github.com/Microsoft/WSL/blob/master/diagnostics/collect-wsl-logs.ps1) in an **administrative powershell prompt**: ``` Invoke-WebRequest -UseBasicParsing "https://raw.githubusercontent.com/microsoft/WSL/master/diagnostics/collect-wsl-logs.ps1" -OutFile collect-wsl-logs.ps1 Set-ExecutionPolicy Bypass -Scope Process -Force .\collect-wsl-logs.ps1 ``` The script will output the path of the log file once done. If this is a networking issue, please use [collect-networking-logs.ps1](https://github.com/Microsoft/WSL/blob/master/diagnostics/collect-networking-logs.ps1), following the instructions [here](https://github.com/microsoft/WSL/blob/master/CONTRIBUTING.md#collect-wsl-logs-for-networking-issues) Once completed please upload the output files to this Github issue. [Click here for more info on logging](https://github.com/microsoft/WSL/blob/master/CONTRIBUTING.md#8-collect-wsl-logs-recommended-method) If you choose to email these logs instead of attaching to the bug, please send them to wsl-gh-logs@microsoft.com with the number of the github issue in the subject, and in the message a link to your comment in the github issue and reply with '/emailed-logs'.

View similar issues

Please view the issues below to see if they solve your problem, and if the issue describes your problem please consider closing this one and thumbs upping the other issue to help us prioritize it!

Open similar issues:

Closed similar issues:

Note: You can give me feedback by thumbs upping or thumbs downing this comment.

github-actions[bot] commented 1 month ago

No logs.etl found in the archive. Make sure that you ran collect-wsl-logs.ps1 as administrator and that the logs.etl file is in the archive.

Diagnostic information ``` .wslconfig found Detected appx version: 2.2.4.0 optional-components.txt not found No logs.etl found in archive. Error while parsing the logs. See action page for details ```
github-actions[bot] commented 1 month ago

No logs.etl found in the archive. Make sure that you ran collect-wsl-logs.ps1 as administrator and that the logs.etl file is in the archive.

Diagnostic information ``` appxpackage.txt not found optional-components.txt not found No logs.etl found in archive. Error while parsing the logs. See action page for details ```
paimfp commented 1 month ago

WslNetworkingLogs-2024-09-17_10-43-57.zip

github-actions[bot] commented 1 month ago
Diagnostic information ``` .wslconfig found Detected appx version: 2.2.4.0 optional-components.txt not found ```
OneBlue commented 1 month ago

Thank you @paimfp. This is a very interesting case. I wonder if this is something that's accentuated by a VPN / AV solution on your machine.

Does disconnecting from the VPN affect the transfer speed ?

paimfp commented 1 month ago

Sure @OneBlue , thanks for looking into it. It took me a good amount of weeks to even notice the slack pattern, but I can reproduce consistently now.

Hmm. I'm not sure how to test that, because I can't reach the server without the VPN for security.

OneBlue commented 1 month ago

Do you see the same behavior if you run rsync on a machine that's on your local network ?

paimfp commented 1 month ago

Ok, I took some time to do a real test, I set a free temp VPS remotely, and had the same problem with VPN off. So the issue does not seem to be on VPN nor the company server. It was actually much slower, probably due to the server is less powerful being free and all, Around 5 minutes on that last file...:

[09:55:57] sending incremental file list [09:55:57] ./ [09:55:57] 113.b143eb8157ac2ddc.js 561.34K 100% 100.82MB/s 0:00:00 (xfr#1, to-chk=19/21) [09:55:57] 289.c3509c6e01ea6b0e.js 249.90K 100% 29.79MB/s 0:00:00 (xfr#2, to-chk=18/21) [09:55:57] 388.576b50c5744a5a1d.js 42.42K 100% 4.50MB/s 0:00:00 (xfr#3, to-chk=17/21) [09:55:57] 570.d2f4ca6ff2a1ab90.js 9.60K 100% 1.02MB/s 0:00:00 (xfr#4, to-chk=16/21) [09:55:57] 625.2729bbe582944a03.js 282.79K 100% 22.47MB/s 0:00:00 (xfr#5, to-chk=15/21) [09:55:57] 763.e6ddd16a01bfd7a0.js 505.01K 100% 24.08MB/s 0:00:00 (xfr#6, to-chk=14/21) [09:55:57] 827.e44b63e01c3d5700.js 578.36K 100% 21.21MB/s 0:00:00 (xfr#7, to-chk=13/21) [09:55:57] 853.581a703fd7e7c0ba.js 1.68M 100% 32.10MB/s 0:00:00 (xfr#8, to-chk=12/21) [09:55:57] 901.78013c14c6e332bb.js 63.90K 100% 1.22MB/s 0:00:00 (xfr#9, to-chk=11/21) [09:55:57] 916.55f374226a859f5b.js 470.07K 100% 8.01MB/s 0:00:00 (xfr#10, to-chk=10/21) [09:55:57] app.html 498 100% 8.68kB/s 0:00:00 (xfr#11, to-chk=9/21) [09:55:57] common.50ec3f7169bfc778.js 4.14K 100% 72.13kB/s 0:00:00 (xfr#12, to-chk=8/21) [09:55:57] main.15a229ae645e50dd.js 539.28K 100% 8.16MB/s 0:00:00 (xfr#13, to-chk=7/21) [09:55:57] polyfills-core-js.1a569dc597e4a97b.js 155.84K 100% 2.29MB/s 0:00:00 (xfr#14, to-chk=6/21) [09:55:57] polyfills-css-shim.b7104271783cd4fb.js 13.48K 100% 202.60kB/s 0:00:00 (xfr#15, to-chk=5/21) [09:55:57] polyfills-dom.d6f548fbb79677f1.js 27.26K 100% 403.29kB/s 0:00:00 (xfr#16, to-chk=4/21) [09:55:57] polyfills.749b4791c60c08da.js 145.70K 100% 2.04MB/s 0:00:00 (xfr#17, to-chk=3/21) [09:55:57] runtime.5c4d6f8c8c3fdf2a.js 15.10K 100% 216.84kB/s 0:00:00 (xfr#18, to-chk=2/21) [09:55:57] styles.c8c20d060ea3628b.css 8.12K 100% 116.60kB/s 0:00:00 (xfr#19, to-chk=1/21) [09:55:57] vendor.fe9484990446fb21.js 13.60M 100% 128.12kB/s 0:01:43 (xfr#20, to-chk=0/21) [10:00:19] [10:00:19] sent 3.57M bytes received 399 bytes 13.29K bytes/sec [10:00:19] total size is 18.96M speedup is 5.31

paimfp commented 1 month ago

And... the mysterious slack call made it faster too ( I removed the files from server to get it fresh like the other upload ):

[10:08:56] sending incremental file list [10:08:56] ./ [10:08:56] 113.b143eb8157ac2ddc.js 561.34K 100% 100.82MB/s 0:00:00 (xfr#1, to-chk=19/21) [10:08:56] 289.c3509c6e01ea6b0e.js 249.90K 100% 29.79MB/s 0:00:00 (xfr#2, to-chk=18/21) [10:08:56] 388.576b50c5744a5a1d.js 42.42K 100% 4.50MB/s 0:00:00 (xfr#3, to-chk=17/21) [10:08:56] 570.d2f4ca6ff2a1ab90.js 9.60K 100% 1.02MB/s 0:00:00 (xfr#4, to-chk=16/21) [10:08:56] 625.2729bbe582944a03.js 282.79K 100% 22.47MB/s 0:00:00 (xfr#5, to-chk=15/21) [10:08:56] 763.e6ddd16a01bfd7a0.js 505.01K 100% 22.93MB/s 0:00:00 (xfr#6, to-chk=14/21) [10:08:56] 827.e44b63e01c3d5700.js 578.36K 100% 20.43MB/s 0:00:00 (xfr#7, to-chk=13/21) [10:08:56] 853.581a703fd7e7c0ba.js 1.68M 100% 32.10MB/s 0:00:00 (xfr#8, to-chk=12/21) [10:08:57] 901.78013c14c6e332bb.js 63.90K 100% 1.19MB/s 0:00:00 (xfr#9, to-chk=11/21) [10:08:57] 916.55f374226a859f5b.js 470.07K 100% 7.86MB/s 0:00:00 (xfr#10, to-chk=10/21) [10:08:57] app.html 498 100% 8.53kB/s 0:00:00 (xfr#11, to-chk=9/21) [10:08:57] common.50ec3f7169bfc778.js 4.14K 100% 70.86kB/s 0:00:00 (xfr#12, to-chk=8/21) [10:08:57] main.15a229ae645e50dd.js 539.28K 100% 8.16MB/s 0:00:00 (xfr#13, to-chk=7/21) [10:08:57] polyfills-core-js.1a569dc597e4a97b.js 155.84K 100% 2.29MB/s 0:00:00 (xfr#14, to-chk=6/21) [10:08:57] polyfills-css-shim.b7104271783cd4fb.js 13.48K 100% 199.53kB/s 0:00:00 (xfr#15, to-chk=5/21) [10:08:57] polyfills-dom.d6f548fbb79677f1.js 27.26K 100% 403.29kB/s 0:00:00 (xfr#16, to-chk=4/21) [10:08:57] polyfills.749b4791c60c08da.js 145.70K 100% 2.01MB/s 0:00:00 (xfr#17, to-chk=3/21) [10:08:57] runtime.5c4d6f8c8c3fdf2a.js 15.10K 100% 213.70kB/s 0:00:00 (xfr#18, to-chk=2/21) [10:08:57] styles.c8c20d060ea3628b.css 8.12K 100% 114.91kB/s 0:00:00 (xfr#19, to-chk=1/21) [10:08:57] vendor.fe9484990446fb21.js 13.60M 100% 10.25MB/s 0:00:01 (xfr#20, to-chk=0/21) [10:08:59] [10:08:59] sent 3.57M bytes received 399 bytes 419.68K bytes/sec [10:08:59] total size is 18.96M speedup is 5.31

paimfp commented 1 month ago

I started to noticed this after windows 11 upgrade.

I have a feeling it has to do with this issue, but it's just a guess: #9430