Skip to content

uftrace

Jump to bottom Edit New page
HyeockJinKim edited this page Oct 13, 2019 · 1 revision

uftrace is a tool for tracing and analyzing the execution of programs written in C / C++. But it can also be used to do for Rust. It supports various kind of commands and filters to help analysis of the program execution and performance.

uftrace supports Linux. It may not run on other os.

Installation uftrace

  1. Clone uftrace
$ git clone https://github.com/namhyung/uftrace.git
$ cd uftrace
  1. Install uftrace
$ sudo misc/install-deps.sh    # optional for advanced features
$ ./configure                  # --prefix can be used to change install dir
$ make
$ sudo make install

See here for details.

Install Rustpython

  1. Clone RustPython
$ git clone https://github.com/RustPython/RustPython.git
$ cd RustPython
  1. Install Rust
$ export PATH="$HOME/.cargo/bin:$PATH"
$ curl https://sh.rustup.rs/ -sSf | sh
$ source $HOME/.cargo/env
  1. Install & set nightly compiler
$ rustup install nightly
$ rustup default nightly

Nightly compiler is required for using -Z flag options.

  1. Set flags and build RustPython
$ export RUSTFLAGS="-Z instrument-mcount"
$ cargo build

The -z flag is required to use RustPython with uftrace.

  1. Check the generated binary
$ nm ./target/debug/rustpython | grep mcount

output

                 U mcount@@GLIBC_2.2.5
  1. Get demangled version of Rust symbol names

More readable calling convention is needed to trace a specific function.
rustfilt could pipe to stdout using grep or less.

$ cargo install rustfilt
$ nm ./target/debug/rustpython | rustfilt
  1. Run RustPython with uftrace
$ uftrace -F rustpython_vm::obj::objrange::PyRange::getitem -D 2 ./target/debug/rustpython -c 'range(10)[0:5]'

output

