Slow install possibly from downloads

[passcod]

Moving from #19 to avoid pinging everyone with more back and forth:

---

Can you provide that log again but with --json-output and at trace level so we can see where the time spent is? thanks

I've done the same steps as before (uninstall, turn off AV), here's the command I ran:

$ cargo binstall cargo-nextest -y --log-level trace --json-output

Log: contents.log

---

Looking at the log myself, the 2 things that take the longest are the download from crates.io and the download from GitHub. Why is that? I have a gigabit fiber connection (and a speed test proves that), so it's not my internet being slow. I'm clueless.

Originally posted by @Sculas in #19 (comment)

[passcod]

Just to check, could you download https://github.com/nextest-rs/nextest/releases/download/cargo-nextest-0.9.57/cargo-nextest-0.9.57-x86_64-pc-windows-msvc.tar.gz manually (over the cli e.g. with curl or iex)?

I do think however that it's probably not that, and instead maybe to do with how we stream to tar directly @NobodyXu?

[Sculas]

Just to check, could you download https://github.com/nextest-rs/nextest/releases/download/cargo-nextest-0.9.57/cargo-nextest-0.9.57-x86_64-pc-windows-msvc.tar.gz manually (over the cli e.g. with curl or iex)?

Sure!

$ time { iwr https://github.com/nextest-rs/nextest/releases/download/cargo-nextest-0.9.57/cargo-nextest-0.9.57-x86_64-pc-windows-msvc.tar.gz -OutFile out.tar.gz }
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 1
Milliseconds      : 224
Ticks             : 12242446
TotalDays         : 1,41694976851852E-05
TotalHours        : 0,000340067944444444
TotalMinutes      : 0,0204040766666667
TotalSeconds      : 1,2242446
TotalMilliseconds : 1224,2446

out.tar.gz contains the cargo-nextest.exe file, so it successfully downloaded it.

PS: time is not a builtin command, it's a function I've defined in my PowerShell profile which looks like this:

function time($block) {
    $sw = [Diagnostics.Stopwatch]::StartNew()
    &$block
    $sw.Stop()
    $sw.Elapsed
}

[NobodyXu]

I've checked the log, downloading and processing the cargo-nextest crate tarball takes about 2s which is not as fast as I would expect but acceptable.

However, there's a 45s gap before that due to rate-limit.

Downloading and extract the cargo-nextest binary takes 46s, which is indeed a problem.
I'm not sure what caused that, maybe the way we do the disk I/O doesn't make windows happy?

[NobodyXu]

cc @simonsan I think you encountered a similar problem here.
Just cc you so that you are aware of the discussion here and feel free to comment on anything we missed or you think it's worth mentioning.

[NobodyXu]

It's really strange, I can install cargo-nextest within 8s on my terribly slow Australia NBN network.

[simonsan]

cc @simonsan I think you encountered a similar problem here. Just cc you so that you are aware of the discussion here and feel free to comment on anything we missed or you think it's worth mentioning.

Only check

It takes 1 minutes for not even installing anything, for example.

cargo binstall cargo-nextest -y
 WARN Failed to read git credential file C:\Users\dailyuse\.git-credentials err=Os { code: 2, kind: NotFound, message: "The system cannot find the file specified." }
 INFO resolve: Resolving package: 'cargo-nextest'
 INFO resolve: cargo-nextest v0.9.57 is already installed, use --force to override
 INFO Done in 60.6370694s

Log for that here: cargo-binstall.log

With --force

Installing takes 3 Minutes.

PS C:\Users\dailyuse> cargo binstall cargo-nextest -y --force
 WARN Failed to read git credential file C:\Users\dailyuse\.git-credentials err=Os { code: 2, kind: NotFound, message: "The system cannot find the file specified." }
 INFO resolve: Resolving package: 'cargo-nextest'
 WARN The package cargo-nextest v0.9.57 will be downloaded from github.com
 INFO This will install the following binaries:
 INFO   - cargo-nextest.exe (cargo-nextest.exe -> C:\Users\dailyuse\.cargo\bin\cargo-nextest.exe)
 INFO Installing binaries...
 INFO Done in 177.3222273s

Log with --force here: cargo-binstall.log

Timing

time { iwr https://github.com/nextest-rs/nextest/releases/download/cargo-nextest-0.9.57/cargo-nextest-0.9.57-x86_64-pc-windows-msvc.tar.gz -OutFile out.tar.gz }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 1
Milliseconds      : 468
Ticks             : 14681117
TotalDays         : 1.69920335648148E-05
TotalHours        : 0.000407808805555556
TotalMinutes      : 0.0244685283333333
TotalSeconds      : 1.4681117
TotalMilliseconds : 1468.1117

[NobodyXu]

Thanks, @simonsan @Sculas can you guys try the latest main build?
I added more logs to main since there seems to be a 30s-45s gap where nothing is logged at all even though it should be doing resolution by fetching from crates.io

[Sculas]

Thanks, can you guys try the latest main build?
I added more logs to main since there seems to be a 30s-45s gap where nothing is logged at all even though it should be doing resolution by fetching from crates.io

I've installed commit 3e67e36 and followed the same steps as before.
Indeed, much more is logged now, including hyper and trust-dns-resolver trace logs. However, this also logs some other stuff, such as your DNS server, which is not very ideal in some cases (mine was still from my ISP instead of CF, oops).

Now then, as for that gap, I think I have an idea. I've taken a look at the logs, and I'm starting to suspect trust-dns-resolver here. One potentially important note, I have IPv6 enabled.
What I see here is that it tries to connect to a DNS server, but continuously times out, waits 5s, tries again, and times out again. After some time, it fails with a Windows API error and then it does connect. Looks kind of like this, but not SRV/TXT related: https://github.com/bluejekyll/trust-dns/issues/1636#issuecomment-1079445663
Others also seemed to have slowness issues with trust-dns on Windows: Barre/privaxy#23, prisma/prisma-engines#2694

Either way, these are my current findings in the short time I had. Tomorrow, I'll send the logs (after I've cleaned them a bit) so we can take a look further.

[NobodyXu]

Thank you @Sculas !

trust-dns-resolver recently released v0.23.0, so I wonder if upgrading to it would fix the problem.
I've opened seanmonstar/reqwest#1965 in reqwest and hope it will merge soon

[Sculas]

Sorry that it took so long, but here's the log file (gist because it's 31MB, lol): raw gist

