ext4slower会跟踪ext4的读，写，打开和fsyncs操作，并在超过阈值后打印信息。

对于识别或排除性能问题非常有用：通过文件系统显示独立的慢速磁盘I/O。由于磁盘处理I/O是异步的，因此很难将该层的延迟与应用程序的延迟联系起来。使用本工具，可以在 VFS -> 文件系统接口层面进行跟踪，将更接近应用的问题所在。

$ ./ext4slower 1
Tracing ext4 operations slower than 1 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
06:35:01 cron           16464  R 1249    0          16.05 common-auth
06:35:01 cron           16463  R 1249    0          16.04 common-auth
06:35:01 cron           16465  R 1249    0          16.03 common-auth
06:35:01 cron           16465  R 4096    0          10.62 login.defs

延迟的评估从发起VFS接口到文件系统的操作开始，到该操作结束为止。中间包括多个过程：块设备I/O，系统cpu周期，文件系统锁，运行队列延迟等。相比评估块设备接口的延迟更加合理。

注：本工具仅会跟踪前面列出的通用的文件系统操作，不包含其他文件系统操作(如inode操作)。

类似的用于其他系统的工具还有btrfsslower,xfsslower,和zfsslower。此外还有fileslower命令，用于跟踪基于文件的同步读写。

默认显示慢于10ms的I/O操作。

更多用法参见example。

biolatency

biolatency会跟踪块设备的I/O延迟，并以直方图显示延迟分布，相比iostat给出的平均延迟更加直观。

# ./biolatency
Tracing block device I/O... Hit Ctrl-C to end.
     usecs           : count     distribution
       0 -> 1        : 0        |                                      |
       2 -> 3        : 0        |                                      |
       4 -> 7        : 0        |                                      |
       8 -> 15       : 0        |                                      |
      16 -> 31       : 0        |                                      |
      32 -> 63       : 0        |                                      |
      64 -> 127      : 1        |                                      |
     128 -> 255      : 12       |********                              |
     256 -> 511      : 15       |**********                            |
     512 -> 1023     : 43       |*******************************       |
    1024 -> 2047     : 52       |**************************************|
    2048 -> 4095     : 47       |**********************************    |
    4096 -> 8191     : 52       |**************************************|
    8192 -> 16383    : 36       |**************************            |
   16384 -> 32767    : 15       |**********                            |
   32768 -> 65535    : 2        |*                                     |
   65536 -> 131071   : 2        |*                                     |

上面展示了从128微秒到32767微秒之间的I/O延迟分布，最高的延迟为65毫秒到131毫秒之间的2个IO

examples:
    ./biolatency            # summarize block I/O latency as a histogram
    ./biolatency 1 10       # print 1 second summaries,10 times
    ./biolatency -mT 1      # 1s summaries,milliseconds,and timestamps
    ./biolatency -Q         # include OS queued time in I/O time
    ./biolatency -D         # show each disk device separately
    ./biolatency -F         # show I/O flags separately

更多用法参见example。

biosnoop

biosnoop跟踪每个块设备的I/O，并打印每个I/O的延迟。

$ ./biosnoop
TIME(s)     COMM           PID    DISK    T SECTOR     BYTES  LAT(ms)
0.000000    jbd2/vda1-8    301    vda     W 17073104   40960     0.65
0.000479    jbd2/vda1-8    301    vda     W 17073184   4096      0.42
3.071857    kworker/u4:0   17124  vda     W 2048       12288     0.51
3.071927    kworker/u4:0   17124  vda     W 4196360    4096      0.57

使用时可以结合biolatency，首先使用biolatency -D找出延迟大的磁盘，然后使用biosnoop找出导致延迟的进程。

更多用法参见example。

cachestat

cachestat每秒会打印文件系统cache的概要信息。使用该工具可以定位低缓存命中率和高miss率。

$ ./cachestat.py
    HITS   MISSES  DIRTIES HITRATIO   BUFFERS_MB  CACHED_MB
       1        0        0  100.00%            5        191
     198    12136        0    1.61%            5        238
       1    11007        3    0.01%            5        281
       0     6384        0    0.00%            5        306
       1    14464        0    0.01%            5        363
       0    11776        0    0.00%            5        409
       1    11712        0    0.01%            5        454
      32    13184        0    0.24%            5        506
       0    11232        0    0.00%            5        550
       1    13056        0    0.01%            5        601
      16    14720        0    0.11%            5        658
      33     9920        0    0.33%            5        697
       0    13248        0    0.00%            5        749
       4    14144        0    0.03%            5        804
       0     9728        0    0.00%            5        842
       1    10816        0    0.01%            5        885
     808    13504        1    5.65%            5        938
       0    11409        0    0.00%            5        982
       0    11520        0    0.00%            5       1027
       0    15616        0    0.00%            5       1088
       1     9792        0    0.01%            5       1126
       0     8256        0    0.00%            5       1158
       1     9600        0    0.01%            5       1196
     599     4804        0   11.09%            5       1215
       1        0        0  100.00%            5       1215
       0        0        0    0.00%            5       1215
       3        1        0   75.00%            5       1215
   79536       34        0   99.96%            5       1215
   87693      274        4   99.69%            6       1214
   89018     3546        0   96.17%            7       1227
   33531      201        4   99.40%            7       1228
      22       44        0   33.33%            8       1228
       0        0        0    0.00%            8       1228
      73       21        2   77.66%            8       1228

