用 ftrace + uprobe trace 應用程序 - 1

ftrace 整合了 uprobe, 可以很方便的在使用者應用中加上 probe point, 如此不需 gdb 就可以對應用做 trace 動作, 也不需要修改程序或重 build, 相當的便利.

所有的操作, 跟 ftrace 一樣, 都是在 debugfs 中完成的

/sys/kernel/debug/tracing

裡面跟 uprobe 相關的檔案如下

# ls uprobe_*
uprobe_events  uprobe_profile

要新增 probe point 就對 uprobe_events 寫入, 要瞭解 uprobe 的統計資訊可參考 uprobe_profile.

接著, 說明下什麼是 uprobe. uprobe 算是 Linux kernel 中提供的 dynamic tracing 機制之一, 可以按需, 在應用的 .text 段加上 probe point, 當程序執行到該處時, 就會轉跳到 ftrace 實現的 uprobe event handler 中, 然後, 可以進行如全局變量, 參數, 堆的取值及打印, 結果都會出現在 kernel ring buffer 中, 取得內容的方法如下

# cat /sys/kernel/debug/tracing/trace

然後, 重點來了, 要增加 probe point 的話對 uprobe_events 寫入, 寫些什麼? 根據 Linux kernel 中 Documentation/trace/uprobetrace.txt 的說明, 語法如下

  p[:[GRP/]EVENT] PATH:OFFSET [FETCHARGS] : Set a uprobe
  r[:[GRP/]EVENT] PATH:OFFSET [FETCHARGS] : Set a return uprobe (uretprobe)
  -:[GRP/]EVENT                           : Clear uprobe or uretprobe event
  • p 類型的 probe 加在 function 的開始或中間處
  • r 類型的 return probe 只會在 function 返回時觸發, 可能取 return value
  • GRP 為可選的 group name, default 為 uprobes
  • EVENT 為可選的 event name
  • PATH 為可執行程序或庫的路徑
  • OFFSET 為 probe 要放置的 address, 當然, 是會是 .text 段
  • FETCHARGS 當 probe 被觸發時, 用來取出如全局變量, 參數, 堆, 任意地址上的值, 這個稍晚說明

首先, 我們準備個程序用來測試

#include <stdio.h>

void hello1(int v)
{
    printf("%d\n", v);
}

void hello2(int v, char *s)
{
    printf("v=%d, s=%s\n", v, s);
}

struct Member
{
    unsigned int age;
    const char *name;
};

void hello3(int v, char *s, const struct Member *m)
{
    printf("v=%d, s=%s, (Member){%u, %s}\n", v, s, m->age, m->name);
}

int main()
{
    hello1(1);
    hello2(2, "foo");
    hello3(3, "bar", &(struct Member){60, "John"});

    return 0;
}

Build 出可執行程序

$ gcc -o hello hello.c

uprobe 需要使用者跟它說 probe point 要放在內存的什麼位置 (即先前提到的 OFFSET), 可配合 readelf 命令取得, 例如

$ readelf -s hello | grep hello
    36: 0000000000000000     0 FILE    LOCAL  DEFAULT  ABS hello.c
    53: 0000000000400527    41 FUNC    GLOBAL DEFAULT   13 hello2
    65: 0000000000400550    62 FUNC    GLOBAL DEFAULT   13 hello3
    66: 0000000000400506    33 FUNC    GLOBAL DEFAULT   13 hello1

這樣我們就有了 3 個 hello?() 的 address, 但這個 address 還不能直接使用, 還得要減去 base address

$ readelf -e hello | grep -m 1 LOAD
  LOAD           0x0000000000000000 0x0000000000400000 0x0000000000400000

這裡的 0x0000000000400000 就是 base address, 所以, hello1() 的 uprobe address 就是

0x400506 - 0x400000 = 0x506

好, 在加上新 probe point 前, 先把 uprobe 關掉並清空先前定義的 uprobe

# cd /sys/kernel/debug/tracing
# [ -f events/uprobes/enable ] && echo 0 >events/uprobes/enable
# echo >uprobe_events

接下來試試看在 hello1() 加上 probe point

# echo "p $HOME/hello:0x506" >uprobe_events

啟動 uprobe 開始產生 log

# echo 1 >events/uprobes/enable

補充說明一下, 在 ftrace 中所有的 events 都可以在 events 目錄下找到. 由於 static tracepoint 及基於 mount 的 probe point 是在 build kernel 時就決定下來了, 所以它們產生的 event 在 events 目錄下是固定不變的. 基於 uprobe 及 kprobe 的 probe point 則是按需加上的(dynamic probe point), 所以在 events 目錄下的 uprobeskprobes 目錄也是增加了定義才出現, 所以上面的 script 先確認了 events/uprobes/enable 是否存在才寫入 0 關閉所有 uprobe 的 probe point 停止產生 event.

執行測試程序

# ~/hello
1
v=2, s=foo
v=3, s=bar, (Member){60, John}

查看 log

# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-17987 [003] d... 27952.284639: p_hello_0x506: (0x400506)

FUNCTION 的位置顯示為 p_hello_0x506 可讀性不高, 我們可以修改一下 probe point 的定義讓它可讀性高些

