Perhaps programs compiled with Rust also can be traced

[ParkHanbum]

$ cat ../rust_hello.rs
// This is the main function
fn main() {
    // The statements here will be executed when the compiled binary is called

    // Print text to the console
    println!("Hello World!");
}

$ ./uftrace -L. -P. ../rust_hello

Hello World!
some functions cannot be patched dynamically
# DURATION     TID     FUNCTION
            [115811] | std::rt::lang_start_internal::hf52213aa92df6a15() {
   1.121 us [115811] |   signal();
            [115811] |   std::sys::unix::thread::guard::init::h03749acf4149002d() {
   0.443 us [115811] |     sysconf();
   1.166 us [115811] |     pthread_attr_init();
   0.375 us [115811] |     pthread_self();
 269.009 us [115811] |     pthread_getattr_np();
   0.124 us [115811] |     pthread_attr_getstack();
   0.086 us [115811] |     pthread_attr_destroy();
 279.230 us [115811] |   } /* std::sys::unix::thread::guard::init::h03749acf4149002d */
            [115811] |   std::sys::unix::stack_overflow::imp::init::hc161bf9b77627914() {
   0.410 us [115811] |     sigaction();
   0.281 us [115811] |     sigaction();
   0.407 us [115811] |     sigaltstack();
   2.013 us [115811] |     mmap();
   0.307 us [115811] |     sigaltstack();
   4.416 us [115811] |   } /* std::sys::unix::stack_overflow::imp::init::hc161bf9b77627914 */
            [115811] |   alloc::str::_$LT$impl$u20$alloc..borrow..ToOwned$u20$for$u20$str$GT$::to_owned::h0c9075337dd817c1() {
            [115811] |     alloc::slice::_$LT$impl$u20$alloc..borrow..ToOwned$u20$for$u20$$u5b$T$u5d$$GT$::to_owned::hc6d2c970d555e1ac() {
            [115811] |       __rdl_alloc() {
   0.152 us [115811] |         malloc();
   0.677 us [115811] |       } /* __rdl_alloc */
   0.430 us [115811] |       _$LT$alloc..raw_vec..RawVec$LT$T$C$$u20$A$GT$$GT$::reserve_internal::h8098ed8f7e77bbd1();
   0.107 us [115811] |       memcpy();
   2.051 us [115811] |     } /* alloc::slice::_$LT$impl$u20$alloc..borrow..ToOwned$u20$for$u20$$u5b$T$u5d$$GT$::to_owned::hc6d2c970d555e1ac */
   5.339 us [115811] |   } /* alloc::str::_$LT$impl$u20$alloc..borrow..ToOwned$u20$for$u20$str$GT$::to_owned::h0c9075337dd817c1 */
            [115811] |   std::thread::Thread::new::hbdbbfcbf902e8c10() {
   0.149 us [115811] |     memchr();
            [115811] |     std::ffi::c_str::CString::from_vec_unchecked::h0873db404d4a72e6() {
            [115811] |       _$LT$alloc..raw_vec..RawVec$LT$T$C$$u20$A$GT$$GT$::reserve_internal::h2b14b3d2391c308b() {
            [115811] |         __rdl_realloc() {
   0.221 us [115811] |           realloc();
   0.626 us [115811] |         } /* __rdl_realloc */
   1.038 us [115811] |       } /* _$LT$alloc..raw_vec..RawVec$LT$T$C$$u20$A$GT$$GT$::reserve_internal::h2b14b3d2391c308b */
   0.106 us [115811] |       _$LT$alloc..vec..Vec$LT$T$GT$$GT$::into_boxed_slice::h4cf00f730cf0fdab();
   1.687 us [115811] |     } /* std::ffi::c_str::CString::from_vec_unchecked::h0873db404d4a72e6 */

this is tested with #588

[ParkHanbum]

dynamic: dynamic update stats:
dynamic:    total:      451
dynamic:  patched:      224 (49.67%)
dynamic:   failed:        0 (0.00%)
dynamic:  skipped:      227 (50.33%)
dynamic: no match:        0

[namhyung]

How did you build your rust program? What was the version of uftrace?

[ParkHanbum]

@namhyung

m@m:~/git$ rustc rust_hello.rs
m@m:~/git$ ./rust_hello
Hello World!

m@m:~/git/uftrace$ ./uftrace --version
uftrace v0.9-129-g36e9 ( dwarf python tui perf sched )

[namhyung]

Did rustc add some instrumentation code or is it your change to trace it (full-)dynamically?

[taeguk]

@namhyung Maybe he trace it (full-)dynamically. As I know, there is no support for instrumentation code in rustc now. (https://users.rust-lang.org/t/profiling-based-on-instrumentation/21227)

[namhyung]

@taeguk thanks, it'd be nice if rust would support tracing officially.

[namhyung]

It seems we need to demangle rust symbols separately..

[taeguk]

@namhyung There is very simple rustc demangler. (https://github.com/alexcrichton/rustc-demangle/blob/master/src/lib.rs)

[quark-zju]

I'm trying to add mcount support to rustc: rust-lang/rust#57220.

[namhyung]

@quark-zju Looks great! Thanks for your work.

[honggyukim]

@quark-zju Welcome to uftrace and thank you very much!

[namhyung]

Is there a quick way to determine a binary is a rust program? I checked the .comment section but it shows GCC versions only

$ readelf -p .comment hello-rust

String dump of section '.comment':
  [     0]  GCC: (GNU) 8.2.1 20180831
  [    1a]  GCC: (GNU) 8.2.1 20181127

[quark-zju]

C++ and Rust objects can be linked together. So it's not that easy. Perhaps rust_panic symbol can be used as a hint. Ideally, symbol demangling logic knows both Rust and C++ symbols.

There are ongoing efforts to change how Rust symbols are mangled. The new scheme has _R prefix.

[namhyung]

I added a simple demangle logic to handle rust symbols seamlessly but it'd be nice to know it's rust before loading symbols.

Anyway new mangling scheme will help.

[honggyukim]

I just tested a rust program tracing.

$ cat fib.rs
fn fibonacci(n: u32) -> u32 {
    match n {
        0 => 1,
        1 => 1,
        _ => fibonacci(n - 1) + fibonacci(n - 2),
    }
}

fn main() {
    fibonacci(5);
}

I compiled rust compiler from the master branch which rust-lang/rust#57220 is already committed.

$ git clone https://github.com/rust-lang/rust.git
$ cd rust
$ git submodule update --init --recursive
$ ./x.py build

Then tested it with a fibonacci example as follows:

$ cd rust/build/x86_64-unknown-linux-gnu/stage2/bin
$ ./rustc -Z instrument-mcount -g fib.rs

$ uftrace -a --no-libcall fib
# DURATION     TID     FUNCTION
            [ 54039] | std::rt::lang_start(&fib::main, 1, 0x7ffef4865af8) {
            [ 54039] |   std::rt::lang_start::_{{closure}}() {
            [ 54039] |     fib::main() {
            [ 54039] |       fib::fibonacci(5) {
            [ 54039] |         fib::fibonacci(4) {
            [ 54039] |           fib::fibonacci(3) {
            [ 54039] |             fib::fibonacci(2) {
   0.370 us [ 54039] |               fib::fibonacci(1) = 1;
   0.240 us [ 54039] |               fib::fibonacci(0) = 1;
   4.057 us [ 54039] |             } = 2; /* fib::fibonacci */
   0.246 us [ 54039] |             fib::fibonacci(1) = 1;
   5.347 us [ 54039] |           } = 3; /* fib::fibonacci */
            [ 54039] |           fib::fibonacci(2) {
   0.230 us [ 54039] |             fib::fibonacci(1) = 1;
   0.234 us [ 54039] |             fib::fibonacci(0) = 1;
   1.607 us [ 54039] |           } = 2; /* fib::fibonacci */
  11.987 us [ 54039] |         } = 5; /* fib::fibonacci */
            [ 54039] |         fib::fibonacci(3) {
            [ 54039] |           fib::fibonacci(2) {
   0.234 us [ 54039] |             fib::fibonacci(1) = 1;
   0.220 us [ 54039] |             fib::fibonacci(0) = 1;
   1.470 us [ 54039] |           } = 2; /* fib::fibonacci */
   0.236 us [ 54039] |           fib::fibonacci(1) = 1;
   2.606 us [ 54039] |         } = 3; /* fib::fibonacci */
  15.727 us [ 54039] |       } = 8; /* fib::fibonacci */
  16.373 us [ 54039] |     } /* fib::main */
            [ 54039] |     _<() as std..process..Termination>::report(&realloc) {
            [ 54039] |       _<std..process..ExitCode as std..process..Termination>::report(0) {
   0.236 us [ 54039] |         std::sys::unix::process::process_common::ExitCode::as_i32(0x7ffef486585f) = 0;
   1.190 us [ 54039] |       } = 0; /* _<std..process..ExitCode as std..process..Termination>::report */
   1.947 us [ 54039] |     } = 0; /* _<() as std..process..Termination>::report */
  19.877 us [ 54039] |   } = 0; /* std::rt::lang_start::_{{closure}} */
 393.263 us [ 54039] | } = 0; /* std::rt::lang_start */

It shows a lot more library calls if I run it without --no-libcall.

# DURATION     TID     FUNCTION
            [ 54070] | std::rt::lang_start(&fib::main, 1, 0x7fff48a14ff8) {
   2.100 us [ 54070] |   signal(SIGPIPE, 0x1) = 0;
   0.647 us [ 54070] |   sysconf();
   2.430 us [ 54070] |   pthread_attr_init();
   0.243 us [ 54070] |   pthread_self();
 340.642 us [ 54070] |   pthread_getattr_np();
   0.374 us [ 54070] |   pthread_attr_getstack();
   0.287 us [ 54070] |   pthread_attr_destroy();
   1.544 us [ 54070] |   sigaction(SIGSEGV, 0x7fff48a14d58, 0) = 0;
   1.003 us [ 54070] |   sigaction(SIGBUS, 0x7fff48a14d58, 0) = 0;
   1.243 us [ 54070] |   sigaltstack();
   4.917 us [ 54070] |   mmap(0, 8192, PROT_WRITE|PROT_READ, MAP_ANON|MAP_PRIVATE, -1, 0) = &realloc;
   0.906 us [ 54070] |   sigaltstack();
   0.550 us [ 54070] |   malloc(4) = 0x562ef0c68d00;
   0.417 us [ 54070] |   memchr(0x562ef0c68d00, 0, 4) = 0;
   0.403 us [ 54070] |   realloc(0x562ef0c68d00, 5) = 0x562ef0c68d00;
   0.433 us [ 54070] |   pthread_mutex_lock(&std::thread::ThreadId::new::GUARD) = 0;
   0.373 us [ 54070] |   pthread_mutex_unlock(&std::thread::ThreadId::new::GUARD) = 0;
   0.316 us [ 54070] |   malloc(40) = 0x562ef0c68cd0;
   0.353 us [ 54070] |   pthread_mutexattr_init();
   0.200 us [ 54070] |   pthread_mutexattr_settype();
   0.487 us [ 54070] |   pthread_mutex_init(0x562ef0c68cd0, 0x7fff48a14d58) = 0;
   0.193 us [ 54070] |   pthread_mutexattr_destroy();
   0.320 us [ 54070] |   malloc(48) = 0x562ef0c68d20;
   0.370 us [ 54070] |   pthread_condattr_init();
   0.190 us [ 54070] |   pthread_condattr_setclock();
   0.310 us [ 54070] |   pthread_cond_init();
   0.160 us [ 54070] |   pthread_condattr_destroy();
   0.287 us [ 54070] |   malloc(80) = 0x562ef0c68d60;
   1.276 us [ 54070] |   __cxa_thread_atexit_impl();
   0.306 us [ 54070] |   pthread_mutex_lock(&std::sys::unix::args::imp::LOCK) = 0;
   0.274 us [ 54070] |   pthread_mutex_unlock(&std::sys::unix::args::imp::LOCK) = 0;
            [ 54070] |   std::rt::lang_start::_{{closure}}() {
            [ 54070] |     fib::main() {
            [ 54070] |       fib::fibonacci(5) {
            [ 54070] |         fib::fibonacci(4) {
            [ 54070] |           fib::fibonacci(3) {
            [ 54070] |             fib::fibonacci(2) {
   0.353 us [ 54070] |               fib::fibonacci(1) = 1;
   0.270 us [ 54070] |               fib::fibonacci(0) = 1;
   2.360 us [ 54070] |             } = 2; /* fib::fibonacci */
   0.233 us [ 54070] |             fib::fibonacci(1) = 1;
   3.560 us [ 54070] |           } = 3; /* fib::fibonacci */
            [ 54070] |           fib::fibonacci(2) {
   0.200 us [ 54070] |             fib::fibonacci(1) = 1;
   0.223 us [ 54070] |             fib::fibonacci(0) = 1;
   1.520 us [ 54070] |           } = 2; /* fib::fibonacci */
  10.147 us [ 54070] |         } = 5; /* fib::fibonacci */
            [ 54070] |         fib::fibonacci(3) {
            [ 54070] |           fib::fibonacci(2) {
   0.230 us [ 54070] |             fib::fibonacci(1) = 1;
   0.234 us [ 54070] |             fib::fibonacci(0) = 1;
   1.543 us [ 54070] |           } = 2; /* fib::fibonacci */
   0.237 us [ 54070] |           fib::fibonacci(1) = 1;
   2.643 us [ 54070] |         } = 3; /* fib::fibonacci */
  13.914 us [ 54070] |       } = 8; /* fib::fibonacci */
  14.531 us [ 54070] |     } /* fib::main */
            [ 54070] |     _<() as std..process..Termination>::report(&realloc) {
            [ 54070] |       _<std..process..ExitCode as std..process..Termination>::report(0) {
   0.227 us [ 54070] |         std::sys::unix::process::process_common::ExitCode::as_i32(0x7fff48a14d5f) = 0;
   1.170 us [ 54070] |       } = 0; /* _<std..process..ExitCode as std..process..Termination>::report */
   1.930 us [ 54070] |     } = 0; /* _<() as std..process..Termination>::report */
  17.844 us [ 54070] |   } = 0; /* std::rt::lang_start::_{{closure}} */
   0.293 us [ 54070] |   pthread_mutex_lock(&std::sys::unix::args::imp::LOCK) = 0;
   0.246 us [ 54070] |   pthread_mutex_unlock(&std::sys::unix::args::imp::LOCK) = 0;
   1.023 us [ 54070] |   sigaltstack();
   4.637 us [ 54070] |   munmap(&realloc, 8192) = 0;
   0.266 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.247 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.244 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.240 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.247 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.237 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.243 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.240 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.254 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.236 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.244 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.236 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.237 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.230 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.247 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.233 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.244 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.227 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.240 us [ 54070] |   pthread_mutex_lock(&std::sys_common::at_exit_imp::LOCK) = 0;
   0.233 us [ 54070] |   pthread_mutex_unlock(&std::sys_common::at_exit_imp::LOCK) = 0;
 438.484 us [ 54070] | } = 0; /* std::rt::lang_start */
   0.444 us [ 54070] | free(0x562ef0c68d00);
   0.383 us [ 54070] | pthread_mutex_destroy(0x562ef0c68cd0) = 0;
   0.283 us [ 54070] | free(0x562ef0c68cd0);
   0.256 us [ 54070] | pthread_cond_destroy();
   0.260 us [ 54070] | free(0x562ef0c68d20);
   0.237 us [ 54070] | free(0x562ef0c68d60);

Thanks a lot for doing this great work @quark-zju!

[namhyung]

Cool! :)

[quark-zju]

@honggyukim Thanks for https://reviews.llvm.org/D22666 in the first place! Otherwise the change would have been less confident or elegant. Kudos of demangling improvement go to @namhyung.

[honggyukim]

@quark-zju Thank you too :)

[honggyukim]

Hi @quark-zju, I would like to ask you if there is a reason to choose -Z instrument-mcount. It seems that -Z pg or -pg would be more consistent usage although it's less intuitive to general users who are not familiar with -pg flag.

[quark-zju]

-pg means "profiling for gprof". __gmon_start__ is not written, so gprof does not actually work. There is also a rustc -Z profile, which makes it a bit confusing.

Non--Z flags need to go through RFC process. It is easier to add a -Z flag.

[honggyukim]

Understood. Thanks for the explanation!

[taeguk]

Finally, the -Z instrument-mcount feature was released to rustc 1.33.0-nightly yesterday :)

[taeguk]

I've analyzed rustc using uftrace.

$ git clone https://github.com/rust-lang/rust.git --depth=1
$ cd rust
$ git submodule update --init --recursive
$ ./x.py build -i --stage=1
$ RUSTFLAGS="-Z instrument-mcount -g" ./x.py build -i --keep-stage 0 --stage 2
$ cd build/x86_64-unknown-linux-gnu/stage2/bin
$ uftrace -a -t 100us ./rustc fib.rs
----Omit the full output because it is so huge----

The part of output is:

The recored data by uftrace record -a ./rustc fib.rs is:
https://drive.google.com/open?id=12Kgcexl378FxpBBpS4MHbwKnLAo7yOYq

[honggyukim]

@taeguk Great! You can also use dump --chrome to generate .json and it can also be converted into .html file. Then it can be uploaded to any web server so that people can access it.

It will show how rust compiler works as a high level view. Please see https://uftrace.github.io/slide/#dump.

[honggyukim]

#655 is related to this.

[honggyukim]

I was also able to trace rustc compiler itself as follows.

  TOTAL TIME : FUNCTION
    4.927  s : (1) rustc
    2.590  s :  ├▶(1) std::rt::lang_start_internal
             :  │
    2.337  s :  └─(9) std::sys::unix::thread::Thread::new::thread_start
    2.337  s :    (9) std::sys_common::thread::start_thread
    2.336  s :    (9) _<F as alloc..boxed..FnBox<A>>::call_box
    2.336  s :    (9) __rust_maybe_catch_panic
    2.336  s :    (9) std::panicking::try::do_call
    2.336  s :    (9) std::sys_common::backtrace::__rust_begin_short_backtrace
    2.201  s :     ├─(1) syntax::with_globals
    2.201  s :     │ (1) __rust_probestack
    2.201  s :     │ (1) _<scoped_tls..ScopedKey<T>>::set
    2.195  s :     │  ├─(1) rustc_driver::run_compiler
    2.194  s :     │  │ (1) _<scoped_tls..ScopedKey<T>>::set
    2.194  s :     │  │ (1) __rust_probestack
    2.194  s :     │  │ (1) rustc_driver::run_compiler_with_pool
    3.891 ms :     │  │  ├▶(1) rustc::session::build_session_with_source_map
             :     │  │  │
   54.623 ms :     │  │  ├▶(1) std::sync::once::Once::call_inner
             :     │  │  │
    3.912 ms :     │  │  ├▶(1) _<rustc_codegen_llvm..LlvmCodegenBackend as rustc_codegen_utils..codegen_backend..CodegenBackend>::init
             :     │  │  │
    2.124  s :     │  │  ├─(1) __rust_probestack
    2.124  s :     │  │  │ (1) rustc_driver::driver::compile_input
    2.254 ms :     │  │  │  ├▶(1) rustc_driver::driver::phase_1_parse_input
             :     │  │  │  │
    1.185  s :     │  │  │  ├─(2) __rust_probestack
  630.416 ms :     │  │  │  │  ├▶(1) rustc_driver::driver::phase_2_configure_and_expand
             :     │  │  │  │  │
  554.574 ms :     │  │  │  │  └─(1) rustc_driver::driver::phase_3_run_analysis_passes
  554.433 ms :     │  │  │  │    (1) __rust_probestack
  554.424 ms :     │  │  │  │    (1) rustc::ty::context::TyCtxt::create_and_enter
  553.844 ms :     │  │  │  │    (1) _<std..thread..local..LocalKey<T>>::with
   76.803 ms :     │  │  │  │     ├─(1) rustc_typeck::check_crate
   73.937 ms :     │  │  │  │     │▶(1) rustc::util::common::time
             :     │  │  │  │     │
  152.630 ms :     │  │  │  │     ├▶(2) rustc::util::common::time
             :     │  │  │  │     │
  319.077 ms :     │  │  │  │     └─(1) rustc_driver::driver::compile_input::_{{closure}}
  319.006 ms :     │  │  │  │      ▶(1) rustc_driver::driver::phase_4_codegen
             :     │  │  │  │
   13.927 ms :     │  │  │  ├▶(1) core::ptr::real_drop_in_place
             :     │  │  │  │
  921.584 ms :     │  │  │  └▶(1) _<rustc_codegen_llvm..LlvmCodegenBackend as rustc_codegen_utils..codegen_backend..CodegenBackend>::join_codegen_and_link
             :     │  │  │
    4.080 ms :     │  │  └─(1) core::ptr::real_drop_in_place
             :     │  │
    5.758 ms :     │  └▶(1) core::ptr::real_drop_in_place
             :     │
   14.499 ms :     ├─(21) linux:schedule
             :     │
   89.090 ms :     ├▶(11) _<std..sync..mpsc..Receiver<T>>::recv
             :     │
   27.595 ms :     └─(6) rustc_codegen_ssa::back::write::execute_work_item
   26.146 ms :      ▶(6) rustc_codegen_llvm::back::write::codegen

The above TUI output shows some notable phases.

• rustc_driver::driver::phase_1_parse_input
• rustc_driver::driver::phase_2_configure_and_expand
• rustc_driver::driver::phase_3_run_analysis_passes
• rustc_driver::driver::phase_4_codegen