上述首次花费了24s来读取1GB的文件，体现为高MISSES ，低HITRATIO；第二次读取时仅花费了4s，HITRATIO接近99%。HITRATIO=HITS/(HITS+MISSES)

tcpconnect+tcpaccept+tcpretrans

推荐使用ss命令查看，ss -i可以看到重传信息。

runqlat

以直方图的方式显示cpu run队列中的现存等待的时间。用于评估在cpu饱和时等待的时长。

$ ./runqlat -p 980 -L
Tracing run queue latency... Hit Ctrl-C to end.
^C

tid = 1054
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 5        |****************************************|
         8 -> 15         : 1        |********                                |

tid = 1055
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 3        |****************************************|
         4 -> 7          : 2        |**************************              |
         8 -> 15         : 1        |*************                           |
...

上面展示了进程980中的线程的等待时长的分布情况。进程等待时间过程可能是被其他cpu密集型任务占用了cpu。

examples:
    ./runqlat            # summarize run queue latency as a histogram
    ./runqlat 1 10       # print 1 second summaries,10 times
    ./runqlat -mT 1      # 1s summaries,and timestamps
    ./runqlat -P         # show each PID separately
    ./runqlat -p 185     # trace PID 185 only

profile

推荐使用strace和perf trace命令

BCC的开发

本节介绍使用Python接口进行BCC的开发，包括两部分：可观测性和网络。

可观测性

Lesson 1. Hello World

执行examples/hello_world.py，并在另一个会话中执行一些命令(如ls)，此时会打印"Hello,World!".

# ./examples/hello_world.py
            bash-13364 [002] d... 24573433.052937: : Hello,World!
            bash-13364 [003] d... 24573436.642808: : Hello,World!
[...]

hello_world.py中的代码如下：

from bcc import BPF
BPF(text='int kprobe__sys_clone(void *ctx) { bpf_trace_printk("Hello,World!\\n"); return 0; }').trace_print()

包含如下6个内容：

1. text='...': 定义了一个使用C编写的内联的BPF程序。
2. kprobe__sys_clone(): 这是通过kprobes对内核进行动态跟踪的一种捷径。如果C函数以kprobe__开头，剩下的部分将作为内核函数名来处理，本例为sys_clone()，
3. void *ctx: ctx包含参数，但鉴于此处没有使用，因此将其强转为void *
4. bpf_trace_printk(): 将printf()输出到通用的trace_pipe (/sys/kernel/debug/tracing/trace_pipe)的一个简单内核工具。该函数对于一些场景是合适的，但也有限制：最多3个参数，仅有一个%s，且trace_pipe是全局共享的，因此并行的程序会导致输出混乱。最好采用BPF_PERF_OUTPUT()接口，后续会介绍。
5. return 0; kprobe__sys_clone函数的出参类型为int，必须返回一个值。
6. .trace_print(): 一个bcc例程，从trace_pipe中读取，并打印输出。

Lesson 2. sys_sync()

尝试将跟踪的系统调用改为sys_sync()，当执行sync命令时会输出"sys_sync() called"

#!/usr/bin/python
from bcc import BPF
BPF(text='int kprobe__sys_sync(void *ctx) { bpf_trace_printk("sys_sync() called!\\n"); return 0; }').trace_print()

Lesson 3. hello_fields.py

文件路径为examples/tracing/hello_fields.py。运行时的输出如下：

$ ./hello_fields.py
TIME(s)            COMM             PID    MESSAGE
546.560775000      bash             1150   Hello,World!
547.127956000      bash             1150   Hello,World!

源码如下：

from bcc import BPF

# define BPF program
prog = """
int hello(void *ctx) {
    bpf_trace_printk("Hello,World!\\n");
    return 0;
}
"""

# load BPF program
b = BPF(text=prog)
b.attach_kprobe(event=b.get_syscall_fnname("clone"),fn_name="hello")

# header
print("%-18s %-16s %-6s %s" % ("TIME(s)","COMM","PID","MESSAGE"))

# format output
while 1:
    try:
        (task,pid,cpu,flags,ts,msg) = b.trace_fields()
    except ValueError:
        continue
    print("%-18.9f %-16s %-6d %s" % (ts,task,msg))

内容与hello_world.py类似，通过sys_clone()跟踪新的进程，但增加了新的内容：

1. prog =: 将C程序定义为一个变量，后面会引用它，便于使用命令行参数时进行字符串替换。
2. hello(): 此处定义了一个C函数，而没有直接使用kprobe__开头的系统调用，后续会引用它。定义在BPF程序中的C函数将会运行在一个probe上，这些函数都使用pt_reg* ctx作为第一个参数。如果需要定义一些不在probe上执行的辅助函数，则需要将这些函数定义为static inline，以便编译器进行内联，有时还需要向其添加_always_inline function属性。
3. b.attach_kprobe(event=b.get_syscall_fnname("clone"),fn_name="hello"):为内核clone系统调用函数创建一个kprobe，该kprobe会执行自定义的hello()函数。可以通过多次执行attach_kprobe() ，将自定义的C函数附加到多个内核函数上。
4. b.trace_fields():从trace_pipe返回固定的字段集，与trace_print()类似，对黑客来说很方便，但实际作为工具时，推荐使用BPF_PERF_OUTPUT()。

