---
# System prepended metadata

title: Function Tracing
tags: [Profiling]

---

###### tags: `Profiling`

# Function Tracing

:::info
- uftrace: function tracing in userspace
- trace-cmd: front end for ftrace in Linux
:::

## uftrace
uftrace 為 userspace 的函式追蹤器，使用方法跟輸出都類似 Linux 的 ftrace，以下筆記 uftrace 的使用方法。

### Prerequisite

確認被追蹤的函式庫和執行檔都有使用 `-pg` 編譯及連結，若使用 cmake 可以修改以下參數：

- CMAKE_C_FLAGS
- CMAKE_CXX_FLAGS
- CMAKE_EXE_LINKER_FLAGS

若使用 ROS2 的組建工具 colcon 則可以使用以下命令，自動組建可用 uftrace 追蹤的執行檔。
```bash
$ colcon build --symlink-install \
  --cmake-args -DCMAKE_C_FLAGS="-pg" \
               -DCMAKE_CXX_FLAGS="-pg" \
               -DCMAKE_EXE_LINKER_FLAGS="-pg" \
```

### Usage

> 常用指令的 man pages:
> [uftrace-record(1)](https://github.com/namhyung/uftrace/blob/master/doc/uftrace-record.md), [uftrace-report(1)](https://github.com/namhyung/uftrace/blob/master/doc/uftrace-report.md)

紀錄一個命令 :
```bash
$ uftrace record -a -k <command>
```
- `-a`: auto arguments recording
- `-k`: 追蹤 kernel 函數 (需要有 root 權限)

列出效能報表，依照函數花費的時間排序
```bash
$ uftrace report
```

Ouput example (紀錄 ROS2 應用程式的熱點):
```cpp
$ uftrace report
  Total time   Self time       Calls  Function
  ==========  ==========  ==========  ====================
    2.036  m    2.036  m         580  linux:schedule
    2.016  m  163.070 us          54  std::__invoke
    2.016  m   85.230 us          54  std::__invoke_impl
    2.016  m   32.664 us           6  std::thread::_State_impl::_M_run
    2.016  m    5.664 us           6  std::thread::_Invoker::operator()
    2.016  m   22.143 us           6  std::thread::_Invoker::_M_invoke
    1.008  m  493.544 us           3  eprosima::fastrtps::rtps::UDPChannelResource::perform_listen_operation
    1.007  m  392.896 us         113  eprosima::fastrtps::rtps::UDPChannelResource::Receive
    1.007  m  333.519 us         113  asio::basic_datagram_socket::receive_from
    1.007  m   84.633 us         113  asio::datagram_socket_service::receive_from
    1.007  m  548.420 us         113  asio::detail::reactive_socket_service::receive_from
    1.007  m   88.103 us         113  asio::detail::socket_ops::sync_recvfrom
    1.007  m    2.466 ms         113  asio::detail::socket_ops::recvfrom
   44.130  s    2.902 ms         404  rclcpp::sleep_for
   22.766  s    4.360 ms           1  main
   22.707  s    1.428 us           1  eprosima::fastrtps::rtps::ResourceEvent::run_io_service
   22.707  s    1.405 us           1  asio::io_service::run
   22.707  s  179.629 us           1  asio::detail::task_io_service::run
   22.707  s  325.524 us          49  asio::detail::task_io_service::do_run_one
   ...
```

印出函式呼叫關係，適合用在追蹤大型的軟體架構：
```
$ uftrace replay
```
單純使用 `replay` 可能會印出太多函式，以 ROS2 為例一個簡單的 talker  (不斷的發送資料給其他節點) 會印出約近千萬筆函式呼叫的紀錄，因此需搭配 uftrace 提供的過濾功能：

只列出幾個常用的選項，以下旗標可以在 uftrace 的任何子命令使用
- `-F FUNC`: 函式白名單，只列出 FUNC 函式
- `-N FUNC`: 函式黑名單，排除 FUNC 函式
- `-C FUNC`: 列出所有呼叫 FUNC 的函式，也就是列出 FUNC 的 caller
- <mark>`-t TIME`: 以函式的執行時間過濾，只列出執行時間大於 TIME 的函式 (最好用)</mark>

使用範例，列出所有執行時間大於 50us 且函式名稱開頭不是 std 的所有函式：
```
$ uftrace replay -N ^std -t 50us
```

輸出結果，只列出其中一部份：
```
$ uftrace replay -N ^std -t 50us
...
            [ 30561] |   rclcpp::Publisher::publish(0x562cc5ba4150, 0x7ffdcdd97ab0) {
            [ 30561] |     rclcpp::Publisher::do_inter_process_publish(0x562cc5ba4150, 0x7ffdcdd97ab0) {
            [ 30561] |       rcl_publish() {
            [ 30561] |         rcl_publish(0x562cc5ba4168, 0x7ffdcdd97ab0, 0) {
            [ 30561] |           rmw_publish(0x562cc5bf8230, 0x7ffdcdd97ab0, 0) {
            [ 30561] |             rmw_publish() {
            [ 30561] |               rmw_fastrtps_shared_cpp::__rmw_publish() {
            [ 30561] |                 eprosima::fastrtps::Publisher::write() {
            [ 30561] |                   eprosima::fastrtps::PublisherImpl::create_new_change() {
            [ 30561] |                     eprosima::fastrtps::PublisherImpl::create_new_change_with_params() {
            [ 30561] |                       rmw_fastrtps_shared_cpp::TypeSupport::serialize() {
            [ 30561] |                         rmw_fastrtps_cpp::TypeSupport::serializeROSmessage() {
  50.561 us [ 30561] |                           std_msgs::msg::typesupport_fastrtps_cpp::_String__cdr_serialize();
  64.284 us [ 30561] |                         } /* rmw_fastrtps_cpp::TypeSupport::serializeROSmessage */
  72.783 us [ 30561] |                       } /* rmw_fastrtps_shared_cpp::TypeSupport::serialize */
            [ 30561] |                       eprosima::fastrtps::PublisherHistory::add_pub_change() {
            [ 30561] |                         eprosima::fastrtps::rtps::WriterHistory::add_change_() {
            [ 30561] |                           eprosima::fastrtps::rtps::StatefulWriter::unsent_change_added_to_history() {
  66.144 us [ 30561] |                             eprosima::fastrtps::rtps::ChangeForReader_t::ChangeForReader_t();
  55.405 us [ 30561] |                             eprosima::fastrtps::rtps::ReaderProxy::add_change();
  51.435 us [ 30561] |                             eprosima::fastrtps::rtps::AsyncWriterThread::wakeUp();
 211.351 us [ 30561] |                           } /* eprosima::fastrtps::rtps::StatefulWriter::unsent_change_added_to_history */
 245.287 us [ 30561] |                         } /* eprosima::fastrtps::rtps::WriterHistory::add_change_ */
 247.500 us [ 30561] |                       } /* eprosima::fastrtps::PublisherHistory::add_pub_change */
 429.102 us [ 30561] |                     } /* eprosima::fastrtps::PublisherImpl::create_new_change_with_params */
 440.351 us [ 30561] |                   } /* eprosima::fastrtps::PublisherImpl::create_new_change */
 445.366 us [ 30561] |                 } /* eprosima::fastrtps::Publisher::write */
 446.717 us [ 30561] |               } /* rmw_fastrtps_shared_cpp::__rmw_publish */
 447.939 us [ 30561] |             } /* rmw_publish */
 450.116 us [ 30561] |           } = 0; /* rmw_publish */
 457.967 us [ 30561] |         } = 0; /* rcl_publish */
 459.788 us [ 30561] |       } /* rcl_publish */
 460.571 us [ 30561] |     } /* rclcpp::Publisher::do_inter_process_publish */
 461.153 us [ 30561] |   } /* rclcpp::Publisher::publish */
```

### Set Record Whitelist
指定所有要追蹤的函式，以下為 ROS2 使用 fastrtps 當作底層 DDS middleware 時，傳輸和接收一個 ros message 所呼叫的函式 (按照呼叫順序)。
```
// publish side
rcl_publish
eprosima::fastrtps::Publisher::write
eprosima::fastrtps::PublisherHistory::add_pub_change

eprosima::fastrtps::rtps::UDPTransportInterface::ShrinkLocatorLists
eprosima::fastrtps::rtps::NetworkFactory::ShrinkLocatorLists
eprosima::fastrtps::rtps::RTPSMessageGroup::add_data
eprosima::fastrtps::rtps::RTPSMessageGroup::~RTPSMessageGroup

// subscription side
rmw_wait
eprosima::fastrtps::rtps::ReceiverResource::OnDataReceived
eprosima::fastrtps::SubscriberHistory::add_received_change
rclcpp::executor::Executor::execute_subscription
rmw_take_with_info
```

如果直接使用 uftrace 過濾函式名稱，使用過後覺得有些困難，不僅是因為 mcount 會造成 overhead，造成函式之間經過的時間失真，而且過濾規則可能要套用 uftrace 的 TRIGGER 選項，指定呼叫的深度，因此改用 bpftrace 簡單寫一個腳本觀察呼叫時間。

以下為輸出範例，最左邊為 timestamp (單位為 us)，lat 代表函式進入和回傳經過的時間
```
...
29043337757, rmw_wait entry
29043436718, ReceiverResource::OnDataReceived
29043436796, add_received_change
29043436937, rmw_wait exit, lat: 99219 us
29043437122, rmw_take_with_info, lat: 58 us
...
```

## trace-cmd

trace-cmd 為 ftrace 提供一個簡易使用的前端命令，追蹤 Linux kernel 中的函式呼叫。

### 1. Trace ROS2 Applications Function Calls

ftrace 會追蹤整個系統上的核心的函式呼叫，第一個欄位會顯示此呼叫所屬的程式為何 (格式為 comm-pid)，因 ROS2 使用 DDS 進行傳輸，DDS 的通訊協定 DDSI-RTPS 是建立在 UDP 之上，因此觀察 `udp_sendmsg` 了解系統行為及效能，以下為追蹤使用的命令：

```bash
$ trace-cmd record -p function_graph -c -g udp_sendmsg <command>
```
- `-p`: 選擇要使用的 plugin，function_graph 會紀錄某個函式及其所呼叫的函式
- `-c`: 表示要紀錄 child process
- `-g`: 此選項提供給 function_graph，指定要紀錄的函式，這裡紀錄 `udp_sendmsg`

:::info
plugin 總共有 function, function_graph, preemptirqsoff, irqsoff, preemptoff, and wakeup

請參考 [trace-cmd-record(1)](https://linux.die.net/man/1/trace-cmd-record)
:::

### Output Example

```
$ trace-cmd report
```

單行範例，每一行皆代表一個事件，funcgraph_entry 代表函式進入。
```
talker-22190 [002] 567757.342223: funcgraph_entry: |  udp_sendmsg() {
```


以下為修改過後的輸出結果，拿掉 plugin 名稱 (funcgraph_entry, funcgraph_exit)。
```
$ trace-cmd report | cut --complement -c1-10,44-65 | less
...

talker-22196 [009] 567758.376036:              |  udp_sendmsg() {
talker-22196 [009] 567758.376042:              |    lock_sock_nested() {
talker-22196 [009] 567758.376044:              |      _cond_resched() {
talker-22196 [009] 567758.376046:   1.667 us   |        rcu_all_qs();
talker-22196 [009] 567758.376050:   5.500 us   |      }
talker-22196 [009] 567758.376052:   1.724 us   |      _raw_spin_lock_bh();
talker-22196 [009] 567758.376055:   1.666 us   |      __local_bh_enable_ip();
talker-22196 [009] 567758.376058: + 16.475 us  |    }
talker-22196 [009] 567758.376060:   2.093 us   |    __cgroup_bpf_run_filter_sock_addr();
talker-22196 [009] 567758.376064:              |    release_sock() {
talker-22196 [009] 567758.376065:   1.662 us   |      _raw_spin_lock_bh();
talker-22196 [009] 567758.376069:   1.848 us   |      ip4_datagram_release_cb();
talker-22196 [009] 567758.376072:              |      _raw_spin_unlock_bh() {
talker-22196 [009] 567758.376074:   1.666 us   |        __local_bh_enable_ip();
talker-22196 [009] 567758.376077:   4.750 us   |      }
talker-22196 [009] 567758.376079: + 15.150 us  |    }
talker-22196 [009] 567758.376081:   1.896 us   |    security_sk_classify_flow();
talker-22196 [009] 567758.376085:              |    ip_route_output_flow() {
talker-22196 [009] 567758.376086:              |      ip_route_output_key_hash() {
talker-22196 [009] 567758.376088:              |        ip_route_output_key_hash_rcu() {
talker-22196 [009] 567758.376090:   4.407 us   |          fib_table_lookup();
talker-22196 [009] 567758.376097:   1.615 us   |          find_exception();
talker-22196 [009] 567758.376101: + 13.135 us  |        }
talker-22196 [009] 567758.376103: + 16.453 us  |      }
...
talker-22196 [009] 567758.376329:              |    udp_send_skb.isra.47() {
talker-22196 [009] 567758.376331:   1.708 us   |      udp4_hwcsum();
talker-22196 [009] 567758.376334:              |      ip_send_skb() {
talker-22196 [009] 567758.376336:              |        ip_local_out() {
talker-22196 [009] 567758.376337:              |          __ip_local_out() {
talker-22196 [009] 567758.376339:   1.635 us   |            ip_send_check();
talker-22196 [009] 567758.376342:   4.588 us   |          }
talker-22196 [009] 567758.376344:              |          ip_output() {
talker-22196 [009] 567758.376345:              |            ip_finish_output() {
talker-22196 [009] 567758.376347:   2.084 us   |              __cgroup_bpf_run_filter_skb();
talker-22196 [009] 567758.376351:              |              __ip_finish_output() {
talker-22196 [009] 567758.376353:   1.640 us   |                ipv4_mtu();
talker-22196 [009] 567758.376356:              |                ip_finish_output2() {
talker-22196 [009] 567758.376360:              |                  dev_queue_xmit() {
talker-22196 [009] 567758.376362:              |                    __dev_queue_xmit() {
talker-22196 [009] 567758.376364:   1.771 us   |                      netdev_core_pick_tx();
talker-22196 [009] 567758.376368:              |                      validate_xmit_skb() {
talker-22196 [009] 567758.376369:              |                        netif_skb_features() {
talker-22196 [009] 567758.376372:   1.682 us   |                          skb_network_protocol();
talker-22196 [009] 567758.376375:   5.624 us   |                        }
talker-22196 [009] 567758.376377:   1.694 us   |                        skb_csum_hwoffload_help();
talker-22196 [009] 567758.376380:   1.734 us   |                        validate_xmit_xfrm();
talker-22196 [009] 567758.376384: + 15.748 us  |                      }
talker-22196 [009] 567758.376387:              |                      dev_hard_start_xmit() {
...
```

:::info
使用 function_graph 回報的函式執行時間，會受到其內部函式的呼叫次數影響，呼叫次數越多或層數越多，overhead 就越大，若要精準的執行時間要使用以下命令： 
```bash
$ trace-cmd record -p function -l <func_name>
```
:::

### 2. Trace a BPF Helper Calls

TC (Traffic Control) 在 Linux 是用來過濾並排程封包的子系統，在 TC 中也有一個 eBPF hook，可以讓我們掛載自訂 eBPF 程式過濾封包。在 Linux Network Stack 之中呼叫 `cls_bpf_classify` 時就會執行目前註冊的 eBPF 程式。

```
cpus=12
...
   ssh-15986 [002]  2882.242765: funcgraph_entry:                   |  cls_bpf_classify() {
   ssh-15986 [002]  2882.242767: funcgraph_entry:        0.213 us   |    bpf_skb_load_bytes();
   ssh-15986 [002]  2882.242767: funcgraph_exit:         2.816 us   |  }
<idle>-0     [002]  2882.243697: funcgraph_entry:                   |  cls_bpf_classify() {
<idle>-0     [002]  2882.243697: funcgraph_entry:        0.150 us   |    bpf_skb_load_bytes();
<idle>-0     [002]  2882.243698: funcgraph_exit:         1.330 us   |  }
talker-17381 [003]  2882.290333: funcgraph_entry:                   |  cls_bpf_classify() {
talker-17381 [003]  2882.290339: funcgraph_entry:        1.255 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290342: funcgraph_entry:        1.022 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290344: funcgraph_entry:        1.031 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290346: funcgraph_entry:        0.978 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290348: funcgraph_entry:        0.959 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290349: funcgraph_entry:        0.974 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290351: funcgraph_entry:        0.958 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290353: funcgraph_entry:        0.963 us   |    bpf_skb_load_bytes();
talker-17381 [003]  2882.290355: funcgraph_entry:                   |    bpf_ktime_get_ns() {
talker-17381 [003]  2882.290356: funcgraph_entry:        1.271 us   |      ktime_get_mono_fast_ns();
talker-17381 [003]  2882.290358: funcgraph_exit:         3.032 us   |    }
talker-17381 [003]  2882.290359: funcgraph_entry:                   |    bpf_skb_event_output() {
talker-17381 [003]  2882.290361: funcgraph_entry:                   |      perf_misc_flags() {
talker-17381 [003]  2882.290362: funcgraph_entry:        0.923 us   |        kvm_is_in_guest();
talker-17381 [003]  2882.290364: funcgraph_exit:         3.681 us   |      }
talker-17381 [003]  2882.290366: funcgraph_entry:        1.791 us   |      perf_output_begin();
talker-17381 [003]  2882.290369: funcgraph_entry:        1.083 us   |      perf_output_copy();
talker-17381 [003]  2882.290371: funcgraph_entry:        0.948 us   |      perf_output_copy();
talker-17381 [003]  2882.290373: funcgraph_entry:                   |      perf_output_end() {
talker-17381 [003]  2882.290374: funcgraph_entry:                   |        perf_output_put_handle() {
```

#### Dump Kernel Stack

印出呼叫函式時的堆疊。

```
          talker-30890 [010]  6385.274551: function:             cls_bpf_classify
          talker-30890 [010]  6385.274552: kernel_stack:         <stack trace>
=> cls_bpf_classify (ffffffffc0f38585)
=> tcf_classify (ffffffff82f597c0)
=> __dev_queue_xmit (ffffffff82efcc16)
=> dev_queue_xmit (ffffffff82efd1c0)
=> ip_finish_output2 (ffffffff82f786e1)
=> __ip_finish_output (ffffffff82f78a7a)
=> ip_finish_output (ffffffff82f78b6c)
=> ip_mc_output (ffffffff82f7a15d)
=> ip_local_out (ffffffff82f79aeb)
=> ip_send_skb (ffffffff82f7ac99)
=> udp_send_skb.isra.47 (ffffffff82fa9d76)
=> udp_sendmsg (ffffffff82faa6b7)
=> inet_sendmsg (ffffffff82fb9dad)
=> sock_sendmsg (ffffffff82ed79dc)
=> ___sys_sendmsg (ffffffff82ed8b19)
=> __sys_sendmsg (ffffffff82eda363)
=> __x64_sys_sendmsg (ffffffff82eda3bf)
=> do_syscall_64 (ffffffff8260441a)
=> entry_SYSCALL_64_after_hwframe (ffffffff8320008c)
          talker-30890 [010]  6385.274553: function:             bpf_ktime_get_ns
          talker-30890 [010]  6385.274554: kernel_stack:         <stack trace>
=> bpf_ktime_get_ns (ffffffff827e63d5)

```

---
## References:

### uftrace
uftrace-replay: https://github.com/namhyung/uftrace/blob/master/doc/uftrace-replay.md

### ftrace

trace-cmd tutorial: https://jvns.ca/blog/2017/03/19/getting-started-with-ftrace/