Slow incremental build/test workflow.

[rcgoodfellow]

tl;dr; A single-line change in a saga has a 10-minute build penalty for running tests. I'm developing on a 64-core machine with 256G of RAM using NVMe disks with trim enabled.

I run tests with cargo nextest run. I do not typically use -p as it's not always clear what packages my changes may intersect with. In these cases, I feel like the build system should be the one figuring out what needs to be rebuilt and not the user. It's also not clear why a change in a saga, which is seemingly near the top of the build pyramid, would cause a rebuild of unrelated testing packages.

Here is what a test run looks like with no-compilation, e.g. just running the tests.

real     3:32.627233210
user  3:35:25.998393895
sys   1:11:30.318353845
trap     2:22.183659850
tflt        4.635349996
dflt       47.150890796
kflt        0.837772914
lock 1751:11:53.945211231
slp  36:06:41.425071578
lat   3:53:12.177588657
stop  3:41:12.590832239

Here is a one-line change to saga code.

real    14:04.030041228
user  4:02:55.102264210
sys   1:07:44.130983296
trap     2:29.129798646
tflt        2.271531121
dflt       31.685564198
kflt        0.299503476
lock 1771:59:46.664672742
slp  38:27:07.709200291
lat   4:01:12.321380386
stop  3:54:09.085315193

Within that time the build time is the majority as reported by cargo.

Finished test [unoptimized + debuginfo] target(s) in 10m 29s

[internet-diglett]

Some additional tests, also running on illumos.

System Specifications:

Ryzen 5950x (16c / 32t, Base Clock 3.4GHz, Boost up to 4.9Ghz)
128 GB RAM running @ 3200
Dedicated 1 TB Samsung NVME (OS is running on a separate NVME)

Clean and Build roundtrip times

cargo clean && ptime -m cargo build

real     4:46.005452752
user    43:57.502065154
sys      8:42.829707839
trap        2.247956401
tflt        2.673304572
dflt        3.661350049
kflt        0.017162225
lock  1:13:34.345323723
slp   1:32:29.511645923
lat      1:27.684343420
stop     8:28.648802889

$ du -Ash target
31.9G	target

$ cargo clean && ptime -m cargo nextest run
[cargo nextest]
Summary [ 168.925s] 794 tests run: 794 passed (5 slow, 1 leaky), 2 skipped

[ptime]
real    12:11.677374521
user  3:05:58.623930006
sys     30:48.644936368
trap       34.106167448
tflt        9.639465852
dflt       14.283905823
kflt        0.288599200
lock 309:53:28.524718771
slp  16:57:48.486904890
lat     44:10.005121372
stop    59:03.009517416

$ du -Ash target
78.1G	target

Observations

Looks like test builds a lot more stuff, compared to the normal debug build. Target dir increased by over 2x.

Actual test runtime took ~2 min 49 seconds, so the increase in ptime stats seems to also be mostly due to building the additional test binaries.

[rcgoodfellow]

Running with -p omicron-nexus does not make a big difference.

ry@masaka:~/src/omicron$ cargo nextest run -p omicron-nexus
warning: ignoring unknown configuration keys in config file /home/ry/src/omicron/.config/nextest.toml: nexte
st-version
   Compiling omicron-nexus v0.1.0 (/home/ry/src/omicron/nexus)
   Compiling mg-admin-client v0.1.0 (/home/ry/src/omicron/mg-admin-client)
    Finished test [unoptimized + debuginfo] target(s) in 10m 20s
    Starting 317 tests across 4 binaries

I was watching htop for this one. The linker took up ~ 8m 50s minutes of that 10m 20s.

[smklein]

NOTE TO READER: THE FOLLOWING ARE ALL ON A 32 GiB, 16 CORE LINUX SYSTEM

I tried setting up an incremental rebuild of Nexus, using the following command:

$ touch nexus/src/lib.rs && cargo build --timings -p omicron-nexus --tests

I observed build times of roughly 50 seconds, with the following --timing info:

There are a couple takeaways from this:

• The majority of our time is spent building the Nexus library
• All downstream tests and binaries still take a while to build
• Tests take a fair bit longer to build than the normal binaries, though they're both slow