Lesson 4. sync_timing.py

还记得系统管理员在重启前在一个慢控制台上输入sync三次的日子吗，这些操作是为了给第一个异步sync完成的时间？有人认为直接执行一行代码sync;sync;sync更加便利，这种方式后来成为了行业惯例，尽管它违背了最初的目的。此时sync变成了同步执行的指令，这看起来很愚蠢。

下面例子展示了do_sync函数被调用的速度，并打印输出(如果最近调用的时间超过一秒钟)，sync;sync;sync会打印输出第二次和第三次sync。

# ./examples/tracing/sync_timing.py
Tracing for quick sync's... Ctrl-C to end
At time 0.00 s: multiple syncs detected,last 95 ms ago
At time 0.10 s: multiple syncs detected,last 96 ms ago

代码来自 examples/tracing/sync_timing.py。

from __future__ import print_function
from bcc import BPF

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>

BPF_HASH(last); #初始化一个哈希，用于保存时间，一个哈希可以保存多个key/value对，使用items()进行迭代

int do_trace(struct pt_regs *ctx) {
    u64 ts,*tsp,delta,key = 0;

    // attempt to read stored timestamp
    tsp = last.lookup(&key); //查找是否存在key，哈希在保存时采纳的时key的值，而不是key的地址，因此要保证key的值是唯一的
    if (tsp != NULL) {
        delta = bpf_ktime_get_ns() - *tsp;// 打印两次调用之间的时间差，纳秒
        if (delta < 1000000000) {
            // output if time is less than 1 second
            bpf_trace_printk("%d\\n",delta / 1000000);
        }
        last.delete(&key);
    }

    // update stored timestamp
    ts = bpf_ktime_get_ns(); //将当前时间保存到键为key的hash中
    last.update(&key,&ts);
    return 0;
}
""")

b.attach_kprobe(event=b.get_syscall_fnname("sync"),fn_name="do_trace")#追踪sync命令
print("Tracing for quick sync's... Ctrl-C to end")

# format output
start = 0
while 1:
    (task,ms) = b.trace_fields()
    if start == 0:
        start = ts
    ts = ts - start
    print("At time %.2f s: multiple syncs detected,last %s ms ago" % (ts,ms))

内容包括：

1. bpf_ktime_get_ns(): 返回纳秒为单位的时间
2. BPF_HASH(last):创建一个hash（关联数组）的BPF map对象，称为”last“，由于没有进一步指定任何参数，因此默认为u64类型的key和value。
3. key = 0:只在该hash中存储一个key/value对，其中key为零。
4. last.lookup(&key): 在hash中查找key，如果存在，则返回对应的值，否则返回NULL。上面将key作为指向指针的地址传入。
5. if (tsp != NULL) {: 校验指针是否为空，如果不为空，则表示该函数并非首次调用，可以计算两次调用的时间差
6. last.delete(&key):删除键，原因是内核的.update()存在的bug。
7. last.update(&key,&ts):将第二个参数表示的时间值保存到键为key的hash中，覆盖之前的数值。

Lesson 5. sync_count.py

修改sync_timing.py程序，保存所有sync系统调用的次数，并打印输出，修改如下(注意运行不能带中文字符)：

#!/usr/bin/python

from __future__ import print_function
from bcc import BPF

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>

BPF_HASH(last);
BPF_HASH(count); //创建一个新的count

int do_trace(struct pt_regs *ctx) {
    u64 curct=1,key = 0,key1 = 1;
    u64 *ctp;

    // attempt to read stored timestamp
    tsp = last.lookup(&key);
    ctp = count.lookup(&key1); //获取保存的地址，一个key对应一个变量地址
    if (NULL != ctp){          //如果存在则累加，并更新
        curct = *ctp+1;   //注意：此处不能使用*curct++，可能是因为内核数据的原因，只能通过count.update更新
		count.update(&key1,&curct); 
    }else{
		count.update(&key1,&curct);//如果不存在直接保存当前值1
    }

    if (tsp != NULL) {
        delta = bpf_ktime_get_ns() - *tsp;
        if (delta < 1000000000) {
            // output if time is less than 1 second
            bpf_trace_printk("count:%d,%d\\n",curct,delta / 1000000); //打印count
        }
        last.delete(&key);
    }

    // update stored timestamp
    ts = bpf_ktime_get_ns();
    last.update(&key,fn_name="do_trace")
print("Tracing for quick sync's... Ctrl-C to end")

# format output
start = 0
while 1:
    (task,ms))

输出结果如下：

Tracing for quick sync's... Ctrl-C to end
At time 0.00 s: multiple syncs detected,last count:2,3 ms ago
At time 0.00 s: multiple syncs detected,last count:3,0 ms ago
At time 0.41 s: multiple syncs detected,last count:4,413 ms ago
At time 0.42 s: multiple syncs detected,last count:5,2 ms ago
At time 0.42 s: multiple syncs detected,last count:6,0 ms ago

Lesson 6. disksnoop.py

执行examples/tracing/disksnoop.py ，部分输出结果如下：

$ ./disksnoop.py
TIME(s)            T  BYTES    LAT(ms)
4011.638426000     W  65536       1.01
4011.638754000     W  65536       1.33
4011.639049000     W  65536       1.62
4011.639490000     W  65536       2.06
4011.639511000     W  65536       2.08
4011.639750000     W  65536       2.32

代码为：

[...]
REQ_WRITE = 1		# from include/linux/blk_types.h

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/blkdev.h>

BPF_HASH(start,struct request *); //此处的value为一个指针。由于trace_start和trace_completion中的入参req其实是同一个地址，因此此处可以使用指针

void trace_start(struct pt_regs *ctx,struct request *req) {
	// stash start timestamp by request ptr
	u64 ts = bpf_ktime_get_ns();

	start.update(&req,&ts); //使用req的地址作为key
}

void trace_completion(struct pt_regs *ctx,struct request *req) {
	u64 *tsp,delta;

	tsp = start.lookup(&req);
	if (tsp != 0) {
		delta = bpf_ktime_get_ns() - *tsp;
		bpf_trace_printk("%d %x %d\\n",req->__data_len,req->cmd_flags,delta / 1000);
		start.delete(&req);
	}
}
""")

