Quickwords30：Use Both kprobe and uprobe At The Same Time

Posted on 本文总阅读量次

用ftrace可以观察内核方法的调用信息。用uprobe可以观察用户空间二进制可执行文件中方法的调用信息。奇怪的是当你想把两个合在一起用的时候，比如你想看到内核调度器调度到了你关心的用户进程，同时也想知道调度之后，该进程会执行哪个方法的时候，网络上我没有找到任何资料教你如何去做。按说这应该是一个对各类系统问题诊断很有用的能力。

也许是太简单了？下面用一个示例说明。

内核版本

1
2
uname -r
4.19.6-1.el7.elrepo.x86_64

有点新，不过不害事。

设置uprobe

设置uprobe的方法还是挺多的，我个人建议用perf设置算比较方便。硬核爱好者可以参考这篇：https://decodezp.github.io/2018/12/04/ftrace-uprobe/

看看有哪些能设置的点

perf probe -x /bin/bash -F
打印出来的是/bin/bash这个二进制文件中可以设置的trace point。

添加uprobe跟踪点

perf probe -x /bin/bash 'readline%return +0($retval):string'

readline是上面打印出来的trace point之一，后面的参数是打印该方法的返回值。在这里就是我们在bash中敲入的命令。

加入之后在cat /sys/kernel/debug/tracing/uprobe_events就能看到这个信息。

但这里能看到并不说明什么问题。此时会看到在

/sys/kernel/debug/tracing/events/probe_bash会多出一个事件。将这里面的enable echo成1。

其实这个时候就已经可以从trace中看到用户程序的追踪信息了。（前提是在bash中敲入了一些代码）

1
2
3
4
5
6
7
8
9
10
11
[root@bogon tracing]# cat trace | tail
  kworker/u256:2-3393  [000] d...  4537.944067: sched_stat_runtime: comm=kworker/u256:2 pid=3393 runtime=1557 [ns] vruntime=11510909796 [ns]
  kworker/u256:2-3393  [000] d...  4537.944067: sched_switch: prev_comm=kworker/u256:2 prev_pid=3393 prev_prio=120 prev_state=R+ ==> next_comm=sshd next_pid=1645 next_prio=120
            sshd-1645  [000] d...  4537.944188: sched_stat_runtime: comm=sshd pid=1645 runtime=121420 [ns] vruntime=1187191909 [ns]
            sshd-1645  [000] d...  4537.944191: sched_switch: prev_comm=sshd prev_pid=1645 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120
            bash-1649  [003] d.h.  4537.944987: sched_stat_runtime: comm=bash pid=1649 runtime=991600 [ns] vruntime=9501612170 [ns]
            bash-4920  [001] d...  9557.263762: readline: (0x41e6ea <- 0x48aaf0) arg1="cd .."
            bash-4920  [001] d...  9557.806689: readline: (0x41e6ea <- 0x48aaf0) arg1="ls"
            bash-4920  [001] d...  9558.865593: readline: (0x41e6ea <- 0x48aaf0) arg1="cd .."
            bash-4920  [001] d...  9559.230347: readline: (0x41e6ea <- 0x48aaf0) arg1="ls"
            bash-4920  [001] d...  9562.364085: readline: (0x41e6ea <- 0x48aaf0) arg1="cat trace | tail"

设置kprobe

这个比较简单，设置一下enable就行。我们这里只打开sched相关的事件。

echo 1 > /sys/kernel/debug/tracing/events/sched/enable

观察trace结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
cat trace | grep -C 2 readline
kworker/u256:2-3393  [002] d...  4510.436525: sched_switch: prev_comm=kworker/u256:2 prev_pid=3393 prev_prio=120 prev_state=R+ ==> next_comm=swapper/2 next_pid=0 next_prio=120
            bash-1649  [000] d.h.  4510.436528: sched_wakeup: comm=sshd pid=1645 prio=120 target_cpu=000
            bash-1649  [000] d...  4510.436601: readline: (0x41e6ea <- 0x48aaf0) arg1="cat enable "
            bash-1649  [000] d...  4510.436661: sched_stat_runtime: comm=bash pid=1649 runtime=220718 [ns] vruntime=8123222027 [ns]
            bash-1649  [000] ....  4510.436738: sched_process_fork: comm=bash pid=1649 child_comm=bash child_pid=4348
