Intriguing slow RSYNC issue temporarily fixed by slack call

[paimfp]

Windows Version

Microsoft Windows [Version 10.0.22631.4169]

WSL Version

2.2.4.0

Are you using WSL 1 or WSL 2?

• WSL 2
• WSL 1

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]

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 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, following the instructions here

Once completed please upload the output files to this Github issue.

Click here for more info on logging
If you choose to email these logs instead of attaching to the bug, please send them to [email protected] 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:

• Very slow network speeds (#8171), similarity score: 0.72

Closed similar issues:

• Re-open #2138 - WSL hangs on rsync/ssh (#11112), similarity score: 0.70

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

[github-actions]

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]

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]

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

[github-actions]

Diagnostic information

.wslconfig found
Detected appx version: 2.2.4.0
optional-components.txt not found

[OneBlue]

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]

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]

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

[paimfp]

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]

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]

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