b.attach_kprobe(event="blk_start_request",fn_name="trace_start")
b.attach_kprobe(event="blk_mq_start_request",fn_name="trace_start")
b.attach_kprobe(event="blk_account_io_completion",fn_name="trace_completion")
[...]

包含内容：

1. REQ_WRITE：此处在python程序中定义了一个内核常量，该变量来自include/linux/blk_types.h，可以直接使用
2. trace_start(struct pt_regs *ctx,struct request *req)：该函数后续会添加到kprobes中。第一个参数struct pt_regs *ctx用于通过kprpbe函数注册BPF上下文，第二个参数才是给该函数的参数。此处将该函数附加到blk_start_request上，其首个参数类型为struct request *。
3. start.update(&req,&ts): 使用指向request结构体的指针作为hash的key，使用指向结构体的指针作为key是个不错的选择，因为指针的地址是唯一的(需要注意释放和重用场景)。此处是给描述磁盘I/O的request结构体打上时间标签。还有两个常用的键用于存储时间戳：指向结构体的指针和线程ID。
4. req->__data_len:此处访问了struct request的成员，可以在内核源代码中查看它的定义，并了解其中有哪些成员。bcc实际上会将这些表达重写为一系列的bpf_probe_read_kernel()调用，有时bcc无法处理复杂的引用，此时需要直接调用bpf_probe_read_kernel()

注：上述程序使用trace_start和trace_completion对访问磁盘的操作进行打点，blk_start_request，blk_mq_start_request和blk_account_io_completion都是内核函数，具体实现可以在linux源码中找到，对函数的描述如下(来自内核v5.7.7版本)：

/**
 * blk_mq_start_request - Start processing a request
 * @rq: Pointer to request to be started
 *
 * Function used by device drivers to notify the block layer that a request
 * is going to be processed now,so blk layer can do proper initializations
 * such as starting the timeout timer.
 */
 
 /**
 * blk_mq_complete_request - end I/O on a request
 * @rq:		the request being processed
 *
 * Description:
 *	Ends all I/O on a request. It does not handle partial completions.
 *	The actual completion happens out-of-order,through a IPI handler.
 **/

在内核5.7.7版本中已经不存在blk_start_request函数，因此在最新的bcc 0.1.10版本中上述程序修改为：

if BPF.get_kprobe_functions(b'blk_start_request'): #首先验证该内核函数是否存在
    b.attach_kprobe(event="blk_start_request",fn_name="trace_completion")

bcc使用get_kprobe_functions函数校验内涵函数是否存在，可以看到是在/proc/kallsyms中进行检查的，/proc/kallsyms保存了Linux内核符号表。

Lesson 7. hello_perf_output.py

最后使用bpf_trace_printk()和BPF_PERF_OUTPUT()接口，这也意味着将不再使用trace_field()获取如PID和时间戳等信息。

执行examples/tracing/hello_perf_output.py的结果如下：

# ./hello_perf_output.py
TIME(s)            COMM             PID    MESSAGE
0.000000000        bash             22986  Hello,perf_output!
0.021080275        systemd-udevd    484    Hello,perf_output!
0.021359520        systemd-udevd    484    Hello,perf_output!
0.021590610        systemd-udevd    484    Hello,perf_output!
[...]

代码如下：

from bcc import BPF

# define BPF program
prog = """
#include <linux/sched.h>

// define output data structure in C
struct data_t {
    u32 pid;
    u64 ts;
    char comm[TASK_COMM_LEN];
};
BPF_PERF_OUTPUT(events);

int hello(struct pt_regs *ctx) {
    struct data_t data = {};

    data.pid = bpf_get_current_pid_tgid(); //获取执行该命令的进程ID
    data.ts = bpf_ktime_get_ns();
    bpf_get_current_comm(&data.comm,sizeof(data.comm));

    events.perf_submit(ctx,&data,sizeof(data));

    return 0;
}
"""

# load BPF program
b = BPF(text=prog)
b.attach_kprobe(event=b.get_syscall_fnname("clone"),"MESSAGE"))

# process event
start = 0
def print_event(cpu,data,size):
    global start
    event = b["events"].event(data)
    if start == 0:
            start = event.ts
    time_s = (float(event.ts - start)) / 1000000000
    print("%-18.9f %-16s %-6d %s" % (time_s,event.comm,event.pid,"Hello,perf_output!"))

