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").return

Now 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

None: RustProgramInstrumentationwithSystemTap (last edited 2023-09-24 11:55:46 by WilliamCohen)