Alex Profiles Cargo and `-j28`

# Alex Profiles Cargo and `-j28` > **OVERALL CONCLUSIONS** > > * Rayon's new scheduler is likely to help quite a bit > * We shouldn't spin up all $ncores threads immediately, but lazily once jobserver tokens are acquired. --- Setup (as of 2019-10-28) ``` $ rustup-toolchain-install-master 8d78bf6b273848d17da8f5c92162c6a6b9b10dfd --alt ``` ## Total Build Time Benchmark: ``` rm -rf target && RUSTFLAGS=-Zthreads=N cargo +8d78bf6b273848d17da8f5c92162c6a6b9b10dfd-alt check ``` Uses [rust-lang/cargo@8ac9868](https://github.com/rust-lang/cargo/tree/8ac9868554edfbc9afda63666187aec0ac6199da) | N | Total Runtime | |---|--------------| | 1 | 27.97s | | 2 | 20.90s | | 5 | 16.45s | | 10 | 15.36s | | 15 | 15.84s | | 20 | 16.93s | | 28 | 20.13s | | 28 (no jobserver) | 16.42s | **Conclusion**: throwing more cores at the problem doesn't help, but it should in theory in the compiler's case. Now... why? Watching `htop` Alex sees a "ton of red" in the beginning of the highly-parallel builds, corresponding to kernel time (green == user/compiler time). Let's drill down to the first few seconds of the build... ## Crates in the first 3 seconds Benchmark: ``` rm -rf target RUSTFLAGS=-Zthreads=N /usr/bin/time --verbose cargo +8d78bf6b273848d17da8f5c92162c6a6b9b10dfd-alt check & sleep 3 pkill cargo ``` Eyeball how many crates finished in the first 3 seconds. Basically just watch cargo's progress bar and try to see the highest-flashing number for `A/B` and `A` is listed in the below chart | N | Crates finished | User time | System time | CPU usage | Voluntary Context Switches | Involuntary Context Switches | |-|-|-|-|-|-|-| | 1 | 101 | 34.04 | 3.29 | 1240% | 9935 | 4432 | | 2 | 105 | 43.16 | 3.98 | 1561% | 23672 | 8969 | | 5 | 106 | 50.58 | 6.18 | 1882% | 130602 | 44064 | | 10 | 102 |41.95 |17.03 |1955% | 502164 | 132882 | 15 | 87 |35.51 | 31.46 | 2220% |1044746 | 301839 | | 20 | 74 | 22.27 | 41.06 | 2098% |1342144 |293478 | 25 | 55 | 10.83 | 30.57 | 1371% |923744 |119497 | | 28 | 45 | 6.98 | 22.05 | 952% | 651657 | 76945 | | 28 (no jobserver) | 86 | 51.01 | 13.70 | 2084% | 88015 | 12975163 | **Conclusion**: A few things here: * This is only profiling the first 3 seconds of the build, clearly we're actually doing less useful work (building crates) in the first few seconds the more threads we have * This shows with lots of threads (NCPUs) we're spending most of our time in the kernel (system) * CPU usage actually goes down after a peak around 15-or so cores (this is a 14-core, 28-hyperthread machine) Now... why? (again) Where is rustc spending all of its system time in the 28 core case? ## Profiling the first 3 seconds Benchmark: ``` rm -rf target RUSTFLAGS=-Zthreads=N perf trace -o foo --sort-events --summary -m 10000 cargo +8d78bf6b273848d17da8f5c92162c6a6b9b10dfd-alt check & sleep 3 pkill cargo ``` Afterwards run `perf`'s output through [this script](https://gist.github.com/alexcrichton/4e5f8cacc2704b7cf401a69ef114cdad) to coalesce all of the rustc processes together For reference, here's the [syscall tracing of the `8d78bf6b273848d17da8f5c92162c6a6b9b10dfd` compiler but **not the `alt` build**](https://gist.github.com/alexcrichton/1a9254607a0f1bcfd3808f7686d2c6b8) ``` syscall calls total min avg max (msec) (msec) (msec) (msec) ----------------- -------- ------------ --------- --------- --------- futex 50875 39358.928 0.001 0.774 1136.257 poll 165 6102.146 0.001 36.983 486.924 clone 1486 744.527 0.000 0.501 6.794 read 6737 501.563 0.001 0.074 116.370 execve 224 212.375 0.088 0.948 7.486 openat 26291 129.690 0.001 0.005 17.379 ``` (beats me what's calling `futex` so much) Here's a the [syscall tracing for `-Zthreads=1`](https://gist.github.com/alexcrichton/e556d4b3b76d992ceb3e2227bac43e99) ``` syscall calls total min avg max (msec) (msec) (msec) (msec) ----------------- -------- ------------ --------- --------- --------- futex 48081 46073.051 0.001 0.958 1337.679 poll 498 13252.854 0.001 26.612 410.973 read 6694 4626.946 0.001 0.691 185.860 clone 1436 668.062 0.000 0.465 4.526 execve 210 173.977 0.089 0.828 4.802 openat 24631 122.444 0.001 0.005 19.582 ``` And finally here's the tracing of [`-Zthreads=28`](https://gist.github.com/alexcrichton/925e130c9186270247100a50f271b226): ``` syscall calls total min avg max (msec) (msec) (msec) (msec) ----------------- -------- ------------ --------- --------- --------- sched_yield 1164147 4015660.951 0.000 3.449 749.758 futex 52421 870192.378 0.000 16.600 2150.744 read 10917 652812.564 0.000 59.798 923.119 poll 7497 533212.946 0.000 71.124 2211.468 write 8880 84570.321 0.000 9.524 924.179 munmap 5318 19269.749 0.000 3.623 790.732 ``` **Conclusion**: * The **non-`alt` build** looks pretty similar to the `-Zthreads=1` build * The 28 build has **way more `sched_yield`, nearly 4 seconds of CPU time in this syscall** * The 28-core build has ~3x more `clone` calls (threads?) * 62084948.72% more time is spent in `sched_yield` * 1788.72% more time is spent in `futex` * A huge amount more time is spent in `poll`/`read`/`write` but that's perhaps expected with the jobserver * Oddly a massive amount of time is spent in `statx` Or putting those stats another way, compared the the `-Zthreads=1` build the `-Zthreads=28` build has the following syscalls wall times (relative to `-Zthreads=1`) ``` sched_yield 62084948.72% futex 1788.72% read 14008.93% poll 3923.38% write 114056.18% munmap 18277.52% statx 113131.67% clone 1674.51% madvise 21560.76% sigaltstack 291954.29% close 80810.97% openat 3225.59% lstat 8444.54% mmap 2512.42% ``` And an additional trace of [`-Zthreads=28`](https://gist.github.com/alexcrichton/8b545412e8651536a352e5c6f09eb65c) but without a jobserver: ``` syscall calls total min avg max (msec) (msec) (msec) (msec) ----------------- -------- ------------ --------- --------- --------- sched_yield 6646397 1581419.050 0.000 0.238 2036.300 futex 73860 1543195.593 0.000 20.894 2218.186 munmap 5421 130169.709 0.000 24.012 2105.350 madvise 1529 43459.340 0.000 28.423 2049.319 sigaltstack 4676 14620.113 0.001 3.127 2104.617 poll 27 11241.993 0.000 416.370 1356.360 clone 3325 9244.359 0.000 2.780 414.609 read 3173 4941.834 0.000 1.557 1075.522 ```

Syntax	Example	Reference
# Header	Header	基本排版
- Unordered List	Unordered List
1. Ordered List	Ordered List
- [ ] Todo List	Todo List
> Blockquote	Blockquote
Bold font	Bold font
Italics font	Italics font
~~Strikethrough~~	~~Strikethrough~~
19^th^	19^th
H~2~O	H₂O
++Inserted text++	Inserted text
==Marked text==	Marked text
[link text](https:// "title")	Link
![image alt](https:// "title")	Image
`Code`	`Code`	在筆記中貼入程式碼
```javascript var i = 0; ```	`var i = 0;`
:smile:		Emoji list
{%youtube youtube_id %}	Externals
$L^aT_eX$	L^aT_eX
:::info This is a alert area. :::	This is a alert area.