This seems really odd to me, in particular for schema-updater, because it should be a really thing binary, but it's still taking 10+ seconds to build.

Running the following command, I tried to inspect the schema-updater binary size:

size -A -d schema-updater  | awk '{print $2,$1}' | tail -n +3 | numfmt --field=1 --to=iec-i --suffix=B | sort -h
0B .tm_clone_table
8B .fini_array
13B .fini
16B .init_array
24B .rela.plt
27B .init
28B .gnu.hash
28B .interp
32B .got.plt
32B .note.ABI-tag
34B .debug_gdb_scripts
36B .note.gnu.build-id
48B .plt
48B .plt.got
120B .tdata
165B .comment
328B .tbss
424B .data
704B .dynamic
768B .gnu.version_r
1.4KiB .bss
2.0KiB .gnu.version
4.6KiB .gcc_except_table
17KiB .dynstr
22KiB .rodata.cst
24KiB .dynsym
68KiB .debug_macro
193KiB .got
230KiB .eh_frame_hdr
340KiB .data.rel.ro
448KiB .rodata
736KiB .eh_frame
997KiB .rela.dyn
2.4MiB .debug_abbrev
4.0MiB .debug_frame
5.7MiB .text
8.1MiB .debug_aranges
12MiB .debug_loc
19MiB .debug_ranges
37MiB .debug_line
213MiB .debug_info
397MiB .debug_pubnames
663MiB .debug_str
743MiB .debug_pubtypes
2.1GiB Total

(The Nexus binary itself is very similar in size, coming in at 2.2 GiB)

