layout: post —

http://www.brendangregg.com/blog/2016-10-06/linux-bcc-ext4dist-ext4slower.html

@君翁

存储IO的性能经常是块设备层研究的内容,但是如果能监控文件系统而不是一味追求块层更精确的数据,这样会让我们更加明白应用程序是如何影响IO的。

我提供了ext4dist的工具专门针对ext4文件系统做,并监控reads,writes,opens,fsyncs并使用直方图输出汇总完的时延,例如:

ext4dist

Tracing ext4 operation latency… Hit Ctrl-C to end. ^C

operation = ‘read’ usecs : count distribution 0 -> 1 : 1210 |**************| 2 -> 3 : 126 |** | 4 -> 7 : 376 |**** | 8 -> 15 : 86 |** | 16 -> 31 : 9 | | 32 -> 63 : 47 |* | 64 -> 127 : 6 | | 128 -> 255 : 24 | | 256 -> 511 : 137 |** | 512 -> 1023 : 66 | | 1024 -> 2047 : 13 | | 2048 -> 4095 : 7 | | 4096 -> 8191 : 13 | | 8192 -> 16383 : 3 | | operation = ‘write’ usecs : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 75 |**************| 16 -> 31 : 5 | | operation = ‘open’ usecs : count distribution 0 -> 1 : 1278 |**************| 2 -> 3 : 40 |* | 4 -> 7 : 4 | | 8 -> 15 : 1 | | 16 -> 31 : 1 | |

																									这个图显示了读延时的分布,较快的时延在7ms内完成,较慢在256~1023ms之间。延时列的数量可以显示出有多少产生延时的事件落到这个范围内。从上面的图我们大概可以推断较快的时延可能命中了文件系统pagecache,较慢的时延可能需要从磁盘中读。

																									延时是一个操作从VFS发出到文件系统,并等待其完成的时间,所以包括了很多:块设备IO、文件系统CPU cycles, 文件系统的锁, 运行时队列的延时等。相比从更低层块设备去统计,这样能更好的测量出应用程序的延时,块设备层的统计更适合资源容量的规划。

																									注意这个工具只追踪通用文件系统的操作,这个上面已经列出。而其他文件系统的操作,比如inode操作getattr等,是不会追踪的。 ext4dist主要是利用的内核动态追踪BPF实现的bcc工具,bcc是一个前后端工具集,主要利用新版本内核的eBPF。

																									我还写过ext4slower,用来追踪ext4中大于某一个阈值的操作,比如下面1ms:

