Telling when cargo has finished each crate


#1

My codebase is broken up into a little ecosystem of about 25 crates. cargo prints a message each time it starts compiling a crate, but never prints anything when it finishes, even when -vv is supplied. So oftentimes during a long build my console looks like this:

   Compiling rayon-core v1.3.0
   Compiling netlib-src v0.7.4
   Compiling syn v0.12.14
   Compiling serde_derive v1.0.18
   Compiling indoc v0.2.3
   Compiling enum-map v0.2.24
   Compiling chrono v0.4.0
   Compiling failure v0.1.1
   Compiling rayon v0.8.2
   Compiling frunk_derives v0.2.0
   Compiling bindgen v0.31.3
   Compiling rsp2-assert-close v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/util/assert-close)
   Compiling rsp2-soa-ops v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/util/soa-ops)
   Compiling vasp-poscar v0.1.1
 (loooooooong pause)

and I actually have no idea which of the last 8 or so crates listed is the one that’s taking so long to compile. (all I know is that it can’t possibly be vasp-poscar which takes 4 seconds to build on its own).

I mean, I guess I could just Ctrl-C it and re-issue the build command (in which case the culprit will be the first crate to appear), but it’d be nice if such information could come from cargo. (along with the time that each crate took)


#2

It could use indicatif to show active spinners next to each crate in progress.


#3

Multiple spinners? So such a crate does exist!!

I had found spinner earlier but it made me sad.


#4

Uh, I’d love that!


#5

You can use cargo build --jobs 1 (or -j) to build one crate at a time. You can also build a specific crate using the -p/--package argument: cargo build -p rsp2-assert-close.

(sometimes I use --jobs 1 with cargo install if I’m updating things like clippy in the background while I’m working on something else)


#6

So I did the following:

$ cat lag.py
# Each time a line is received from stdin, print the *previous* line.
# This is makes the output of `ts -i` more meaningful.
import sys
prev = None
for line in sys.stdin:
    if prev is not None:
        print(prev, end=''); sys.stdout.flush()
    prev = line
print(prev, end=''); sys.stdout.flush()

$ cargo build --release --jobs 1 2>&1 | python3 lag.py | ts -i | tee timings

And the results:

$ sort timings | tail
00:00:21    Compiling rsp2-structure-io v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/io/structure)
00:00:23    Compiling syn v0.12.14
00:00:25    Compiling regex v0.2.2
00:00:42    Compiling serde_derive v1.0.59
00:00:53    Compiling rsp2-tasks-config v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/tasks/config)
00:01:01    Compiling syn v0.14.0
00:01:07    Compiling lapack-src v0.1.4
00:01:33    Compiling clap v2.27.1
00:01:50    Compiling rsp2-tasks v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/tasks)
00:10:19    Compiling cexpr v0.2.2

cexpr? Whaaaat?

After further investigation, I found the true “10 minute culprit” is actually netlib-src. It turns out that even with --jobs 1, cargo starts building other packages while netlib-src is busy running cmake, hence the timestamp appearing on cexpr. (humorously, it also appears that the --jobs 1 setting is propagated down to cmake, because without the setting, that crate builds in ~4 minutes).

How about the things that are actually in my own code?

$ sort timings | grep rsp2 | tail
00:00:02    Compiling rsp2-soa-ops v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/util/soa-ops)
00:00:03    Compiling rsp2-lammps-wrap v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/io/lammps)
00:00:05    Compiling rsp2-array-types v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/util/array-types)
00:00:08    Compiling rsp2-minimize v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/minimize)
00:00:09    Compiling rsp2 v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2)
00:00:15    Compiling rsp2-structure v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/structure)
00:00:16    Compiling rsp2-phonopy-io v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/io/phonopy)
00:00:21    Compiling rsp2-structure-io v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/io/structure)
00:00:53    Compiling rsp2-tasks-config v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/tasks/config)
00:01:50    Compiling rsp2-tasks v0.1.0 (file:///home/lampam/cpp/other/rust/rsp2/src/tasks)
  • It looks like serde_yaml Deserialize codegen is (still) incredibly time-consuming. This is something I discovered a year ago, and it’s the reason why rsp2-tasks-config exists.

    Despite taking 50s, rsp2-tasks-config contains nothing but some struct defs, and a couple of monomorphic wrappers around serde_yaml::from_reader. (this also may explain the rsp2-phonopy-io and rsp2-structure-io build times, which are another 30s total; they too have monomorphic yaml deserialization functions)

  • rsp2-array-types (0:05) has a lot of code generated through macros, but most of it is polymorphic (and has aggressive inline annotations on top of that) so I did not expect to see much here. (I rarely touch the crate, so maybe I should do something to get more codegen happening there)

  • rsp2-structure (0:15) has a lot of floating point math and is almost entirely monomorphic. It also makes heavy use of rsp2-array-types (which as previously mentioned is aggressively inlined). So I guess there is something to be gained by factoring out heavy floating point math.

  • rsp2-tasks (1:50) is a smorgasboard so I can’t tell anything from that. (it’s where I plan to use this information!)