# loop with callback to print_event
b["events"].open_perf_buffer(print_event)
while 1:
    b.perf_buffer_poll()

需要掌握的内容为：

1. struct data_t: 定义了将数据从内核空间传递到用户空间的C结构体
2. BPF_PERF_OUTPUT(events): 将输出channel命名为"events"
3. struct data_t data = {};: 创建一个空的data_t结构体
4. bpf_get_current_pid_tgid(): 获取低32为的进程ID(内核角度的PID，在用户空间体现为线程ID)，线程组ID和高32位(在用户空间体现为PID)。保存低32位的内容，并丢弃高32位的内容。那么应该呈现的是PID还是TGID？对于一个多线程app，其TGID是相同的，因此需要使用PID来进行区分。
5. bpf_get_current_comm(): 用当前进程名填充第一个参数地址。在上述例子中打点的系统调用位"clone"，在执行clone时会填充clone的进程的PID，时间戳和进程名，因此进程名和PID是一致的。
6. events.perf_submit():通过一个perf ring buffer将事件交给用户空间。
7. def print_event(): 定义一个Python函数，用于从事件流中处理事件
8. b["events"].event(data): 通过C声明自动将事件转为为Python对象
9. b["events"].open_perf_buffer(print_event): 将Python的print_event与事件流关联起来。
10. while 1: b.perf_buffer_poll():阻塞等待事件

Lesson 8. sync_perf_output.py

重新修改前面的sync_timing.py，使用BPF_PERF_OUTPUT进行输出：

#!/usr/bin/python
#
# sync_timing.py    Trace time between syncs.
#                   For Linux,uses BCC,eBPF. Embedded C.
#
# Written as a basic example of tracing time between events.
#
# Copyright 2016 Netflix,Inc.
# Licensed under the Apache License,Version 2.0 (the "License")

from __future__ import print_function
from bcc import BPF
from bcc.utils import printb

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>

BPF_HASH(last);

struct data_t {
    u64 cur_ts;
	u64 diff_ts;
};

BPF_PERF_OUTPUT(events);