[GNQG]

After some investigation I guessed the potential problem of this issue is seanmonstar/reqwest#431 (comment). I tried manually set-upping name server config for reqwest client with dns_resolver to avoid listing up all adapter settings: cb40519.

CC @simonsan @Sculas can you try my patch cb40519?

[Sculas]

After some investigation I guessed the potential problem of this issue is seanmonstar/reqwest#431 (comment).

Well, isn't this interesting! I never thought I needed to mention it, but yeah, I have VMware installed, so I also have all of these network adapters (but from VMware instead of VirtualBox), as mentioned in the comment you linked above. You know what? That might also explain why the logs say that the name servers don't match because those name servers are the IPv6 loopback address! (and I'm presuming trust-dns-resolver has no idea what to do with them because they're invalid?)

I've installed your patch, and... wow. Look what we have here:

# cargo binstall cargo-nextest -y
INFO resolve: Resolving package: 'cargo-nextest'
WARN The package cargo-nextest v0.9.57 (x86_64-pc-windows-msvc) has been downloaded from github.com
INFO This will install the following binaries:
INFO   - cargo-nextest.exe (cargo-nextest.exe -> C:\Users\$USER\.cargo\bin\cargo-nextest.exe)
INFO Installing binaries...
INFO Done in 1.4159677s

I can't thank you enough @GNQG for finding the problem and fixing it!
@NobodyXu, can we look into merging this patch so that this issue can be closed?

[Sculas]

So, I got curious. It seems like just disabling the trust-dns feature in crates/bin/Cargo.toml also works, see my patch: Sculas@4881396

[NobodyXu]

@GNQG Thanks for your patch!

I've skimmed through it and it seems more reasonable to be in reqwest, can you open a PR in upstream?

I will upgrade reqwest to latest as soon as it is released.

[simonsan]

What a ride! <3

[NobodyXu]

After thinking on this again, @GNQG I am willing to accept your patch and cut a new release to fix this issue.

Then we can consider upstreaming this to reqwest.

[NobodyXu]

@GNQG If you are busy, I can merge the code into main for you.