# DURATION     TID     FUNCTION
            [ 14911] | rustpython_vm::obj::objrange::PyRange::getitem() {
   6.400 us [ 14911] |   _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref();
   5.600 us [ 14911] |   rustpython_vm::obj::objint::PyInt::as_bigint();
   6.100 us [ 14911] |   _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref();
   5.600 us [ 14911] |   rustpython_vm::obj::objint::PyInt::as_bigint();
  39.000 us [ 14911] |   rustpython_vm::obj::objrange::PyRange::length();
   6.400 us [ 14911] |   _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref();
   6.200 us [ 14911] |   rustpython_vm::obj::objslice::PySlice::step_index();
   5.600 us [ 14911] |   _<core..result..Result<T,E> as core..ops..try..Try>::into_result();
   8.500 us [ 14911] |   _<num_bigint..bigint..BigInt as num_traits..identities..One>::one();
   5.600 us [ 14911] |   core::ptr::real_drop_in_place();
   5.700 us [ 14911] |   _<num_bigint..bigint..BigInt as num_traits..sign..Signed>::is_negative();
   8.300 us [ 14911] |   _<num_bigint..bigint..BigInt as num_traits..identities..Zero>::zero();
  10.600 us [ 14911] |   _<num_bigint..bigint..BigInt as core..clone..Clone>::clone();
   6.300 us [ 14911] |   _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref();
  10.100 us [ 14911] |   rustpython_vm::obj::objslice::PySlice::start_index();
   5.600 us [ 14911] |   _<core..result..Result<T,E> as core..ops..try..Try>::into_result();
   6.000 us [ 14911] |   _<num_bigint..bigint..BigInt as num_traits..sign..Signed>::is_negative();
   6.000 us [ 14911] |   core::cmp::PartialOrd::gt();
   9.000 us [ 14911] |   _<num_bigint..bigint..BigInt as core..clone..Clone>::clone();
   6.600 us [ 14911] |   core::ptr::real_drop_in_place();
   6.200 us [ 14911] |   _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref();
  10.900 us [ 14911] |   rustpython_vm::obj::objslice::PySlice::stop_index();
   5.600 us [ 14911] |   _<core..result..Result<T,E> as core..ops..try..Try>::into_result();
   5.700 us [ 14911] |   _<num_bigint..bigint..BigInt as num_traits..sign..Signed>::is_negative();
   9.500 us [ 14911] |   core::cmp::PartialOrd::gt();
   9.900 us [ 14911] |   _<num_bigint..bigint..BigInt as core..clone..Clone>::clone();
   7.100 us [ 14911] |   core::ptr::real_drop_in_place();
  17.000 us [ 14911] |   _<&num_bigint..bigint..BigInt as core..ops..arith..Mul<&num_bigint..bigint..BigInt>>::mul();
  13.800 us [ 14911] |   _<&num_bigint..bigint..BigInt as core..ops..arith..Mul<&num_bigint..bigint..BigInt>>::mul();
  10.900 us [ 14911] |   _<&num_bigint..bigint..BigInt as core..ops..arith..Add<num_bigint..bigint..BigInt>>::add();
  15.000 us [ 14911] |   _<&num_bigint..bigint..BigInt as core..ops..arith..Mul<&num_bigint..bigint..BigInt>>::mul();
   5.600 us [ 14911] |   _<&num_bigint..bigint..BigInt as core..ops..arith..Add<num_bigint..bigint..BigInt>>::add();
   5.800 us [ 14911] |   rustpython_vm::obj::objint::PyInt::new();
   8.700 us [ 14911] |   rustpython_vm::pyobject::PyValue::into_ref();
   5.700 us [ 14911] |   rustpython_vm::obj::objint::PyInt::new();
   7.900 us [ 14911] |   rustpython_vm::pyobject::PyValue::into_ref();
   5.700 us [ 14911] |   rustpython_vm::obj::objint::PyInt::new();
   8.500 us [ 14911] |   rustpython_vm::pyobject::PyValue::into_ref();
   8.400 us [ 14911] |   rustpython_vm::pyobject::PyValue::into_ref();
   5.600 us [ 14911] |   rustpython_vm::pyobject::PyRef<T>::into_object();
   7.200 us [ 14911] |   core::ptr::real_drop_in_place();
   6.400 us [ 14911] |   core::ptr::real_drop_in_place();
:

See here for more option

  1. Generate dump output

uftrace record command dump the output.

$ uftrace record -F rustpython_vm::obj::objrange::PyRange::getitem -D 2 ./target/debug/rustpython -c 'range(10)[0:5]'

uftrace replay command show the dumped output.

$ uftrace replay
# DURATION     TID     FUNCTION
            [ 10304] | rustpython_vm::obj::objrange::PyRange::getitem() {
...
  1. Visualize trace output of RustPython
  • Graph
$ uftrace graph

output

# Function Call Graph for 'rustpython' (session: 5477228a1255f589)
========== FUNCTION CALL GRAPH ==========
# TOTAL TIME   FUNCTION
  751.300 us : (1) rustpython
  751.300 us : (1) rustpython_vm::obj::objrange::PyRange::getitem
   30.500 us :  +-(5) _<rustpython_vm..pyobject..PyRef<T> as core..ops..deref..Deref>::deref
             :  | 
   10.900 us :  +-(2) rustpython_vm::obj::objint::PyInt::as_bigint
             :  | 
   38.000 us :  +-(1) rustpython_vm::obj::objrange::PyRange::length
             :  | 
    6.000 us :  +-(1) rustpython_vm::obj::objslice::PySlice::step_index
             :  | 
   16.300 us :  +-(3) _<core..result..Result<T,E> as core..ops..try..Try>::into_result
             :  | 
    8.500 us :  +-(1) _<num_bigint..bigint..BigInt as num_traits..identities..One>::one
             :  | 
   63.000 us :  +-(10) core::ptr::real_drop_in_place
             :  | 
   16.600 us :  +-(3) _<num_bigint..bigint..BigInt as num_traits..sign..Signed>::is_negative
             :  | 
    8.100 us :  +-(1) _<num_bigint..bigint..BigInt as num_traits..identities..Zero>::zero
             :  | 
   28.400 us :  +-(3) _<num_bigint..bigint..BigInt as core..clone..Clone>::clone
             :  | 
    9.800 us :  +-(1) rustpython_vm::obj::objslice::PySlice::start_index
             :  | 
   15.100 us :  +-(2) core::cmp::PartialOrd::gt
             :  | 
   10.700 us :  +-(1) rustpython_vm::obj::objslice::PySlice::stop_index
             :  | 
   43.900 us :  +-(3) _<&num_bigint..bigint..BigInt as core..ops..arith..Mul<&num_bigint..bigint..BigInt>>::mul
             :  | 
   15.900 us :  +-(2) _<&num_bigint..bigint..BigInt as core..ops..arith..Add<num_bigint..bigint..BigInt>>::add
             :  | 
   16.900 us :  +-(3) rustpython_vm::obj::objint::PyInt::new
             :  | 
   32.400 us :  +-(4) rustpython_vm::pyobject::PyValue::into_ref
             :  | 
    6.200 us :  +-(1) rustpython_vm::pyobject::PyRef<T>::into_object

See here for details

  • Chrome
$ uftrace record -D 3 ./target/debug/rustpython -c 'range(10)[0:5]'
$ uftrace dump --chrome > uftrace-dump-rustpython.json
$ trace2html uftrace-dump-rustpython.json

This wiki referenced uftrace README and uftrace RustPython Wiki.

Add a custom footer
Clone this wiki locally