ext4slower 1

																									Tracing ext4 operations slower than 1 ms
																									TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
																									06:49:17 bash           3616   R 128     0           7.75 cksum
																									06:49:17 cksum          3616   R 39552   0           1.34 [
																									06:49:17 cksum          3616   R 96      0           5.36 2to3-2.7
																									06:49:17 cksum          3616   R 96      0          14.94 2to3-3.4
																									06:49:17 cksum          3616   R 10320   0           6.82 411toppm
																									06:49:17 cksum          3616   R 65536   0           4.01 a2p
																									06:49:17 cksum          3616   R 55400   0           8.77 ab
																									06:49:17 cksum          3616   R 36792   0          16.34 aclocal-1.14
																									06:49:17 cksum          3616   R 15008   0          19.31 acpi_listen
																									06:49:17 cksum          3616   R 6123    0          17.23 add-apt-repository
																									06:49:17 cksum          3616   R 6280    0          18.40 addpart
																									06:49:17 cksum          3616   R 27696   0           2.16 addr2line
																									06:49:17 cksum          3616   R 58080   0          10.11 ag
																									06:49:17 cksum          3616   R 906     0           6.30 ec2-meta-data
																									06:49:17 cksum          3616   R 6320    0          10.00 animate.im6


																									这个可以用来证明或者排除存储子系统是否高延迟的原因,比如你遇到应用程序概率性出现100ms延迟,猜测可能是单个IO或者多个IO引起。运行“ext4slower 10”将会输出所有大于10ms的操作,从而证明或者排除你的假设。

																									【译者注,以下BCC的介绍是理解bcc脚本很好的教程】
																									[编辑] BCC开发指导

																									BCC工具集的主页,它是利用eBPF创建高效内核追踪工具集,BCC利用C做的内核工具以及python或者lua做的前端,使得BPF程序更容易编写。

																									BPF保证了加载到内核的程序不会导致crash,不会一直运行,但是BPF是通用的工具,会执行任意类型的计算功能,当然,你可以用C写一个程序并编译成有效的BPF,但是这很容易写出一个C程序但是编译出来BPF是无效,而且用户只有在运行的时候才知道是否有效。

																									利用BPF特定的前端,你可以通过某一种语言编写程序(python或lua)并且从编译器能获取是否有效。BCC的工具集就旨在提供前端来创建有效的BPF程序,并且具有很丰富的扩展性。而且,当前与BPF集成的时,有时候需要在内核源码树中编译。BCC工具链则旨在减少开发者编译BPF程序消耗的时间,主要集中在应用程序编写,以及BPF可以解决的问题上。

																									工具集主要包括:使用共享库实现端到端BPF工作流; C语言作为后端; 为了支持JIT,与llvm-bpf后端集成; 动态(卸)加载JITed; 支持BPF内核钩子: socket过滤器、tc分类器、tc操作、和kprobe; socket过滤器的例子; 追踪运行时系统的工具;
																									[编辑] 第一课 Hello World

																									首先运行examples/hello_world.py, 打开另外一个窗口,运行某些命令,例如“ls”。应该会得到一些输出:

./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()

																												详细解释下这个程序:

																												1. text='...': 这里定义了一个BPF inline程序,其中程序是由C写的。

																												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个参数,最多只有1个%s,trace_pipe是全局共享的,因为并发程序输出可能会有冲突,更好的输出接口是BPF_PERF_OUTPUT(), 下面会介绍。

5. return 0: 格式上要求

6. .trace_print(): bcc的程序将会从trace_pipe中读,并打印输出


		   [编辑] 第三课 hello_fields.py

		   这个程序是examples/tracing/hello_fields.py, 输出是:

./examples/tracing/hello_fields.py

		   TIME(s)            COMM             PID    MESSAGE
		   24585001.174885999 sshd             1432   Hello, World!
		   24585001.195710000 sshd             15780  Hello, World!
		   24585001.991976000 systemd-udevd    484    Hello, World!
		   24585002.276147000 bash             15787  Hello, World!

		   代码如下:

		   from bcc import BPF
		    
		   prog = """
		   int hello(void *ctx){
			   	bpf_trace_printk("Hello, World!\\n");
					return 0;
		   } """ b = BPF(text=prog)
b.attach_kprobe(event="sys_clone", fn_name="hello")
 
print("%-18s %-16s %-6s %s" %("Time()s", "COMM", "PID", "MESSAGE"))
 
while 1:
	try:
			(task, pid, cpu, flags, ts, msg) = b.trace_fields()
	except ValueError:
			continue
				print("%-18.9f %-16s %-6d %s" %(ts, task, pid, msg))

				上面的例子跟hello_world.py非常像,也是追踪通过sys_clone创建的新进程,不过可以学到更多的是:

				1. prog: 这次我们将C程序声明了一个变量。这样的话如果你想基于命令行参数修改字符串会比较方便;

				2. hello(): 现在是仅仅声明了一个C函数,而不是像上次使用kprobe__.所有在BPF程序中C函数都会再触发probe的时候被执行到,因此他们都需要pt_reg *ctx作为第一个参数。如果你需要不被probe触发的函数,可以定义成static inline, 这样可以编译成inlined,而且有时候你还要增加_always_inline属性。

					    3. b.attach_kprobe(event="sys_clone", fn_name="hello"): 这里为sys_clone函数创建一个kprobe,并且触发后执行hello。你可以多次调用attach_kprobe,为多个内核函数附带你的fn_name

					    4. b.trace_fields(): 输入来自于trace_pipe,返回固定的域。
								 [编辑] 第六课 disksnoop.py

										 这个程序是examples/tracing/disksnoop.py, 输出是:

./disksnoop.py

										 TIME(s)            T  BYTES    LAT(ms)
16458043.436012    W  4096        3.13
16458043.437326    W  4096        4.44
16458044.126545    R  4096       42.82
16458044.129872    R  4096        3.24
[...]

代码是:

[...]
REQ_WRITE = 1			#from include/linux/blk_types.h
 
b = BPF(text = """ #include <uapi/linux/ptrace.h> #include <linux/blkdev.h>

BPF_HASH(name, key_type=u64, leaf_type=u64, size=10240)

		BPF_HASH(start, struct request *);
		 
		void trace_start(struct pt_regs *ctx, struct request *req) {
				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;
																		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程序中第一个了常量,后面会用到。如果我们要再BPF程序中使用REQ_WRITE的话,就需要加入合适的#include

  2. BPF_HASH(start, struct request *): 创建一个关联hash的BPF map对象,名字是start。后面第一个参数是hash key的类型。对于不指定的参数,默认是u64.

                   3. trace_start(struct pt_regs *ctx, struct request *req): 这个函数后面会附加到kprobe中,第一个参数是struct pt_regs *ctx,即BPF寄存器上下文;后面的才是内核函数实际的参数.
    
                                             4. start.lookup(&req): 在hash中查找key对应的value,如果存在的话,会返回执行value的指针,否则是NULL。注意这里传递是key的指针.
    
                                                            5. start.update(&req, &ts): 同上面lookup,req作为hash的key.覆盖更新key对应的value值。我们使用指针作为key的原因是可以唯一描述一个值,两个数据结构地址不会相同.
    
    
                                                                        [编辑] 第七课 hello_perf_output.py
    
                                                                        这次我们不使用bpf_trace_print而用BPF_PERF_OUTPUT()接口, 这就意味着不再使用trace_field来获取成员变量,比如PID, timestamp;需要直接去获取他们,程序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
																	   import ctypes as ct
																	    
																	   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();
			data.ts = bpf_ktime_get_ns();
				bpf_get_current_comm(&data.comm, sizeof(data.comm));
				 
					event.perf_submit(ctx, &data, sizeof(data));
					 
						return 0; }

”””

b = BPF(text=prog) b.attach_kprobe(event=”sys_clone”, fn_name=”hello”)

#define output data structure python TASK_COMM_LEN = 16 class Data(ct.Structure): fields = [ (“pid”, ct.c_uint), (“ts”, ct.ulonglong), (“comm”, ct.c_char * TASK_COMM_LEN)]

		print("%-18s %-16s %-6s %s" %("TIME(s)", "COMM", "PID", "MESSAGE"))
		 
		start = 0
		def print_event(cpu, data, size):
				global start
					event = ct.cast(data, ct.POINTER(Data)).contents
					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.kprobe_poll()

1. struct data_t: 定义了从内核态到用户态传递的数据结构;

		  2. BPF_PERF_OUTPUT(events): 对输出channel命名“events”

					      3. bpf_get_current_pid_tgid(): 返回进程ID中的低32位(从内核角度看是PID,用户角度经常称为线程ID)

									     4. events.perf_submit():内核态提交event,这样用户态可以通过perf ring buffer中读取

												     5. b["events"].open_perf_buffer(print_event): 将Python函数print_event与events流联系èµ·来

																		    6. while 1: b.kprobe_poll(): 阻塞方式等待events