# echo 0 >events/uprobes/enable
# echo "p:hello/hello1 $HOME/hello:0x506" >uprobe_events
# echo 1 >events/hello/enable

第二行我們定義了新的 group 叫 hello, 該 group 下有個叫 hello1 的 probe point, 所以第三行啟動 probe point 的地方就從 events/uprobes/enable 改成了 events/hello/enable.

清空 kernel ring buffer, 執行 hello, 取出 log

# echo >trace
# ~/hello 
1
v=2, s=foo
v=3, s=bar, (Member){60, John}
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-20183 [002] d... 28983.175175: hello1: (0x400506)

這樣可讀性就高多了.

接下來, 說明如何打印參數. Linux kernel document 中關於 uprobe 參數描述的語法如下, 後面會以範例說明之

  FETCHARGS     : Arguments. Each probe can have up to 128 args.
   %REG         : Fetch register REG
   @ADDR        : Fetch memory at ADDR (ADDR should be in userspace)
   @+OFFSET     : Fetch memory at OFFSET (OFFSET from same file as PATH)
   $stackN      : Fetch Nth entry of stack (N >= 0)
   $stack       : Fetch stack address.
   $retval      : Fetch return value.(*)
   +|-offs(FETCHARG) : Fetch memory at FETCHARG +|- offs address.(**)
   NAME=FETCHARG     : Set NAME as the argument name of FETCHARG.
   FETCHARG:TYPE     : Set TYPE as the type of FETCHARG. Currently, basic types
                       (u8/u16/u32/u64/s8/s16/s32/s64), "string" and bitfield
                       are supported.

  (*) only for return probe.
  (**) this is useful for fetching a field of data structures.

在不使用如 perf 之類的工具配合 debug information 的情況下使用 uprobe 基本寫出的腳本都會跟執行的平台相依, 這是要注意的一件事. 我們的範例平台是運行於 x86_64 之上的 Linux 環境, 根據文檔(或參考這頁)可以得知參數的傳遞, 前 6 個都是放在 register 之中, 超過的部份會放在 stack 之上. 會用到的 register 依序條列如下

  • arg1 - rdi
  • arg2 - rsi
  • arg3 - rdx
  • arg4 - r10
  • arg5 - r9
  • arg6 - r8

hello1 帶了一個參數, 會用到 rdi, 在 ftrace 中表示方式為 %di, 所以上面的命令修改如下

# echo 0 >events/hello/enable
# echo "p:hello/hello1 $HOME/hello:0x506 %di" >uprobe_events
# echo 1 >events/hello/enable
# echo >trace
# ~/hello 
1
v=2, s=foo
v=3, s=bar, (Member){60, John}
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-23624 [000] d... 30190.498636: hello1: (0x400506) arg1=0x1

嗯~ arg1=0x1 冒似正確. ftrace 還可以為參數命名 (以下省略停止/啟動的命令)

# echo "p:hello/hello1 $HOME/hello:0x506 v=%di" >uprobe_events
[...]
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-24103 [003] d... 30401.189468: hello1: (0x400506) v=0x1

接下來對 hello2 加上 probe point. hello2 有 2 個參數, 第二個參數類型為 C string (char *), 需要用到這個語法

   +|-offs(FETCHARG) : Fetch memory at FETCHARG +|- offs address.(**)

也就是 C 中對 pointer 的 dereference. hello2OFFSET 為 0x527, 增加 probe point 的命令修改如下

# echo "p:hello/hello2 $HOME/hello:0x527 v=%di s=+0(%si)" >uprobe_events
[...]
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-25758 [001] d... 31158.264845: hello2: (0x400527) v=0x2 s="foo"

這裡我們以第二個參數 (%si) 的值做為 address 加上 0 的 offset (為了滿足語法) 後對內存取值, 並增加了 :string 指定打印的方式為 string.

接著看第三個範例, hello3, OFFSET 為 0x550, 有 3 個參數. 第 3 個參數為 struct Member 的 pointer (置於 %dx 中), 會比較複雜些, 但 uprobe 還是能處理

# echo "p:hello/hello2 $HOME/hello:0x550 v=%di s=+0(%si) m_age=+0(%dx):u32 m_name=+0(+8(%dx)):string" >uprobe_events
[...]
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-27575 [002] d... 32031.990397: hello2: (0x400550) v=0x3 s=0x31b010000726162 m_age=0x3c m_name="John"

因為 struct Member 是以 pointer 的方式傳進 hello3 的, 所以也需要以 +|-offs(FETCHARGS) 的語法存取 memory 中的值. m->agestruct Member 中的 offset 為 0, 型態為 unsigned int, 所以指定了類型為 u32. 而 m->name 在 struct 中的 offset 為了對齊, 所以是 +8, 裡面放是的 C string 所在的 address, 所以需要再做一次 memory 的存取, 以取得 John. 以下小實驗在印出 m->name 時會少掉開頭的 J

# echo "p:hello/hello2 $HOME/hello:0x550 v=%di s=+0(%si) m_age=+0(%dx):u32 m_name=+1(+8(%dx)):string" >uprobe_events
[...]
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           hello-29366 [002] d... 32854.350597: hello2: (0x400550) v=0x3 s=0x31b010000726162 m_age=0x3c m_name="ohn"