uftrace

name: title-layout
layout: true
class: center, middle, title

---
name: picture-layout
layout: true
class: center, middle

---
name: basic-layout
layout: true
class: left, top

---
name: title
template: title-layout

# uftrace
### A function (graph) tracer for C/C++/Rust/Python programs
### [https://github.com/namhyung/uftrace](https://github.com/namhyung/uftrace)
.footnote[[https://uftrace.github.io](https://uftrace.github.io)]

---
name: toc
class: font-22px
### Table of Contents
- [Installation](#installation)
- [Basic Tracing](#basic-tracing)
  - [(user) Function Tracing](#user-tracing)
  - [Library Function Tracing](#lib-tracing)
  - [Linux Kernel Function Tracing](#kernel-tracing)
  - [Event Tracing](#event-tracing)
- Filters and Arguments
  - [Filters](#filters)
  - [Display Function Arguments](#args)
  - [Arguments Detection with Debug Info](#autoargs)
- Recorded Data Analysis
  - [report command](#report)
  - [dump command](#dump)
  - [graph command](#graph)
  - [tui command](#tui)
- Advanced Topics
  - [(Python) Scripting](#python)
  - [Dynamic Tracing](#dynamic-tracing)
  - [Full Dynamic Tracing](#full-dynamic-tracing)
  - [Triggers for Trace Control](#trace-control)
  - [Python Function Tracing](#python-tracing)

---
### uftrace
- The [uftrace](https://github.com/namhyung/uftrace) tool is to trace and analyze execution of a program written in C/C++.
- It was heavily inspired by the [ftrace](https://www.kernel.org/doc/Documentation/trace/ftrace.txt) framework of the Linux kernel (especially function graph tracer) and supports userspace programs.
- It supports various kind of commands and filters to help analysis of the program execution and performance.

---
template: picture-layout
<img src="https://raw.githubusercontent.com/namhyung/uftrace/master/doc/uftrace-live-demo.gif" class="center-image" width="680">

---
name: installation
### Quick Installation
.footnote[[INSTALL.md](https://github.com/namhyung/uftrace/blob/master/INSTALL.md)]
<pre>
<code class="bash">$ git clone https://github.com/namhyung/uftrace && cd uftrace

$ ./configure
uftrace detected system features:
...         prefix: /usr/local
...         libelf: [ .green[on]  ] - more flexible ELF data handling
...          libdw: [ .red[OFF] ] - DWARF debug info support
...      libpython: [ .red[OFF] ] - python tracing & scripting support
...      libluajit: [ .red[OFF] ] - luajit scripting support
...    libncursesw: [ .red[OFF] ] - TUI support
...   cxa_demangle: [ .green[on]  ] - full demangler support with libstdc++
...     perf_event: [ .green[on]  ] - perf (PMU) event support
...       schedule: [ .green[on]  ] - scheduler event support
...       capstone: [ .red[OFF] ] - full dynamic tracing support

$ make

$ sudo make install
</code>
</pre>
---
### Quick Installation
.footnote[[INSTALL.md](https://github.com/namhyung/uftrace/blob/master/INSTALL.md)]
<pre>
<code class="bash">$ git clone https://github.com/namhyung/uftrace && cd uftrace

# To install required packages
$ sudo <a href="https://raw.githubusercontent.com/namhyung/uftrace/master/misc/install-deps.sh">./misc/install-deps.sh</a>

$ ./configure
uftrace detected system features:
...         prefix: /usr/local
...         libelf: [ .green[on]  ] - more flexible ELF data handling
...          libdw: [ .green[on]  ] - DWARF debug info support
...      libpython: [ .green[on]  ] - python tracing & scripting support
...      libluajit: [ .green[on]  ] - luajit scripting support
...    libncursesw: [ .green[on]  ] - TUI support
...   cxa_demangle: [ .green[on]  ] - full demangler support with libstdc++
...     perf_event: [ .green[on]  ] - perf (PMU) event support
...       schedule: [ .green[on]  ] - scheduler event support
...       capstone: [ .green[on]  ] - full dynamic tracing support

$ make

$ sudo make install
</code>
</pre>

---
name: basic-tracing
template: title-layout
# Basic Tracing
### record and replay

---
### uftrace
- uftrace is able to trace
  - C/C++ (user space) functions
      - compiled with -pg or -finstrument-functions
  - Library functions
  - Linux kernel functions
  - Some of system events

---
name: user-tracing
### C/C++ (user) Function Tracing
- Compiler assists tracing with -pg or -finstrument-functions

.left-column[
```
$ cat foobar.c
void bar() {

}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
```
]

---
### C/C++ (user) Function Tracing
- Compiler assists tracing with -pg or -finstrument-functions

.left-column[
```
$ cat foobar.c
void bar() {

}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
$ gcc foobar.c
<bar>:

ret

<foo>:

call <bar>
  ret

<main>:

call <foo>
  call <bar>
  ret
```
]

---
### C/C++ (user) Function Tracing
- Compiler assists tracing with -pg or -finstrument-functions

.left-column[
```
$ cat foobar.c
void bar() {

}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
$ gcc `-pg` foobar.c
<bar>:
* call <mcount@plt>
  ret

<foo>:
* call <mcount@plt>
  call <bar>
  ret

<main>:
* call <mcount@plt>
  call <foo>
  call <bar>
  ret
```
]
---
### C/C++ (user) Function Tracing
- Compiler assists tracing with -pg or -finstrument-functions

.left-column[
```
$ cat foobar.c
void bar() {

}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
$ gcc `-finstrument-functions` foobar.c
<bar>:
* call <__cyg_profile_func_enter@plt>
* call <__cyg_profile_func_exit@plt>
  ret

<foo>:
* call <__cyg_profile_func_enter@plt>
  call <bar>
* call <__cyg_profile_func_exit@plt>
  ret

<main>:
* call <__cyg_profile_func_enter@plt>
  call <foo>
  call <bar>
* call <__cyg_profile_func_exit@plt>
  ret
```
]

---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace record
  - Run a command and record its trace data

```
  $ gcc foobar.c
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace record
  - Run a command and record its trace data

```
  $ gcc `-pg` foobar.c
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace record
  - Run a command and record its trace data

```
  $ gcc -pg foobar.c
  $ ./a.out
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace record
  - Run a command and record its trace data

```
  $ gcc -pg foobar.c
  $ uftrace `record` a.out
```
---
class: code-26px
### C/C++ (user) Function Tracing
.footnote[[uftrace.data](https://github.com/namhyung/uftrace/wiki/Data-Format) contains recorded data]
- uftrace record
  - Run a command and record its trace data

<pre><code>  $ gcc -pg foobar.c
  $ uftrace record a.out
  $ ls
  <x-green>a.out</x-green>  foobar.c  <a href="https://github.com/namhyung/uftrace/wiki/Data-Format">uftrace.data</a>
</code></pre>
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace record
  - Run a command and record its trace data

```
  $ gcc -pg foobar.c
  $ uftrace record a.out
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace replay
  - Print recorded function trace

```
  $ gcc -pg foobar.c
  $ uftrace record a.out
  $ uftrace `replay`
  # DURATION     TID     FUNCTION
              [112643] | main() {
              [112643] |   foo() {
     0.190 us [112643] |     bar();
     1.083 us [112643] |   } /* foo */
     0.127 us [112643] |   bar();
     2.050 us [112643] | } /* main */
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace live
  - Trace functions both doing record and replay

```
  $ gcc -pg foobar.c

$ uftrace `live` a.out
  # DURATION     TID     FUNCTION
              [112643] | main() {
              [112643] |   foo() {
     0.190 us [112643] |     bar();
     1.083 us [112643] |   } /* foo */
     0.127 us [112643] |   bar();
     2.050 us [112643] | } /* main */
```
---
class: code-26px
### C/C++ (user) Function Tracing
- uftrace .grey[(live)]
  - .red[live] can be omitted

```
  $ gcc -pg foobar.c

---
name: lib-tracing
### Library Function Tracing
- Library Function Tracing works via PLT hooking
  - PLT contains trampoline code for calling shared functions

```
    $ gcc -pg foobar.c
```

.left-column[
```
void bar() {

}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
<bar>:
  call <mcount@plt>

ret

<foo>:
  call <mcount@plt>
  call <bar>
  ret

<main>:
  call <mcount@plt>
  call <foo>
  call <bar>
  ret
```
]
---
### Library Function Tracing
- Library Function Tracing works via .red[PLT hooking]
  - PLT contains trampoline code for calling shared functions

```
    $ gcc -pg foobar.c
```

.left-column[
```
void bar() {
  `getpid()`;
}

void foo() {
  bar();
}

int main() {
  foo();
  bar();
}
```
]
.right-column[
```
<bar>:
  call <mcount@plt>
* call <getpid@plt> # call to PLT
  ret

<foo>:
  call <mcount@plt>
  call <bar>
  ret

<main>:
  call <mcount@plt>
  call <foo>
  call <bar>
  ret
```
]
---
class: code-26px
### Library Function Tracing
- Library Function Tracing works via PLT hooking
  - PLT contains trampoline code for calling shared functions

```
    $ gcc -pg foobar.c
```
---
class: code-26px
### Library Function Tracing
- Library Function Tracing works via PLT hooking
  - PLT contains trampoline code for calling shared functions

```
    $ gcc -pg foobar.c

$ uftrace a.out
```
---
class: code-26px
### Library Function Tracing
- Library Function Tracing works via PLT hooking
  - PLT contains trampoline code for calling shared functions

```
    $ gcc -pg foobar.c

$ uftrace a.out
    # DURATION     TID     FUNCTION
                [112962] | main() {
                [112962] |   foo() {
                [112962] |     bar() {
       0.863 us [112962] |       `getpid`();
       1.774 us [112962] |     } /* bar */
       2.334 us [112962] |   } /* foo */
                [112962] |   bar() {
       0.176 us [112962] |     `getpid`();
       0.666 us [112962] |   } /* bar */
       3.663 us [112962] | } /* main */
```
---
class: code-26px
### Library Function Tracing
- --no-libcall
  - Do not record library function invocations.

```
    $ gcc -pg foobar.c

$ uftrace `--no-libcall` a.out
    # DURATION     TID     FUNCTION
                [112962] | main() {
                [112962] |   foo() {
                [112962] |     bar() {
//       0.863 us [112962] |       getpid();
       1.774 us [112962] |     } /* bar */
       2.334 us [112962] |   } /* foo */
                [112962] |   bar() {
//       0.176 us [112962] |     getpid();
       0.666 us [112962] |   } /* bar */
       3.663 us [112962] | } /* main */
```
---
class: code-26px
### Library Function Tracing
- --no-libcall
  - Do not record library function invocations.

```
    $ gcc -pg foobar.c

$ uftrace `--no-libcall` a.out
    # DURATION     TID     FUNCTION
                [112962] | main() {
                [112962] |   foo() {
       1.774 us [112962] |     bar();
       2.334 us [112962] |   } /* foo */
       0.666 us [112962] |   bar();
       3.663 us [112962] | } /* main */
```
---
class: code-26px
### Library Function Tracing
- C++ example
  - new and delete library calls

```
  $ cat new-delete.cpp
  int main()
  {
      int* p = new int;
      delete p;
  }
```
---
class: code-26px
### Library Function Tracing
- C++ example
  - new and delete library calls

```
  $ cat new-delete.cpp
  int main()
  {
      int* p = new int;
      delete p;
  }

$ g++ -pg new-delete.cpp
```
---
class: code-26px
### Library Function Tracing
- C++ example
  - It shows .red[operator new] and .red[operator delete]

```
  $ uftrace a.out
  # DURATION     TID     FUNCTION
              [180964] | main() {
     2.420 us [180964] |   `operator new`();
     3.170 us [180964] |   `operator delete`();
    11.220 us [180964] | } /* main */
```
---
class: code-26px
### Library Function Tracing
- --nest-libcall
  - Trace function calls between libraries.

```
  $ uftrace `--nest-libcall` a.out
  # DURATION     TID     FUNCTION
              [180978] | main() {
              [180978] |   operator new() {

4.250 us [180978] |   } /* operator new */
              [180978] |   operator delete() {

3.547 us [180978] |   } /* operator delete */
    11.857 us [180978] | } /* main */
```
---
class: code-26px
### Library Function Tracing
- --nest-libcall
  - Trace function calls between libraries.

```
  $ uftrace `--nest-libcall` a.out
  # DURATION     TID     FUNCTION
              [180978] | main() {
              [180978] |   operator new() {
     0.957 us [180978] |     `malloc`();
     4.250 us [180978] |   } /* operator new */
              [180978] |   operator delete() {
     1.540 us [180978] |     `free`();
     3.547 us [180978] |   } /* operator delete */
    11.857 us [180978] | } /* main */
```

---
name: kernel-tracing
class: code-26px
### Linux Kernel Function Tracing
- -k, --kernel
  - Trace kernel functions as well as user functions.

```
  $ gcc -pg hello.c
```
---
class: code-26px
### Linux Kernel Function Tracing
- -k, --kernel
  - Trace kernel functions as well as user functions.

```
  $ gcc -pg hello.c
  $ uftrace a.out
  Hello World!
  # DURATION     TID     FUNCTION
              [161960] | main() {
     7.267 us [161960] |   printf();
     6.920 us [161960] |   fflush();
    15.694 us [161960] | } /* main */
```
---
class: code-26px
### Linux Kernel Function Tracing
- -k, --kernel
  - Trace kernel functions as well as user functions.

```
  $ gcc -pg hello.c
  $ `sudo` uftrace `-k` a.out
  Hello World!
  # DURATION     TID     FUNCTION
              [161968] | main() {
              [161968] |   printf() {

32.457 us [161968] |   } /* printf */
              [161968] |   fflush() {

25.244 us [161968] |   } /* fflush */
    59.221 us [161968] | } /* main */
```
---
class: code-26px
### Linux Kernel Function Tracing
- -k, --kernel
  - Trace kernel functions as well as user functions.

```
  $ gcc -pg hello.c
  $ `sudo` uftrace `-k` a.out
  Hello World!
  # DURATION     TID     FUNCTION
              [161968] | main() {
              [161968] |   printf() {
     7.770 us [161968] |     `sys_newfstat`();
    11.737 us [161968] |     `__do_page_fault`();
    32.457 us [161968] |   } /* printf */
              [161968] |   fflush() {
    18.637 us [161968] |     `sys_write`();
    25.244 us [161968] |   } /* fflush */
    59.221 us [161968] | } /* main */
```
---
class: code-18px
### Linux Kernel Function Tracing
- -K DEPTH, --kernel-depth=DEPTH
  - Set kernel max function depth separately.

```
      $ sudo uftrace `-K 2` a.out
      Hello World!
```
---
class: code-18px
### Linux Kernel Function Tracing
- -K DEPTH, --kernel-depth=DEPTH
  - Set kernel max function depth separately.

```
      $ sudo uftrace `-K 2` a.out
      Hello World!
      # DURATION     TID     FUNCTION
                  [162954] | main() {
                  [162954] |   printf() {
                  [162954] |     `sys_newfstat`() {
         3.074 us [162954] |       `vfs_fstat`();
         1.200 us [162954] |       `cp_new_stat`();
         6.914 us [162954] |     } /* sys_newfstat */
                  [162954] |     `__do_page_fault`() {
         0.643 us [162954] |       `down_read_trylock`();
         0.630 us [162954] |       `_cond_resched`();
         2.440 us [162954] |       `find_vma`();
         9.697 us [162954] |       `handle_mm_fault`();
         0.690 us [162954] |       `up_read`();
        21.813 us [162954] |     } /* __do_page_fault */
        42.064 us [162954] |   } /* printf */
                  [162954] |   fflush() {
                  [162954] |     `sys_write`() {
         0.933 us [162954] |       `__fdget_pos`();
        18.310 us [162954] |       `vfs_write`();
        27.117 us [162954] |     } /* sys_write */
        30.673 us [162954] |   } /* fflush */
        74.223 us [162954] | } /* main */
```

---
name: event-tracing
class: code-20px
### Event Tracing (scheduling event)
<pre>
<code class="plain">        $ uftrace tests/t-fork
        # DURATION     TID     FUNCTION
                    [ 14528] | main() {
         127.033 us [ 14528] |   fork();
                    [ 14528] |   wait() {
                    [ 14528] |     /* <x-green>linux:sched-out</x-green> */
                    [ 14540] |   } /* fork */
                    [ 14540] |   a() {
                    [ 14540] |     b() {
                    [ 14540] |       c() {
           1.507 us [ 14540] |         getpid();
           2.987 us [ 14540] |       } /* c */
           3.464 us [ 14540] |     } /* b */
           3.854 us [ 14540] |   } /* a */
          13.394 us [ 14540] | } /* main */
                    [ 14528] |     /* <x-green>linux:sched-in</x-green> */
         799.270 us [ 14528] |   } /* wait */
                    [ 14528] |   a() {
                    [ 14528] |     b() {
                    [ 14528] |       c() {
           2.410 us [ 14528] |         getpid();
           3.470 us [ 14528] |       } /* c */
           3.833 us [ 14528] |     } /* b */
           4.144 us [ 14528] |   } /* a */
         952.797 us [ 14528] | } /* main */
</code>
</pre>
---
class: code-20px
### Event Tracing (scheduling event)
<pre>
<code class="plain">        $ uftrace `--no-event` tests/t-fork
        # DURATION     TID     FUNCTION
                    [ 14528] | main() {
         127.033 us [ 14528] |   fork();
                    [ 14528] |   wait() {
                    [ 14540] |   } /* fork */
                    [ 14540] |   a() {
                    [ 14540] |     b() {
                    [ 14540] |       c() {
           1.507 us [ 14540] |         getpid();
           2.987 us [ 14540] |       } /* c */
           3.464 us [ 14540] |     } /* b */
           3.854 us [ 14540] |   } /* a */
          13.394 us [ 14540] | } /* main */
         799.270 us [ 14528] |   } /* wait */
                    [ 14528] |   a() {
                    [ 14528] |     b() {
                    [ 14528] |       c() {
           2.410 us [ 14528] |         getpid();
           3.470 us [ 14528] |       } /* c */
           3.833 us [ 14528] |     } /* b */
           4.144 us [ 14528] |   } /* a */
         952.797 us [ 14528] | } /* main */
</code>
</pre>

---
name: filters
template: title-layout
# Filters
.footnote[[wiki/Filters](https://github.com/namhyung/uftrace/wiki/Filters)]

---
class: code-26px
### Filters
- -D DEPTH, --depth=DEPTH
  - Set global trace limit in nesting level.