int do_trace(struct pt_regs *ctx) {
    u64 ts,key = 0;
    struct data_t data = {}; 
    // attempt to read stored timestamp
    tsp = last.lookup(&key);
    if (tsp != NULL) {
	    data.cur_ts = bpf_ktime_get_ns() / 1000000000;
	    data.diff_ts = bpf_ktime_get_ns() - *tsp;
        if (data.diff_ts < 1000000000) {
            // output if time is less than 1 second
            events.perf_submit(ctx,sizeof(data));
        }
        last.delete(&key);
    }

    // update stored timestamp
    ts = bpf_ktime_get_ns();
    last.update(&key,fn_name="do_trace")
print("Tracing for quick sync's... Ctrl-C to end")

# format output
start = 0
def print_event(cpu,size):
    global start
    event = b["events"].event(data)
    if start == 0:
        start = event.cur_ts
    ts = event.cur_ts - start
    printb(b"At time %.2f s: multiple syncs detected,event.diff_ts / 1000000))

# loop with callback to print_event
b["events"].open_perf_buffer(print_event)

while 1:
    b.perf_buffer_poll()

Lesson 9. bitehist.py

examples/tracing/bitehist.py程序直方图记录了磁盘I/O的大小:

# ./bitehist.py
Tracing... Hit Ctrl-C to end.
^C
     kbytes          : count     distribution
       0 -> 1        : 3        |                                      |
       2 -> 3        : 0        |                                      |
       4 -> 7        : 211      |**********                            |
       8 -> 15       : 0        |                                      |
      16 -> 31       : 0        |                                      |
      32 -> 63       : 0        |                                      |
      64 -> 127      : 1        |                                      |
     128 -> 255      : 800      |**************************************|

代码如下：

from __future__ import print_function
from bcc import BPF
from time import sleep

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/blkdev.h>

BPF_HISTOGRAM(dist); //定义一个直方图，名为dist

int kprobe__blk_account_io_completion(struct pt_regs *ctx,struct request *req)
{
	dist.increment(bpf_log2l(req->__data_len / 1024)); //增加直方图的计数，key为bpf_log2l(req->__data_len / 1024)
	return 0;
}
""")

# header
print("Tracing... Hit Ctrl-C to end.")

# trace until Ctrl-C
try:
	sleep(99999999)
except KeyboardInterrupt:
	print()

# output
b["dist"].print_log2_hist("kbytes") #打印直方图

回顾之前的内容：

• kprobe__: 以该前缀开头的函数将会被认为是一个内核函数名，并使用kprobe进行检测，相当于直接对内核函数进行检测。第一个参数总是struct pt_regs *，其余的参数为内核函数的入参，如果不使用，则可以忽略。其与使用BPF.attach_kprobe()的方式是相同的。
• struct pt_regs *ctx,struct request *req: 给kprobe传参，ctx用于寄存器和BPF上下文，req为传递给被检测函数blk_account_io_completion()的第一个参数。
• req->__data_len: 获取该成员的值。

新的内容为：

• BPF_HISTOGRAM(dist): 定义一个BPF map对象，为直方图，名称为"dist"
• dist.increment():增加直方图bucket的索引，默认每次增加1，可以使用第二个参数自定义增量。
• bpf_log2l(): 对提供的值进行log-2计算，作为直方图的索引，构造二次幂直方图。
• b["dist"].print_log2_hist("kbytes"): 以二次幂直方图的方式打印"dist"，列标题为"kbytes"。从内核空间传递到用户空间的唯一数据是bucket计数，这样更加高效。

Lesson 10. disklatency.py

编写一个程序计算磁盘I/O时间，并打印延迟的直方图。可以在前面的disksnoop.py中找到磁盘I/O检测和计时的方式，直方图的代码可以参考bitehist.py。

#!/usr/bin/python

from __future__ import print_function
from bcc import BPF
from time import sleep

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/blkdev.h>

BPF_HISTOGRAM(dist);
BPF_HASH(start,struct request *);

void trace_start(struct pt_regs *ctx,struct request *req) {
    // stash start timestamp by request ptr
    u64 ts = bpf_ktime_get_ns();

    start.update(&req,&ts);
}

void trace_completion(struct pt_regs *ctx,struct request *req) {
    u64 *tsp,delta;

    tsp = start.lookup(&req);
    if (tsp != 0) {
        delta = (bpf_ktime_get_ns() - *tsp)/1000;
        dist.increment(bpf_log2l(delta));
        //dist.increment((delta)); /*直接使用非bpf_log2l将无法输出结果，原因是本机延迟普遍大于250us，直方图无法输出这么多行，可以减少delta的比例即可，如设置delta = (bpf_ktime_get_ns() - *tsp)/100000;*/
        start.delete(&req);
    }
}

""")

# header
if BPF.get_kprobe_functions(b'blk_start_request'):
    b.attach_kprobe(event="blk_start_request",fn_name="trace_completion")
print("Tracing... Hit Ctrl-C to end.")

# trace until Ctrl-C
try:
    sleep(99999999)
except KeyboardInterrupt:
    print()

# output
b["dist"].print_log2_hist("LAT-us")

输出如下：

Tracing... Hit Ctrl-C to end.
^C
     LAT-us              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 1        |****************************************|
       512 -> 1023       : 1        |****************************************|

Lesson 11. vfsreadlat.py

本例分为python和C两部分文件： examples/tracing/vfsreadlat.py和examples/tracing/vfsreadlat.c，直接结果如下

# ./vfsreadlat.py
Tracing... Hit Ctrl-C to end.

     usecs               : count     distribution
         0 -> 1          : 2120     |****************************************|
         2 -> 3          : 26       |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 6        |                                        |

     usecs               : count     distribution
         0 -> 1          : 2120     |****************************************|
         2 -> 3          : 26       |                                        |
         4 -> 7          : 2        |                                        |
         8 -> 15         : 4        |                                        |
        16 -> 31         : 2        |                                        |

     usecs               : count     distribution
         0 -> 1          : 627      |****************************************|
         2 -> 3          : 10       |                                        |
         4 -> 7          : 2        |                                        |
         8 -> 15         : 3        |                                        |

内容为：

1. b = BPF(src_file = "vfsreadlat.c"): 从独立的源代码文件中读取BPF C 程序
2. b.attach_kretprobe(event="vfs_read",fn_name="do_return"): 将BPF C程序 do_return()附加到内核函数vfs_read()。kretprobe用于检测程序的返回值，而非入口。区别是attach_kprobe()在进入函数时探测，而attach_kretprobe()在退出函数时探测。
3. b["dist"].clear()：清除直方图

Lesson 12. urandomread.py

执行examples/tracing/urandomread.py，并执行命令dd if=/dev/urandom of=/dev/null bs=8k count=5，输出如下结果：

# ./urandomread.py
TIME(s)            COMM             PID    GOTBITS
4150.692889000     sshd             1420   112
4150.692918000     sshd             1420   384
4150.702547000     sshd             1421   384
4151.182605000     sshd             1420   880
4151.182658000     sshd             1420   8192
4151.182771000     sshd             1420   440
4151.205307000     sshd             1420   128
4151.230603000     sshd             1422   112
4151.230639000     sshd             1422   384
4151.256883000     sshd             1423   384
4151.330354000     sshd             1422   880
4151.330396000     sshd             1422   8192
4151.330503000     sshd             1422   440
4151.353134000     sshd             1422   128
4154.874123000     dd               1452   65536
4154.874193000     dd               1452   65536
4154.874252000     dd               1452   65536
4154.874318000     dd               1452   65536
4154.874383000     dd               1452   65536

源码为：

from __future__ import print_function
from bcc import BPF

# load BPF program
b = BPF(text="""
TRACEPOINT_PROBE(random,urandom_read) {
    // args is from /sys/kernel/debug/tracing/events/random/urandom_read/format
    bpf_trace_printk("%d\\n",args->got_bits);
    return 0;
}
""")

# header
print("%-18s %-16s %-6s %s" % ("TIME(s)","GOTBITS"))

# format output
while 1:
    try:
        (task,msg))

需要掌握的内容为：

