cargo fmt is slow without a fresh registry index

[mzabaluev]

Problem
cargo fmt --all runs unexpectedly slow in a medium-sized workspace project.

Steps

1. Run a GitHub workflow that runs cargo fmt --all on the repository.
2. Check execution time.

This run shows cargo pausing for more than 20 s before producing any output in verbose mode. Seen with timestamps in the raw log:

2020-06-08T17:05:32.3268959Z [command]/usr/share/rust/.cargo/bin/cargo fmt --all --verbose -- --check --verbose
2020-06-08T17:05:55.8733086Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/btree/benches/benchmark.rs"

Notes

Output of cargo version:
cargo 1.44.0 (05d080f 2020-05-06)

Virtual environment information from GitHub workflow:
Operating System
Ubuntu
18.04.4
LTS
Virtual Environment
Environment: ubuntu-18.04
Version: 20200518.1
Included Software: https://github.com/actions/virtual-environments/blob/ubuntu18/20200518.1/images/linux/Ubuntu1804-README.md

[ehuss]

This is an issue for the https://github.com/rust-lang/rustfmt/issues repo, do you mind moving it over there?

[mzabaluev]

This is an issue for the https://github.com/rust-lang/rustfmt/issues repo, do you mind moving it over there?

OK, I was not sure which tool is at fault here.

[mzabaluev]

Here's a more extensive log excerpt that suggests rustfmt is not run before the initial slowdown happens:

2020-06-09T04:14:29.1017365Z [command]/usr/share/rust/.cargo/bin/cargo fmt --all --verbose -- --check --verbose
2020-06-09T04:14:52.2134027Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/btree/benches/benchmark.rs"
2020-06-09T04:14:52.2134740Z [example (2018)] "/home/runner/work/chain-libs/chain-libs/btree/examples/blockindex.rs"
2020-06-09T04:14:52.2139952Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/btree/src/lib.rs"
2020-06-09T04:14:52.2140924Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/cardano-legacy-address/benches/cbor.rs"
2020-06-09T04:14:52.2141755Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/cardano-legacy-address/src/lib.rs"
2020-06-09T04:14:52.2142669Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-addr/src/lib.rs"
2020-06-09T04:14:52.2143457Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-core/src/lib.rs"
2020-06-09T04:14:52.2144280Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/chain-crypto/benches/sumed25519.rs"
2020-06-09T04:14:52.2145090Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/chain-crypto/benches/vrf.rs"
2020-06-09T04:14:52.2152550Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-crypto/src/lib.rs"
2020-06-09T04:14:52.2153921Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-impl-mockchain/src/lib.rs"
2020-06-09T04:14:52.2154743Z [custom-build (2018)] "/home/runner/work/chain-libs/chain-libs/chain-network/build.rs"
2020-06-09T04:14:52.2155529Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-network/src/lib.rs"
2020-06-09T04:14:52.2156472Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-ser/src/lib.rs"
2020-06-09T04:14:52.2157250Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/chain-storage/benches/storage.rs"
2020-06-09T04:14:52.2158283Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-storage/src/lib.rs"
2020-06-09T04:14:52.2159283Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-test-utils/src/lib.rs"
2020-06-09T04:14:52.2160067Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/chain-time/src/lib.rs"
2020-06-09T04:14:52.2161033Z [bench (2018)] "/home/runner/work/chain-libs/chain-libs/imhamt/benches/imhamt.rs"
2020-06-09T04:14:52.2162410Z [example (2018)] "/home/runner/work/chain-libs/chain-libs/imhamt/examples/memdump/main.rs"
2020-06-09T04:14:52.2163590Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/imhamt/src/lib.rs"
2020-06-09T04:14:52.2164410Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/sparse-array/src/lib.rs"
2020-06-09T04:14:52.2165934Z [lib (2018)] "/home/runner/work/chain-libs/chain-libs/typed-bytes/src/lib.rs"
2020-06-09T04:14:52.2168998Z rustfmt --edition 2018 --check --verbose /home/runner/work/chain-libs/chain-libs/btree/benches/benchmark.rs /home/runner/work/chain-libs/chain-libs/btree/examples/blockindex.rs /home/runner/work/chain-libs/chain-libs/btree/src/lib.rs /home/runner/work/chain-libs/chain-libs/cardano-legacy-address/benches/cbor.rs /home/runner/work/chain-libs/chain-libs/cardano-legacy-address/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-addr/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-core/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-crypto/benches/sumed25519.rs /home/runner/work/chain-libs/chain-libs/chain-crypto/benches/vrf.rs /home/runner/work/chain-libs/chain-libs/chain-crypto/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-impl-mockchain/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-network/build.rs /home/runner/work/chain-libs/chain-libs/chain-network/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-ser/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-storage/benches/storage.rs /home/runner/work/chain-libs/chain-libs/chain-storage/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-test-utils/src/lib.rs /home/runner/work/chain-libs/chain-libs/chain-time/src/lib.rs /home/runner/work/chain-libs/chain-libs/imhamt/benches/imhamt.rs /home/runner/work/chain-libs/chain-libs/imhamt/examples/memdump/main.rs /home/runner/work/chain-libs/chain-libs/imhamt/src/lib.rs /home/runner/work/chain-libs/chain-libs/sparse-array/src/lib.rs /home/runner/work/chain-libs/chain-libs/typed-bytes/src/lib.rs

[mzabaluev]

I've found the cause: a fresh checkout of the crates.io-index repository in ~/.cargo/repository/index was needed to make cargo fmt run fast. This run shows the effect of having the index restored from a recent cache.

It's odd, though, that the fmt command should depend so much on the state of dependencies that it does not need to work.

[ehuss]

Sorry, I should have specified in my comment. The issue is here where cargo-fmt calls cargo metadata for every package, twice. It should only call it once for the entire workspace. I was going to make some recommendations over on the rustfmt tracker.

[mzabaluev]

OK, let's track it in rust-lang/rustfmt#4247 then.