Rust Program Instrumentation with SystemTap
SystemTap can instrument binaries for languages other than C. The main requirement is the need for debug information to map between the source code and the binary SystemTap is instrumenting. The Rust compiler can include debuginfo with the binary and SystemTap can use that information.
Including Debuginfo in Rust binaries
Applications written in Rust typically use Cargo, the Rust package manager, to build and distribute the software. A rust package can either be built by Cargo for development/debugging or for a release. The development version of a build using cargo build includes the debuginfo needed by SystemTap. However, if you are building a release of a Rust application, you will need to use the following to include the debuginfo in the binary:
RUSTFLAGS="-C debuginfo=2" cargo build --release
Or set the debug of the Cargo.toml file in the profile.release section to the following:
debug = 2
Example
For an example we will use the Rust emulator for the Intel 8080 CPU. Download and build the example with:
$ git clone https://github.com/mohanson/i8080.git $ cd i8080 $ python ./scripts/get_cpu_tests.py $ RUSTFLAGS="-C debuginfo=2" cargo build --release --example test_roms
We verify that the binary has the needed debuginfo sections:
$ eu-readelf -S target/release/examples/test_roms |grep debug [17] .debug_gdb_scripts PROGBITS 0000000000056748 00056748 00000022 1 AMS 0 0 1 [32] .debug_aranges PROGBITS 0000000000000000 0006547c 00000690 0 0 0 1 [33] .debug_pubnames PROGBITS 0000000000000000 00065b0c 000086bd 0 0 0 1 [34] .debug_info PROGBITS 0000000000000000 0006e1c9 0001e057 0 0 0 1 [35] .debug_abbrev PROGBITS 0000000000000000 0008c220 0000196f 0 0 0 1 [36] .debug_line PROGBITS 0000000000000000 0008db8f 00005d41 0 0 0 1 [37] .debug_str PROGBITS 0000000000000000 000938d0 0000f631 1 MS 0 0 1 [38] .debug_loc PROGBITS 0000000000000000 000a2f01 0000e11e 0 0 0 1 [39] .debug_pubtypes PROGBITS 0000000000000000 000b101f 00006aa5 0 0 0 1 [40] .debug_ranges PROGBITS 0000000000000000 000b7ac4 00005d50 0 0 0 1
Now we are ready to experiment with the Rust binary.
Seeing available probe points
Like binaries compiled from C code we can list the available function probe points and the arguments available at the points with:
$ stap -L 'process("target/release/examples/test_roms").function("*").*'The resulting output is rather long because Rust statically compiles binaries the output of the above command will include functions from other crates (libraries) used to build the binary. One could limit the listed probe point to the i8080 emulator functions with:
$ stap -L 'process("target/release/examples/test_roms").function("*@src/*").*'Each rust program needs a main. If you searched through the output, one thing you might noticed in the output limited to the src directory is that there is no main for the binary. The main is in the examples directory:
$ stap -L 'process("target/release/examples/test_roms").function("*@examples/*")'.*
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").call $path:struct &str
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("borrow_mut<i8080::memory::Linear>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/cell.rs:1016") $self:struct RefCell<i8080::memory::Linear>*
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("clone<core::cell::RefCell<i8080::memory::Linear>>@/builddir/build/BUILD/rustc-1.72.0-src/library/alloc/src/rc.rs:1638")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("drop_in_place<alloc::rc::Rc<core::cell::RefCell<i8080::memory::Linear>>>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/ptr/mod.rs:497")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("drop_in_place<core::cell::Ref<i8080::memory::Linear>>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/ptr/mod.rs:497")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("drop_in_place<core::cell::RefMut<i8080::memory::Linear>>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/ptr/mod.rs:497")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("drop_in_place<i8080::cpu::Cpu>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/ptr/mod.rs:497")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("new<i8080::memory::Linear>@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/cell.rs:782") $value:struct Linear
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("new_const@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/fmt/mod.rs:297") $pieces:struct &[&str]
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").callee("new_v1@/builddir/build/BUILD/rustc-1.72.0-src/library/core/src/fmt/mod.rs:307") $pieces:struct &[&str] $args:struct &[core::fmt::rt::Argument]
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("exec_test<&str>@examples/test_roms.rs:17").return $path:struct &str
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("main@examples/test_roms.rs:55").call
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").function("main@examples/test_roms.rs:55").returnNow that have verified that a Rust binary has probe points we can instrument the binary with SystemTap.
Running a SystemTap example script
As with most emulators the i8080 emulator has a large switch-case statement in the next function to determine how to emulate the instruction. We would like to get an idea where in this complex function time is being spent. The linetimes.stp example will provide that that information. We start it running with:
$ sudo stap --example linetimes.stp 'process("./target/release/examples/test_roms")' 'next' -c './target/release/examples/test_roms'After a while we interrupt the run with a cntrl-c. The program outputted the following to the terminal:
******************* Test loaded: "./res/cpu_tests/8080PRE.COM" 8080 Preliminary tests complete ******************* Test loaded: "./res/cpu_tests/TST8080.COM" MICROCOSM ASSOCIATES 8080/8085 CPU DIAGNOSTIC VERSION 1.0 (C) 1980 CPU IS OPERATIONAL ******************* Test loaded: "./res/cpu_tests/CPUTEST.COM" DIAGNOSTICS II V1.2 - CPU TEST COPYRIGHT (C) 1981 - SUPERSOFT ASSOCIATES ABCDEFGHIJKLMNOPQRSTUVWXYZ CPU IS 8080/8085 BEGIN TIMING TEST END TIMING TEST CPU TESTS OK ******************* Test loaded: "./res/cpu_tests/8080EXM.COM" 8080 instruction exerciser dad <b,d,h,sp>................ PASS! crc is:14474ba6 aluop nn...................... PASS! crc is:9e922f9e ^CWARNING: Child process exited with signal 2 (Interrupt)
In addition to the program output the systemtap script outputted information. The first line indicates the number of times that next function was called, 2519978408. This is followed by the information about the time spent on each line (average and maximum).
process("./target/release/examples/test_roms") next call count: 2519978408
region avg(us) max(us)
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:254") 0 3948
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:255") 3 10363
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:259") 3 8694
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:267") 3 7142
...This is followed by control flow graph information. The first couple of lines are just sequentially executed, line 254 followed by line 255. Line 283 is the start of a rust switch-case (match) statement that interprets the instruction opcode and causes the segment of code to execute to implement the operation. There are many possible statements that follow line 283. Some are much more frequently used than others. For example line 289 implements the increment b register operation is only executed 3 times, while line 296 implementing increment memory executes 779412. Looking farther down the list we see line 659 very frequently used. This maps to the various jumps, both conditional and unconditional.
control flow graph information
from
to
=======================
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:254")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:255") 2519978408
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:255")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:259") 2519978408
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:259")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:267") 2519978407
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:267")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:283") 2519978407
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:283")
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:289") 3
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:290") 3393
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:291") 170
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:292") 2
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:293") 2
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:294") 2
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:296") 779412
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:300") 16777267
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:303") 77818393
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:304") 49688280
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:305") 2
...
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:655") 3
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:659") 227690476
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:688") 81715301
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:719") 83334874
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:748") 1
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:753") 776379
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:754") 776381
process("/home/wcohen/rust/i8080/target/release/examples/test_roms").statement("next@src/cpu.rs:770") 668157121