1. TRACEPOINT_PROBE(random,urandom_read): 检测内核tracepoints random:urandom_read。这是一个稳定的API，推荐尽可能使用该函数替换kprobes。可以使用perf list列出系统支持的tracepoints，使用BPF程序对tracepoint检测时，要求内核版本>=4.7。
2. args->got_bits: args 自动填充为跟踪点参数，其数据结构如下：

#  cat /sys/kernel/debug/tracing/events/random/urandom_read/format
name: urandom_read
ID: 1075
format:
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
        field:int common_pid;   offset:4;       size:4; signed:1;

        field:int got_bits;     offset:8;       size:4; signed:1;
        field:int pool_left;    offset:12;      size:4; signed:1;
        field:int input_left;   offset:16;      size:4; signed:1;

print fmt: "got_bits %d nonblocking_pool_entropy_left %d input_entropy_left %d",REC->got_bits,REC->pool_left,REC->input_left

Lesson 13. disksnoop.py fixed

下面使用block:block_rq_issue 和block:block_rq_complete重写disksnoop.py ：

#!/usr/bin/python
#
# disksnoop.py  Trace block device I/O: basic version of iosnoop.
#               For Linux,eBPF. Embedded C.
#
# Written as a basic example of tracing latency.
#
# Copyright (c) 2015 Brendan Gregg.
# Licensed under the Apache License,Version 2.0 (the "License")
#
# 11-Aug-2015   Brendan Gregg   Created this.

from __future__ import print_function
from bcc import BPF
from bcc.utils import printb

REQ_WRITE = 1   # from include/linux/blk_types.h

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/blkdev.h>

struct data_t {
    u64 len;
    char rwbs[8];
    u64 ts;
};

BPF_HASH(start,u64,struct data_t); //定义一个名为start的哈希，key类型为u64，value类型为struct data_t,注意此处非指针

TRACEPOINT_PROBE(block,block_rq_issue){
    u64 key = 0;
    struct data_t data = {}; //在跟踪block_rq_issue的时候赋值
    data.len = args->bytes;
    bpf_probe_read(&data.rwbs,sizeof(data.rwbs),(void *)args->rwbs);
    data.ts = bpf_ktime_get_ns();

    start.update(&key,&data);
    return 0;
}

TRACEPOINT_PROBE(block,block_rq_complete){
    u64 delta,key = 0;
    struct data_t* datap;
    datap = start.lookup(&key); //在跟踪block_rq_complete时取出保存的值
    if (datap != NULL) {
        delta = bpf_ktime_get_ns() - datap->ts;
        bpf_trace_printk("%d %x %d\\n",datap->len,datap->rwbs,delta / 1000);
        start.delete(&key);
    }
    return 0;
}
""")

# header
print("%-18s %-2s %-7s %8s" % ("TIME(s)","T","BYTES","LAT(ms)"))

# format output
while 1:
    try:
        (task,msg) = b.trace_fields()
        (bytes_s,bflags_s,us_s) = msg.split()

        if int(bflags_s,16) & REQ_WRITE:
            type_s = b"W"
        elif bytes_s == "0":    # see blk_fill_rwbs() for logic
            type_s = b"M"
        else:
            type_s = b"R"
            ms = float(int(us_s,10)) / 1000

            printb(b"%-18.9f %-2s %-7s %8.2f" % (ts,type_s,bytes_s,ms))
    except KeyboardInterrupt:
        exit()

Lesson 14. strlen_count.py

本程序探测用户层面的函数strlen()，计算其字符串参数出现的频率，执行examples/tracing/strlen_count.py的结果为：

# ./strlen_count.py
Tracing strlen()... Hit Ctrl-C to end.
^C     COUNT STRING
         1 " "
         1 "/bin/ls"
         1 "."
         1 "cpudist.py.1"
         1 ".bashrc"
         1 "ls --color=auto"
         1 "key_t"
[...]
        10 "a7:~# "
        10 "/root"
        12 "LC_ALL"
        12 "en_US.UTF-8"
        13 "en_US.UTF-8"
        20 "~"
        70 "#%^,~:-=?+/}"
       340 "\x01\x1b]0;root@bgregg-test: ~\x07\x02root@bgregg-test:~# "

监控的函数strlen()的位置位于libc，当调用libc中的该函数时，会触发运行自定义的count函数

from __future__ import print_function
from bcc import BPF
from time import sleep

# load BPF program
b = BPF(text="""
#include <uapi/linux/ptrace.h>

struct key_t {
    char c[80];
};
BPF_HASH(counts,struct key_t);

