测来测去17：Adding dynamic probe to gain insight of DPDK application

Dynamic Trace Framework

曾经想给DPDK添加一个trace framework，但使用的方法是添加一个专门的rte_trace库，涉及一整套trace buffer和控制相关的操作，同时需要修改原本DPDK应用的代码，使用起来成本还是比较高的。在逐渐熟悉了uprobe的操作之后，其实可以用uprobe完成绝大部分这个trace framework所做的工作，例如方法执行时间戳、方法参数、返回值、内部变量值的记录工作，并且有性能开销方面的保障。

l3fwd

这里就用DPDK自带的l3fwd程序作一个简单的使用示例。

我们的目的是追踪l3fwd中l3fwd_lpm_send_packets这个方法的调用情况。这个方法是在l3fwd收到数据包之后处理转发的时候调用的。

先用perf检查一下编译出来的二进制文件中包含该方法：

perf probe -F -x ./l3fwd | grep lpm_send_packets

我们看一下这个方法的的原型：

static inline void
l3fwd_lpm_send_packets(int nb_rx, struct rte_mbuf **pkts_burst,
                    uint8_t portid, struct lcore_conf *qconf)

也就是不带返回值，然后4个参数。

然后添加一个新的uprobe

perf probe -x ./l3fwd 'l3fwd_lpm_send_packets %di %si %dx %cx'

后面%di %si %dx %cx对应x86_64架构中函数的4个参数寄存器。详见下图：

OK， 这个时候应该可以在/sys/kernel/debug/tracing/events路径下面看到一个叫probe_l3fwd的文件夹了，进去之后echo 1 > enable就算准备完毕。

启动l3fwd:

./l3fwd -c 0x1ffff -- -p 0x3 -P --config="(0,0,1),(0,1,2),(0,2,3),(1,0,4),(1,1,5),(1,2,6)"

查看结果

首先给l3fwd发几个包，用scapy一个一个发就可以。然后

cat /sys/kernel/debug/tracing/trace

就可以看到如下结果：

# tracer: nop
#
# entries-in-buffer/entries-written: 11/11   #P:36
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-105187 [003] d... 9864775.255783: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f728add44b0 arg3=0x0 arg4=0x1407140
           <...>-106508 [003] d... 9864984.831907: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f8f219dc4b0 arg3=0x0 arg4=0x1407140
           <...>-106508 [003] d... 9865065.328194: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f8f219dc4b0 arg3=0x0 arg4=0x1407140
           <...>-106508 [003] d... 9865121.933159: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f8f219dc4b0 arg3=0x0 arg4=0x1407140
           <...>-106508 [003] d... 9865318.618119: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f8f219dc4b0 arg3=0x0 arg4=0x1407140
           <...>-106508 [003] d... 9865340.393096: l3fwd_lpm_send_packets: (0x464f42) arg1=0x1 arg2=0x7f8f219dc4b0 arg3=0x0 arg4=0x1407140

这是发了6个packet之后的结果，这里面给出了每次该方法调用的时间戳、执行CPU序号、以及每次执行时4个参数的值。

核对结果

那么这些值都对不对呢？为了验证可以用gdb attach上去看一下：

gdb attachpidof l3fwd

在l3fwd_lpm_send_packets处设置一个断点：

b /root/dpdk-stable-18.05.1/examples/l3fwd-fdir/l3fwd_lpm.c:243

然后继续continue，发送一个数据包，查看当前变量的值：

(gdb) info locals
pkts_burst = {0x7f8739502e40, 0x2, 0x7f8f219dd770, 0x7f8f23d4b757 <__memmove_ssse3+3895>, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x11, 0x2, 0x452330 <rte_log+138>, 
  0x0, 0x3000000018, 0x7f8f219dc610, 0x7f8f219dc550, 0x0, 0x4e1a46 <eal_thread_dump_affinity+262>, 0x4, 0x2, 0x219de700, 0x7f8f219dc630, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}
lcore_id = 2
prev_tsc = 22639728109674980
diff_tsc = 28037
cur_tsc = 22639728109703017
i = 1
***nb_rx = 1***
***portid = 0***
queueid = 2 '\002'
***qconf = 0x1407140 <lcore_conf+19456>***
drain_tsc = 230000

这里可以看到nb_rx = 1，与trace中第一个参数的值相同，portid = 0与trace中第三个参数的值相同，qconf = 0x1407140与trace中第四个参数的值相同。queueid虽然在参数中没有体现，但根据我们的设置，port0的第二个rx queue由CPU3负责轮询，可以从trace中CPU的信息中对应上。

如果在gdb中打印pkts_burst的地址：

p &pkts_burst

$1 = (struct rte_mbuf *(*)[32]) 0x7f8f219dc4b0

也可以对应起来。

实际上queueid可以通过对qconf做偏移取得。但我的机器似乎内核版本较低（需要大于3.14)，暂时无法提供。方法也很简单就是+8(%cx)，表示往后偏移8个字节。

通过这些数据，完全可以计算出l3fwd这个应用转发速率是多少，每个队列的速率是多少，平均一次收多少包，没有收到包的轮询比例有多少等所有信息。

也可以看一些内部变量的情况，前提是编译器没给你优化掉，这个后面再介绍。

如果可以预置一些此类探针，或者制作一个方便添加/删除的框架，应当可以在多个方面帮助用户。