--
            bash-1649  [000] d...  4510.844339: sched_waking: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4510.844340: sched_wakeup: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4510.844421: readline: (0x41e6ea <- 0x48aaf0) arg1="ls"
            bash-1649  [000] d...  4510.844476: sched_stat_runtime: comm=bash pid=1649 runtime=148935 [ns] vruntime=8124989109 [ns]
            bash-1649  [000] ....  4510.844549: sched_process_fork: comm=bash pid=1649 child_comm=bash child_pid=4354
--
            bash-1649  [000] d...  4515.309199: sched_waking: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4515.309200: sched_wakeup: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4515.309271: readline: (0x41e6ea <- 0x48aaf0) arg1="cd probe_bash/"
            bash-1649  [000] d...  4515.309421: sched_stat_runtime: comm=bash pid=1649 runtime=243557 [ns] vruntime=8128041748 [ns]
            bash-1649  [000] ....  4515.309492: sched_process_fork: comm=bash pid=1649 child_comm=bash child_pid=4361
--
            bash-1649  [000] d...  4515.795429: sched_waking: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4515.795430: sched_wakeup: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [000] d...  4515.795500: readline: (0x41e6ea <- 0x48aaf0) arg1="ls"
            bash-1649  [000] d...  4515.795555: sched_stat_runtime: comm=bash pid=1649 runtime=138497 [ns] vruntime=8128576492 [ns]
            bash-1649  [000] ....  4515.795628: sched_process_fork: comm=bash pid=1649 child_comm=bash child_pid=4366
--
  kworker/u256:2-3393  [000] d...  4517.849441: sched_stat_runtime: comm=kworker/u256:2 pid=3393 runtime=1579 [ns] vruntime=11405903803 [ns]
  kworker/u256:2-3393  [000] d...  4517.849441: sched_switch: prev_comm=kworker/u256:2 prev_pid=3393 prev_prio=120 prev_state=R+ ==> next_comm=sshd next_pid=1645 next_prio=120
            bash-1649  [001] d...  4517.849473: readline: (0x41e6ea <- 0x48aaf0) arg1="cat enable "
            bash-1649  [001] d...  4517.849531: sched_stat_runtime: comm=bash pid=1649 runtime=160328 [ns] vruntime=10110004768 [ns]
            sshd-1645  [000] d...  4517.849543: sched_stat_runtime: comm=sshd pid=1645 runtime=101818 [ns] vruntime=1177932308 [ns]
--
  kworker/u256:2-3393  [000] d...  4518.326292: sched_stat_runtime: comm=kworker/u256:2 pid=3393 runtime=1559 [ns] vruntime=11405998988 [ns]
  kworker/u256:2-3393  [000] d...  4518.326293: sched_switch: prev_comm=kworker/u256:2 prev_pid=3393 prev_prio=120 prev_state=R+ ==> next_comm=sshd next_pid=1645 next_prio=120
            bash-1649  [001] d...  4518.326323: readline: (0x41e6ea <- 0x48aaf0) arg1="ls"
            bash-1649  [001] d...  4518.326377: sched_stat_runtime: comm=bash pid=1649 runtime=155566 [ns] vruntime=10126596805 [ns]
            sshd-1645  [000] d...  4518.326390: sched_stat_runtime: comm=sshd pid=1645 runtime=97022 [ns] vruntime=1178607048 [ns]
--
          <idle>-0     [001] d...  4525.694161: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1649 next_prio=120
            bash-1649  [001] d...  4525.694175: sched_waking: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [001] d...  4525.694257: readline: (0x41e6ea <- 0x48aaf0) arg1="echo "0" > enable"
          <idle>-0     [000] dNh.  4525.694323: sched_wakeup: comm=kworker/u256:2 pid=3393 prio=120 target_cpu=000
            bash-1649  [001] d...  4525.694327: sched_stat_runtime: comm=bash pid=1649 runtime=168870 [ns] vruntime=10131670237 [ns]

OK，此时就可以同时追踪kproble和uprobe了。

tech
© 2020 DecodeZ All Rights Reserved. 本站访客数人次 本站总访问量次
Theme by hiero