int count(struct pt_regs *ctx) {
    if (!PT_REGS_PARM1(ctx))
        return 0;

    struct key_t key = {};
    u64 zero = 0,*val;

    bpf_probe_read_user(&key.c,sizeof(key.c),(void *)PT_REGS_PARM1(ctx));
    // could also use `counts.increment(key)`
    val = counts.lookup_or_try_init(&key,&zero);
    if (val) {
      (*val)++;
    }
    return 0;
};
""")
b.attach_uprobe(name="c",sym="strlen",fn_name="count")

# header
print("Tracing strlen()... Hit Ctrl-C to end.")

# sleep until Ctrl-C
try:
    sleep(99999999)
except KeyboardInterrupt:
    pass

# print output
print("%10s %s" % ("COUNT","STRING"))
counts = b.get_table("counts")
for k,v in sorted(counts.items(),key=lambda counts: counts[1].value):
    print("%10d \"%s\"" % (v.value,k.c.encode('string-escape')))

1. PT_REGS_PARM1(ctx): 该宏会获取传递给 strlen()的第一个参数，即字符串。
2. b.attach_uprobe(name="c",fn_name="count"): 附加到"c"库(如果是主程序，则需要使用其路径，如b.attach_uprobe(name="/usr/bin/python",sym="main",fn_name="do_main"))，更多参见reference。
3. counts = b.get_table("counts"):获取一个table对象，用于遍历。该方式已被废弃，可以直接使用counts = b.["counts"]
4. counts.items():返回table中的key的队列。

Lesson 15. nodejs_http_server.py

本程序会检查用户静态定义跟踪（USDT）probe，它是内核跟踪点的用户级版本，执行examples/tracing/nodejs_http_server.py的结果如下：

# ./nodejs_http_server.py 24728
TIME(s)            COMM             PID    ARGS
24653324.561322998 node             24728  path:/index.html
24653335.343401998 node             24728  path:/images/welcome.png
24653340.510164998 node             24728  path:/images/favicon.png

代码如下：

from __future__ import print_function
from bcc import BPF,USDT
import sys

if len(sys.argv) < 2:
    print("USAGE: nodejs_http_server PID")
    exit()
pid = sys.argv[1]
debug = 0

# load BPF program
bpf_text = """
#include <uapi/linux/ptrace.h>
int do_trace(struct pt_regs *ctx) {
    uint64_t addr;
    char path[128]={0};
    bpf_usdt_readarg(6,ctx,&addr);
    bpf_probe_read_user(&path,sizeof(path),(void *)addr);
    bpf_trace_printk("path:%s\\n",path);
    return 0;
};
"""

# enable USDT probe from given PID
u = USDT(pid=int(pid))
u.enable_probe(probe="http__server__request",fn_name="do_trace")
if debug:
    print(u.get_text())
    print(bpf_text)

# initialize BPF
b = BPF(text=bpf_text,usdt_contexts=[u])

内容包括：

1. bpf_usdt_readarg(6,&addr): 将USDT中的第6个参数的地址保存到addr
2. bpf_probe_read_user(&path,(void *)addr):现在字符串addr执行path变量
3. u = USDT(pid=int(pid)):使用给定的PID初始化USDT跟踪
4. u.enable_probe(probe="http__server__request",fn_name="do_trace"): 将BPF C函数do_trace()附加到Node.js的http__server__request USDT probe上
5. b = BPF(text=bpf_text,usdt_contexts=[u]): 将USDT对象u传递给创建的BPF对象

更多参见@L_301_65@

Lesson 16. task_switch.c

这是一个老的例子，用于回顾上面的内容。

当内核中的每个任务变更时会唤醒该程序，并在BPF map中记录新旧PIDs。

下面的C程序提出了一个新观念：上一个参数。BCC前端对该参数进行了特别处理，这样就可以从kprobe基础设施传递的已保存的上下文中访问该变量。参数的原型位于第一个位置，需要与被kprobed的内核函数的原型匹配，如果匹配，程序将可以无缝地访问函数参数。

#include <uapi/linux/ptrace.h>
#include <linux/sched.h>

struct key_t {
    u32 prev_pid;
    u32 curr_pid;
};

BPF_HASH(stats,struct key_t,1024);
int count_sched(struct pt_regs *ctx,struct task_struct *prev) {
    struct key_t key = {};
    u64 zero = 0,*val;

    key.curr_pid = bpf_get_current_pid_tgid();
    key.prev_pid = prev->pid;

    // could also use `stats.increment(key);`
    val = stats.lookup_or_try_init(&key,&zero);
    if (val) {
      (*val)++;
    }
    return 0;
}

用户空间的组件会加载上述文件，并附加到finish_task_switch内核函数。BPF对象的[]运算符允许访问程序中的每个BPF_HASH，进而访问内核的数据。像使用其他python 字典对象一样使用该对象：允许读取、更新和删除。

BCC实际不会修改内核数据，只是对内核函数调用处进行打点，采集函数入参的信息等。

from bcc import BPF
from time import sleep

b = BPF(src_file="task_switch.c")
b.attach_kprobe(event="finish_task_switch",fn_name="count_sched")

# generate many schedule events
for i in range(0,100): sleep(0.01)

for k,v in b["stats"].items():
    print("task_switch[%5d->%5d]=%u" % (k.prev_pid,k.curr_pid,v.value))

Lesson 17. Further Study

更多例子可以参见Sasha Goldshtein's linux-tracing-workshop。

注：官方的开发文档中没有给出网络相关的内容，后续补充

总结

• BCC的代码分为python和C两部分，C代码通常运行在内核态，用于打点采集系统调用的信息，然后将结果返回给python代码；也可以用于对特定lib的函数进行打点探测。
• BCC的核心为C代码，需要了解系统调用接口，作为信息采集点；以及BCC本身提供的C代码，提供了获取当前时间，进程PID，map数据结构，输出等功能。
• 推荐TRACEPOINT_PROBE进行打点检测，perf list可以列出系统支持的tracepoint，该tracepoint基本包含了系统的大部分系统调用，如clone，sync等(要求内核版本>=4.7)，但网络相关的还是需要使用kprobes对内核函数进行打点，如icmp_rcv。