I was curious to explore how long a program takes to run, how much memory is used over time, and what processes/threads are spawned. To provide answers I wrote a tool, which I named st. Here are a few things I looked into.
See details at the bottom if you are interested in how the tool works (and why I did not use time(1) and strace(1)).
An entertaining way to use st is so to predict the outcome of a command and explore the reasons for discrepancies. I started with a simple C program, fill.c allocating 1GiB and setting each byte individually.
#include <stdio.h> #include <stdlib.h> #include <stdint.h> void fill(uint8_t* addr, size_t amount, char value) { for (size_t i = 0; i < amount; i++) { *(addr + i) = value; } } int main(int argc, char **argv) { size_t s = 1<<30; uint8_t* buffer = (uint8_t*)malloc(s); fill(buffer, s, atoi(argv[0])); return EXIT_SUCCESS; }
Let's build and run it via st.
$ clang -o fill fill.c
$ sudo st fill
EXEC: [/home/leaf/fill]
Num threads = 1
Num process = 1
Max PSS: 1,073,762,304 bytes
Walltime: 1,229ms - user-space: 1,109ms - kernel-space: 87ms
1┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ██████┃ ┃ ████████████┃ ┃ █████████████████┃ ┃ ██████████████████████┃ ┃ ████████████████████████████┃ ┃ █████████████████████████████████┃ ┃ ███████████████████████████████████████┃ ┫ ████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0GB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0s 1
I expected 1GiB to be filled in 10ms but it took a whole second. The issue is that the program is generating many page faults. I remember Firefox sped up their startup time 2x by solving a similar issue[1].
Also noteworthy, the memory usage did not increase abruptly from 0 to 1GiB with malloc. Instead we see a staircase pattern which shows that physical RAM consumption increased as virtual pages were written to by the fill function.
Another test program, fillfill.c, to check the tool is properly tracking PSS, processes, and threads.
#include <stdio.h> #include <stdlib.h> #include <unistd.h> #include <sys/wait.h> #include <stdint.h> void malloc_and_fill(size_t s) { uint8_t* buffer = (uint8_t*) malloc(s); for (size_t i = 0; i < s; i++) { *(buffer+ i) = 'F'; } free(buffer); } int main(int argc, char **argv) { malloc_and_fill(1L << 30); int pid = fork(); if (pid == 0) { malloc_and_fill(1L << 31); } else { waitpid(pid, NULL, 0); } return 0; }
First allocate 1GiB, free it, then spawn a process which does the same but with 2GiB.
$ sudo st ./fillfill
EXEC: [./fillfill]
Num threads = 2
Num process = 2
Max PSS: 2,147,591,168 bytes
Walltime: 3,608ms - user-space: 3,277ms - kernel-space: 327ms
2┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ███ ┃ ┃ ███████ ┃ ┃ ██████████ ┃ ┃ ██████████████ ┃ ┃ ███████████████████ ┃ ┃ ██████████████████████ ┃ ┃ ██████████████████████████ ┃ ┫ █ ██████████████████████████████ ┃ ┃ ██████ █████████████████████████████████ ┃ ┃ █████████ █████████████████████████████████████ ┃ ┃ █████████████ █████████████████████████████████████████ ┃ ┃ █████████████████ ████████████████████████████████████████████ ┃ ┃ ████████████████████ ████████████████████████████████████████████████ ┃ ┃ ████████████████████████ ████████████████████████████████████████████████████ ┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0GB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0s 3
Let's get back to fill.c but this time compile it with full optimization (-O3).
$ clang -o fillo -O3 fill.c $ sudo st fillo EXEC:: [ /home/leaf/fillo] Num threads = 1 Num process = 1 Max PSS: 164,864 bytes Walltime: 5ms - user-space: 1ms - kernel-space: 0ms
164┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┫█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0KB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 0
Wow. From 1000ms to 5ms. And only using 164 KiB?! According to Binary Ninja[2], the compiler discarded both malloc and fill. It makes sense since the program did not read what was allocated and written. Flag -O3 effectively turned fill.c into an empty main function.
int main(int argc, char **argv) { return EXIT_SUCCESS; }
Sidenote: Exploring compiler -O3 outputs with Binary Ninja is a source of endless amazement. Loop to memset substitution (fill.c, cc, cc -O3), strlen caching ...even without -O3 (strlen.c, cc, cc -O3), and printf("%c", 'x') to putchar('x')!) substitution are only a few among many cool optimizations.
I have written extensively about compiler drivers by the past so it was a good opportunity to double check that clang behaved as expected when compiling hello.c.
#include <stdio.h> int main() { printf("Hello, World!"); return 0; }
$ sudo st clang -o hello hello.c EXEC:: [ clang -o hello hello.c] EXEC:: [/usr/lib/llvm-14/bin/clang -cc1 -triple aarch64-unknown-linux-gnu -emit-obj -mrelax-all --mrelax-relocations -disable-free -clear-ast-before-backend -disable-llvm-verifier -discard-value-names -main-file-name hello.c -mrelocation-model pic -pic-level 2 -pic-is-pie -mframe-pointer=non-leaf -fmath-errno -ffp-contract=on -fno-rounding-math -mconstructor-aliases -funwind-tables=2 -target-cpu generic -target-feature +neon -target-feature +v8a -target-abi aapcs -fallow-half-arguments-and-returns -mllvm -treat-scalable-fixed-error-as-warning -debugger-tuning=gdb -fcoverage-compilation-dir=/home/leaf -resource-dir /usr/lib/llvm-14/lib/clang/14.0.0 -internal-isystem /usr/lib/llvm-14/lib/clang/14.0.0/include -internal-isystem /usr/local/include -internal-isystem /usr/bin/../lib/gcc/aarch64-linux-gnu/11/../../../../aarch64-linux-gnu/include -internal-externc-isystem /usr/include/aarch64-linux-gnu -internal-externc-isystem /include -internal-externc-isystem /usr/include -fdebug-compilation-dir=/home/leaf] EXEC:: [/usr/bin/ld -pie -EL -z relro --hash-style=gnu --build-id --eh-frame-hdr -m aarch64linux -dynamic-linker /lib/ld-linux-aarch64.so.1 -o hello /lib/aarch64-linux-gnu/Scrt1.o /lib/aarch64-linux-gnu/crti.o /usr/bin/../lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/bin/../lib/gcc/aarch64-linux-gnu/11 -L/lib/aarch64-linux-gnu -L/usr/lib/aarch64-linux-gnu -L/usr/lib/llvm-14/bin/../lib -L/lib -L/usr/lib /tmp/hello-df1527.o -lgcc --as-needed -lgcc_s --no-as-needed -lc -lgcc --as-needed -lgcc_s --no-as-needed /usr/bin/../lib/gcc/aarch64-linux-gnu/11/crtendS.o /lib/aarch64-linux-gnu/crtn.o ] Num threads = 3 Num process = 3 Max PSS: 90,911,744 bytes Walltime: 71ms - user-space: 24ms - kernel-space: 45ms
63┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ████████┃ ┃ ██████████┃ ┃ ███████████████┃ ┃ █████████████████┃ ┃ ██████████████████████┃ ┃ ████████████████████████┃ ┃ █████████████████████████████┃ ┫ ████████████████████████████████████┃ ┃ ██████████████████████████████████████┃ ┃ █████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 36
Without surprise, we see two forks. One when the driver invokes the compiler and one to invoke the linker. There is no assembler step since it is built-in clang.
After clang, let's check gcc.
$ sudo st gcc -o hello hello.c EXEC:: [ gcc -o hello hello.c] EXEC:: [/usr/lib/gcc/aarch64-linux-gnu/11/cc1 -quiet -imultiarch aarch64-linux-gnu hello.c -quiet -dumpbase hello.c -dumpbase-ext .c -mlittle-endian -mabi=lp64 -fasynchronous-unwind-tables -fstack-protector-strong -Wformat -Wformat-security -fstack-clash-protection -o /tmp/ccmt0cw6.s ] EXEC:: [as -EL -mabi=lp64 -o /tmp/ccSRW1gq.o /tmp/ccmt0cw6.s ] EXEC:: [/usr/lib/gcc/aarch64-linux-gnu/11/collect2 -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/cceZH2hF.res -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lc -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro -o hello /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/ccSRW1gq.o -lg] EXEC:: [/usr/bin/ld -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/cceZH2hF.res -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lc -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lgcc_s --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro -o hello /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/ccSRW1gq.o -lgcc --push-state --as-needed -lg] Num threads = 5 Num process = 5 Max PSS: 18,597,888 bytes Walltime: 51ms - user-space: 20ms - kernel-space: 20ms
17┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ███████ ┃ ┃ ███████ ┃ ┃ █████████ ┃ ┃ █████████ ┃ ┃ ██████████████ ┃ ┃ ███████████████████ ┃ ┃ ████████████████████████ ┃ ┫ ██████████████████████████ ███████ ┃ ┃ ████████████████████████████ █████████ ┃ ┃ ███████████████████████████████ ███████████ ┃ ┃ ███████████████████████████████ ████████████████ ┃ ┃ ███████████████████████████████████ █████ ██████████████████ ┃ ┃ ██████████████████████████████████████ ████████ █████████████████████ ┃ ┃ ████████████████████████████████████████ ██████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 36
gcc uses two more steps than clang. One for the self-explanatory assembler as and one for the cryptic collect2. I read the documentation page but I still don't understand what it does.
Noteworthy, gcc uses four times less memory than clang.
Let's checkout the C++ compiler driver from LLVM suite with hello.cc.
#include <iostream> int main() { std::cout << "Hello World!"; return 0; }
$ sudo st clang++ hello.cc EXEC: [ clang++ /home/leaf/hello.cc] EXEC: [/usr/lib/llvm-14/bin/clang -cc1 -triple aarch64-unknown-linux-gnu -emit-obj -mrelax-all --mrelax-relocations -disable-free -clear-ast-before-backend -disable-llvm-verifier -discard-value-names -main-file-name hello.cc -mrelocation-model pic -pic-level 2 -pic-is-pie -mframe-pointer=non-leaf -fmath-errno -ffp-contract=on -fno-rounding-math -mconstructor-aliases -funwind-tables=2 -target-cpu generic -target-feature +neon -target-feature +v8a -target-abi aapcs -fallow-half-arguments-and-returns -mllvm -treat-scalable-fixed-error-as-warning -debugger-tuning=gdb -fcoverage-compilation-dir=/home/leaf/repos/st -resource-dir /usr/lib/llvm-14/lib/clang/14.0.0 -internal-isystem /usr/bin/../lib/gcc/aarch64-linux-gnu/11/../../../../include/c++/11 -internal-isystem /usr/bin/../lib/gcc/aarch64-linux-gnu/11/../../../../include/aarch64-linux-gnu/c++/11 -internal-isystem /usr/bin/../lib/gcc/aarch64-linux-gnu/11/../../../../include/c++/11/backward -internal-isystem /usr/lib/llvm-14/lib/clang/14.0.0/include -internal-isystem /u] EXEC: [/usr/bin/ld -pie -EL -z relro --hash-style=gnu --build-id --eh-frame-hdr -m aarch64linux -dynamic-linker /lib/ld-linux-aarch64.so.1 -o a.out /lib/aarch64-linux-gnu/Scrt1.o /lib/aarch64-linux-gnu/crti.o /usr/bin/../lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/bin/../lib/gcc/aarch64-linux-gnu/11 -L/lib/aarch64-linux-gnu -L/usr/lib/aarch64-linux-gnu -L/usr/lib/llvm-14/bin/../lib -L/lib -L/usr/lib /tmp/hello-32e667.o -lstdc++ -lm -lgcc_s -lgcc -lc -lgcc_s -lgcc /usr/bin/../lib/gcc/aarch64-linux-gnu/11/crtendS.o /lib/aarch64-linux-gnu/crtn.o ] Num threads = 3 Num process = 3 Max PSS: 127,156,224 bytes Walltime: 221ms - user-space: 136ms - kernel-space: 69ms
127┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ┃ ┃ ┃ ┃ █████████████ ┃ ┃ █ ██████████████████████████████████████ ┃ ┃ █ ███████████████████████████████████████████████ ┃ ┃ █ █████████████████████████████████████████████████ █ ████ ┃ ┃ █ ████████████████████████████████████████████████████████ ████████████┃ ┫ ███████████████████████████████████████████████████████████ █████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 221
No surprises here either. Compiling C++ is much more costly in terms of memory (2x), and takes much longer than hello.c (4x).
Let's checkout the C++ compiler driver from GNU suite, g++.
$ sudo st g++ hello.cc EXEC: [ g++ /home/leaf/hello.cc] EXEC: [/usr/lib/gcc/aarch64-linux-gnu/11/cc1plus -quiet -imultiarch aarch64-linux-gnu -D_GNU_SOURCE /home/leaf/hello.cc -quiet -dumpdir a- -dumpbase hello.cc -dumpbase-ext .cc -mlittle-endian -mabi=lp64 -fasynchronous-unwind-tables -fstack-protector-strong -Wformat -Wformat-security -fstack-clash-protection -o /tmp/ccBFHbve.s ] EXEC: [as -EL -mabi=lp64 -o /tmp/cckOP2RY.o /tmp/ccBFHbve.s ] EXEC: [/usr/lib/gcc/aarch64-linux-gnu/11/collect2 -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/ccpZysdX.res -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lc -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lgcc --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/cckOP2RY.o -lstdc++ -lm] EXEC: [/usr/bin/ld -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/ccpZysdX.res -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lgcc -plugin-opt=-pass-through=-lc -plugin-opt=-pass-through=-lgcc_s -plugin-opt=-pass-through=-lgcc --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/cckOP2RY.o -lstdc++ -lm -lgcc_s -lgcc -lc -lgcc_s -lgc] Num threads = 5 Num process = 5 Max PSS: 60,565,504 bytes Walltime: 232ms - user-space: 127ms - kernel-space: 48ms
60┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ████ ┃ ┃ ████████ ┃ ┃ █████████████ ┃ ┃ █████████████████ ┃ ┃ ██████████████████████ ┃ ┃ █████████████████████████ ┃ ┃ ████████████████████████████ ┃ ┫ ███████████████████████████████ ┃ ┃ ████████████████████████████████████ ┃ ┃ █████████████████████████████████████████ ┃ ┃ █████████████████████████████████████████████ █████ ┃ ┃ █████████████████████████████████████████████████ ██████ ┃ ┃ █████████████████████████████████████████████████████ █████████┃ ┃ ██████████████████████████████████████████████████████████ ███████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 232
Alike the C driver, gnu's version requires twice less RAM than clang++.
rustc has a reputation to be slow and memory hungry. Seems appropriate since it ran for nearly 200ms and used 131 MiB of RAM (roughly the same as clang++ hello.cc).
fn main() { println!("Hello World!"); }
rustc uses an embedded LLVM backend to generates object files. These are handed to the regular gnu suite with collect2 and then the linker ld.
$ sudo st rustc hello.rs EXEC:: [rustc hello.rs] EXEC:: [cc /tmp/rustc4fdpuV/symbols.o hello.hello.f76cf86e-cgu.0.rcgu.o hello.hello.f76cf86e-cgu.1.rcgu.o hello.hello.f76cf86e-cgu.2.rcgu.o hello.hello.f76cf86e-cgu.3.rcgu.o hello.hello.f76cf86e-cgu.4.rcgu.o hello.hello.f76cf86e-cgu.5.rcgu.o hello.2pelail77dwjevsg.rcgu.o -Wl,--as-needed -L /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib -Wl,-Bstatic /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libstd-1d2bb2d795f2ca05.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libpanic_unwind-f1c586c276421094.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libobject-8060a154fd842f2c.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libmemchr-1f7fc15c78d3bcac.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libaddr2line-965bde82ccc4b5e8.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libgimli-352be989f07a059f.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/librustc_demangle-4f461a85c762abbb.rlib /usr/lib/rustlib/aarch64-unknown-linux-gnu/lib/libstd_detect-814ef12b1b7d93c2.rlib /usr/lib/rustlib/aarch64-unknow] EXEC:: [/usr/lib/gcc/aarch64-linux-gnu/11/collect2 -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/ccXRoDto.res --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro -o hello /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/rustlib/aarch64-unknown-linux-gnu/lib -L/usr/lib/rustlib/aarch64-unknown-linux-gnu/lib -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/rustc4fdpuV/symbols.o hello.hello.f76cf86e-cgu.0.rcgu.o hello.hello.f76cf86e-c] EXEC:: [/usr/bin/ld -plugin /usr/lib/gcc/aarch64-linux-gnu/11/liblto_plugin.so -plugin-opt=/usr/lib/gcc/aarch64-linux-gnu/11/lto-wrapper -plugin-opt=-fresolution=/tmp/ccXRoDto.res --build-id --eh-frame-hdr --hash-style=gnu --as-needed -dynamic-linker /lib/ld-linux-aarch64.so.1 -X -EL -maarch64linux --fix-cortex-a53-843419 -pie -z now -z relro -o hello /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/Scrt1.o /usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu/crti.o /usr/lib/gcc/aarch64-linux-gnu/11/crtbeginS.o -L/usr/lib/rustlib/aarch64-unknown-linux-gnu/lib -L/usr/lib/rustlib/aarch64-unknown-linux-gnu/lib -L/usr/lib/gcc/aarch64-linux-gnu/11 -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../aarch64-linux-gnu -L/usr/lib/gcc/aarch64-linux-gnu/11/../../../../lib -L/lib/aarch64-linux-gnu -L/lib/../lib -L/usr/lib/aarch64-linux-gnu -L/usr/lib/../lib -L/usr/lib/gcc/aarch64-linux-gnu/11/../../.. /tmp/rustc4fdpuV/symbols.o hello.hello.f76cf86e-cgu.0.rcgu.o hello.hello.f76cf86e-cgu.1.rcgu.o hello.hello.f76cf86] Num threads = 14 Num process = 4 Max PSS: 131,376,128 bytes Walltime: 197ms - user-space: 134ms - kernel-space: 67ms
133┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ████████████████████████████████ ┃ ┃ █████████████████████████████████████████████ ┃ ┃ █ ████████████████████████████████████████████████ ┃ ┃ █████ ██████████████████████████████████████████████████ ┃ ┃ ███████ █████████████████████████████████████████████████████ ┃ ┃ █████████████████████████████████████████████████████████████████ ┃ ┃ ██████████████████████████████████████████████████████████████████ ┃ ┫ ██████████████████████████████████████████████████████████████████ ┃ ┃ ████████████████████████████████████████████████████████████████████ ┃ ┃ █████████████████████████████████████████████████████████████████████ ┃ ┃ ████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 220
Notice that fourteen threads were created. Ten of then are coming from rustc.
$ cat HelloWorld.java
class HelloWorld {
public static void main(String[] args) {
System.out.println("Hello, World!");
}
}
$ sudo st javac HelloWorld.java
EXEC:: [ javac HelloWorld.java]
Num threads = 23
Num process = 1
Max PSS: 75,673,600 bytes
Walltime: 272ms - user-space: 472ms - kernel-space: 48ms
75┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ███████████┃ ┃ ██████████████████████┃ ┃ ██████████████████████████████┃ ┃ ████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████┃ ┫ ████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 263
Since the compiler is written in Java, I was expecting to see a second process, execing something like java -cp javac.jar java.tools.Javac .... Surprisingly, javac is actually a JNI wrapper which acts as a launcher[3]. It instantiates a VM in-process and there is no fork/exec needed.
Also surprising is the number of threads created. Although the next test shows that it is probably just a thread pool created at startup regardless of what the VM actually does.
$ sudo st java -cp . HelloWorld
EXEC: [ java -cp /home/leaf HelloWorld]
Hello, World!
Num threads = 19
Num process = 1
Max PSS: 30,813,184 bytes
Walltime: 38ms - user-space: 10ms - kernel-space: 21ms
30┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ █████████████ ┃ ┃ ██████████████████████ ┃ ┃ █████████████████████████████ ┃ ┃ ██████████████████████████████████████████ ┃ ┃ ██████████████████████████████████████████ ┃ ┃ █████████████████████████████████████████████ ┃ ┃ █████████████████████████████████████████████ ┃ ┫ ███████████████████████████████████████████████ ┃ ┃ ███████████████████████████████████████████████████ ┃ ┃ ███████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 38
Same elevated number of thread as javac. Likely, javac only created four threads (23-19=4).
go stood up to its reputation of being fast. It generated an executable in 54ms while using only 15MiB of RAM. In this limited helloworld study, it is both the fastest and the least RAM hungry compiler.
package main import "fmt" func main() { fmt.Println("hello world") }
$ sudo st go build helloworld.go
EXEC:: [ go build helloworld.go]
Num threads = 9
Num process = 1
Max PSS: 15,591,424 bytes
Walltime: 54ms - user-space: 25ms - kernel-space: 39ms
15┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ █████████████████████████████████████┃ ┃ ███████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████┃ ┫ ████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████┃ ┃ █████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 53
Golang relies heavily on goroutines, I was surprised to see nine threads being used on a four core system. Something to look into someday.
$ sudo st chromium --headless https://fabiensanglard.net/index.html EXEC: [ chromium https://fabiensanglard.net/index.html] EXEC: [ chromium https://fabiensanglard.net/index.html] EXEC: [/snap/snapd/20102/usr/lib/snapd/snap-seccomp version-info ] Num threads = 21 Num process = 2 Max PSS: 32,493,568 bytes Walltime: 51ms - user-space: 639ms - kernel-space: 565ms
32┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ █ ┃ ┃ █ ┃ ┃ █ ████████████████████████████████████████████████████████████████████████┃ ┫ ██████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████┃ ┃ █ ███████████████████████████████████████████████████████████████████████████┃ ┃ ████ █████████████████████████████████████████████████████████████████████████████┃ ┃ ████ █████████████████████████████████████████████████████████████████████████████┃ ┃ ████ █████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 280
The process spawned by Chromium is for the GPU render. It looks like it also executed a command to check the version of seccomp before sandboxing the GPU.
$ sudo st curl https://fabiensanglard.net/index.html
EXEC: [ curl https://fabiensanglard.net/index.html]
Num threads = 2
Num process = 1
Max PSS: 4,878,336 bytes
Walltime: 356ms - user-space: 47ms - kernel-space: 7ms
4┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ █████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┫ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 356
$ sudo st wget https://fabiensanglard.net/index.html
EXEC: [ wget https://fabiensanglard.net/index.html]
Num threads = 1
Num process = 1
Max PSS: 2,942,976 bytes
Walltime: 348ms - user-space: 8ms - kernel-space: 8ms
2┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ █████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ██████████████████████████████████████████████████████████████████████████████████┃ ┫ ██████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ███████████████████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0ms 348
wget seems to use less RAM than curl. Also, it uses one thread instead of two.
Let's build a medium size project, git, with make.
$ sudo apt-get install dh-autoreconf libcurl4-gnutls-dev libexpat1-dev gettext libz-dev libssl-dev $ sudo apt-get install asciidoc xmlto docbook2x $ gh repo clone git/git $ cd git $ make configure $ ./configure --prefix=/usr $ sudo st make all ...
Num threads = 3,155 Num process = 3,155 Max PSS: 144,361,472 bytes Walltime: 95,427ms - user-space: 83,485ms - kernel-space: 10,995ms
144┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ ┃ █ ┃ ┃ █ █ █ █ ┃ ┫ █ ██ █ ███ █ █ █ ┃ ┃ █ █ ███ ███ █ ██ █ ███ ███ █ █ █ █ █ █ ██ █ █ ██ █ ┃ ┃ ████ ████████ ██ █████████████████████ ███ ██ ██████ ██ █████ █████████ █ ┃ ┃ ██████████████████████████████████████████████████████████████████████████ ████████┃ ┃████████████████████████████████████████████████████████████████████████████ ████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0s 95
Let's observe how parallel compilation, -j4,trades walltime with RAM/cores.
$ git clean
$ sudo st make -j4 all
...
Num threads = 3155
Num process = 3155
Max PSS: 288,531,456 bytes
Walltime: 27,556ms - user-space: 90,311ms - kernel-space: 11,458ms
288┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ┃ ┃ ┃ ┃ █ █ ┃ ┃ █ █ █ █ ┃ ┃ █ █ █ ██ █ █ ██ █ █ █ ┃ ┃ ██ █ ███ ██ █ ██████ █ █ █ █ █ █ ┃ ┃ ███ ████ ████ ███ ██ ██████ █ █ ██ █ █ ████ █████ █ ┃ ┫ ████ ████ █████ █ ███████████████████ ██ █ █████ ██ ██████████████ █ ┃ ┃ █████████████████████████████████████ ██████ ██████████████████████████ █ ┃ ┃ ████████████████████████████████████████████████████████████████████████ ██ ███ ┃ ┃ █████████████████████████████████████████████████████████████████████████ ███████ ┃ ┃ █████████████████████████████████████████████████████████████████████████ █████████┃ ┃ █████████████████████████████████████████████████████████████████████████ █████████┃ ┃ ██████████████████████████████████████████████████████████████████████████ █████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0MB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0s 27
Using four cores, dropped runtime nearly linearly (3.5) and doubled RAM usage.
The latest command I wanted to observe was m which builds AOSP.
$ cd aosp_24 $ cat > source build/envsetup.sh source build/envsetup.sh lunch aosp_arm64-eng m -j8 $ chmod +x make.sh $ sudo st make.sh ...
Num threads = 136,305 Num process = 132,891 Max PSS: 6,152,478,720 bytes Walltime: 700864ms - user-space: 9942532ms - kernel-space: 900950ms
6┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ┃ ┃ ┃ ┃ ┃ █ ┃ ┃ ██ █ ┃ ┃ █████ ███ █ █ ┃ ┃ ███████ ███████ █ █ █ ██ ┃ ┃ ███████████ █ █ ███████ █ █████ ██ ┃ ┫ ███████████████████████ ████████ ██ ┃ ┃ ████████████████████████ ██ ████████ ██ ┃ ┃ █ █ █████████████████████████ ██████ █ ██████████ █ █ ███ ██┃ ┃ █ ██ ██████████████████████████ ██████████ █ ██████████████ ████████┃ ┃ █ ███ ████████████████████████████████ ████████████████████████████████████┃ ┃ ████ ███████████████████████████████████████ █████████████████████████████████████┃ ┃ ████████████████████████████████████████████████████████████████████████████████████┃ ┃█████████████████████████████████████████████████████████████████████████████████████┃ 0GB┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┳━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ 0s 700
6 GiB and 11 minutes to build a whole OS with 8 cores. Not bad at all!
Before writing the tool, I considered relying on time(1) and strace(1). However I was not completely satisfied with them. If time(1) invoked via /usr/bin/time -v could retrieve child processes stats and show peak RSS, I wanted PSS. Also, I wanted to see PSS over time.
Likewise, strace -f could follow child processes but it had a tremendous performance overhead and did not show the command invoked by clone upon fork/thread creation.
In the end, I wrote my own tool and called it st (for space-time). The data sources are as follows.
waitpid(2) and getrusage(2).proc(5)(/proc/PID/smaps) on a regular interval.netlink(7).Following processes lifecycle via netlink proved more challenging than expected, mainly because of poor documentation (maybe because netlink needs root anyway?). If I managed to dig out process-events.txt from a mailing list and found a working sample exec-notify.c, there wasn't much more around.
One series of articles did stand out. Natan Yellin's blog[4][5][6][7]. is a gem. Among many excellent insights, he clarified[8] the less than intuitive values provided by netlink for parent-gid and parent-pid which saved me a lot of time.
Hopefully, st's(source code) will add a little extra clarity to netlink.