The default profile.dev option for Debug is 2. By setting it to `1, this binary size is significantly reduced (this is the schema-updater again):

0B .tm_clone_table
8B .fini_array
13B .fini
16B .init_array
24B .rela.plt
27B .init
28B .gnu.hash
28B .interp
32B .got.plt
32B .note.ABI-tag
34B .debug_gdb_scripts
36B .note.gnu.build-id
48B .plt
48B .plt.got
120B .tdata
165B .comment
328B .tbss
424B .data
704B .dynamic
768B .gnu.version_r
1.4KiB .bss
2.0KiB .gnu.version
4.6KiB .gcc_except_table
17KiB .dynstr
22KiB .rodata.cst
24KiB .dynsym
68KiB .debug_macro
89KiB .debug_pubtypes
191KiB .got
229KiB .eh_frame_hdr
340KiB .data.rel.ro
447KiB .rodata
710KiB .debug_abbrev
721KiB .eh_frame
992KiB .rela.dyn
3.9MiB .debug_frame
4.8MiB .text
7.8MiB .debug_aranges
11MiB .debug_ranges
31MiB .debug_info
35MiB .debug_line
379MiB .debug_pubnames
436MiB .debug_str
910MiB Total

Additionally, the total build time seems to be reduced a fair bit:

[smklein]

Setting debug = 0 in [profile.dev] of Cargo.toml brings this down even further:

[jmpesp]

Setting debug = 0 in [profile.dev] of Cargo.toml brings this down even further

I'm seeing a pretty good bump from this. Using a fresh checkout of omicron:

# cargo clean + cargo build

    Finished dev [unoptimized + debuginfo] target(s) in 5m 41s

real     5:41.684878634
user    52:01.649785641
sys     10:20.348812801
trap        2.118963336
tflt       10.500090796
dflt       11.440283705
kflt        0.603422488
lock  1:39:59.263917987
slp   2:11:25.139189481
lat      1:37.587088675
stop    10:27.215142698

# one line change in nexus/src/app/sagas/switch_port_settings_apply.rs, then cargo build

    Finished dev [unoptimized + debuginfo] target(s) in 1m 16s

real     1:16.668390021
user     1:34.092838558
sys      1:02.971599531
trap        0.013044407
tflt        0.001391870
dflt        0.420686927
kflt        0.000000000
lock     5:16.007108476
slp     10:58.984496465
lat         0.236748885
stop        0.280932951

Then setting debug = 0:

# cargo clean + cargo build

    Finished dev [unoptimized] target(s) in 4m 03s

real     4:03.711154640
user    38:45.185029976
sys      7:39.982399942
trap        1.445820996
tflt        3.634785810
dflt        2.003498021
kflt        0.000645907
lock  1:00:08.045694370
slp   1:28:24.252445845
lat      1:33.636755682
stop    10:18.723593083

# one line change in nexus/src/app/sagas/switch_port_settings_apply.rs, then cargo build

    Finished dev [unoptimized] target(s) in 38.04s

real       38.186279952
user       41.574763210
sys        11.621525240
trap        0.006395064
tflt        0.001001251
dflt        0.022501930
kflt        0.000015539
lock     2:22.804716633
slp      3:52.751385681
lat         0.025387724
stop        0.255555593

Edit:

Ryzen 3950x (16c / 32t, base: 3.5GHz, boost: 4.7GHz)
128GB DDR4
500G sata ssd

[david-crespo]

Seeing a big improvement from debug = 0 on mac too.

[rcgoodfellow]

This did not result in a large difference for me.

ry@masaka:~/src/omicron$ ptime -m cargo nextest run
warning: ignoring unknown configuration keys in config file /home/ry/src/omicron/.config/nextest.toml: nextest-version
   Compiling omicron-nexus v0.1.0 (/home/ry/src/omicron/nexus)
   Compiling omicron-dev-tools v0.1.0 (/home/ry/src/omicron/dev-tools)
    Finished test [unoptimized] target(s) in 9m 55s

[rcgoodfellow]

I tried the same workflow on Linux. The following is for a one-line saga change recompile.

ry@rytk2:~/src/omicron$ time cargo nextest run
   Compiling omicron-nexus v0.1.0 (/home/ry/src/omicron/nexus)
   Compiling omicron-dev-tools v0.1.0 (/home/ry/src/omicron/dev-tools)
    Finished test [unoptimized + debuginfo] target(s) in 2m 01s
    Starting 805 tests across 95 binaries (2 skipped)

I do not have mold or lld installed on this system, so this should just be using the standard linux linker.

ry@rytk2:~$ ls -l /usr/bin/ld
lrwxrwxrwx 1 root root 19 Jun  3 23:49 /usr/bin/ld -> x86_64-linux-gnu-ld

This machine is significantly less capable than my regular dev machine. It has a 6-core Xeon Mobile E-2176M processor and 64G of RAM.

[rcgoodfellow]

Using mold on Linux is about twice as fast. But I also noticed something weird. When I make a one-line change in a file with my editor (vim) and then save, cargo will re-compile things on the next two invocations of cargo nextest. Even weirder, this redundant compilation does not happen when using touch instead of adding a one-line comment to a source file.

#
# makes chanes in file
# 

ry@rytk2:~/src/omicron$ time cargo nextest run --no-run
   Compiling omicron-nexus v0.1.0 (/home/ry/src/omicron/nexus)
   Compiling omicron-dev-tools v0.1.0 (/home/ry/src/omicron/dev-tools)
    Finished test [unoptimized + debuginfo] target(s) in 1m 07s

real	1m7.938s
user	3m33.098s
sys	0m38.624s
ry@rytk2:~/src/omicron$ time cargo nextest run --no-run
   Compiling omicron-nexus v0.1.0 (/home/ry/src/omicron/nexus)
   Compiling omicron-dev-tools v0.1.0 (/home/ry/src/omicron/dev-tools)
    Finished test [unoptimized + debuginfo] target(s) in 44.23s

real	0m44.624s
user	1m8.197s
sys	0m18.583s
ry@rytk2:~/src/omicron$ time cargo nextest run --no-run
    Finished test [unoptimized + debuginfo] target(s) in 0.85s

real	0m1.223s
user	0m1.470s
sys	0m1.232s

[smklein]

One more data point:

[profile.dev]
debug = "line-tables-only"  # This required an update to 1.71.0!

This still preserves backtraces, but otherwise removes all debug info from the binaries.

Considering that the default option for release builds already removes all this debug info, I think this is a worthwhile inclusion. I'll put up a PR soon with this change, which should be one small step towards alleviating this pain during incremental development.

[smklein]

Created #4025 + #4026