Guide:
- eBCC性能分析最佳实践(0) - 开启性能分析新篇章
- eBCC性能分析最佳实践(1) - 线上lstat, vfs_fstatat 开销高情景分析
- eBCC性能分析最佳实践(2) - 一个简单的eBCC分析网络函数的latency
- 敬请期待...
0. eBCC Introduction
BCC是基于4.x kernel版本上的ebpf发展出来的一套性能分析工具集;
eBCC,顾名思义则是extended BCC的缩写,是阿里巴巴内核团队在Aliyun Linux 2上对BCC项目的拓展,包含BCC本身已有的工具集,和我们新开发的一些小的工具; eBCC则是基于在最新的BCC版本0.9之上做了一些拓展。
Aliyun Linux则使用了相对比较前沿,较新的kernel版本,支持ebpf特性,所以,如果想尝试ebpf,eBCC带来的系统上对“性能优化调试” 和 “问题诊断”上的新体验,那就请赶快升级到Aliyun Linux 2上吧。
1. Linux未来监控tracing框架:eBPF
eBPF源于早年间的成型于 BSD 之上的传统技术 BPF(Berkeley Packet Filter)。BPF 的全称是 Berkeley Packet Filter,顾名思义,这是一个用于过滤(filter)网络报文(packet)的架构。
BPF 是在 1997 年首次被引入 Linux 的,Linux 内核中的报文过滤机制其实是有自己的名字的:Linux Socket Filter,简称 LSF。
从 3.15 开始,一个套源于 BPF 的全新设计开始,在3.17被添置到了 kernel/bpf 下。全新设计最终被命名为了 extended BPF(eBPF);为了后向兼容,传统的 BPF 仍被保留了下来,并被重命名为 classical BPF(cBPF)。相对于 cBPF,eBPF 带来的改变可谓是革命性的:一方面,它已经为内核追踪(Kernel Tracing)、应用性能调优/监控、流控(Traffic Control)等领域带来了激动人心的变革;另一方面,在接口的设计以及易用性上,eBPF 也有了较大的改进。
cBPF 所覆盖的功能范围很简单,就是网络监控和 seccomp 两块,数据接口设计的粗放;而 eBPF 的利用范围要广的多,性能调优、内核监控、流量控制什么的,数据接口的多样性设计。
由一个文件(net/core/filter.c)进化到一个目录(kernel/bpf)
目前,支持生成 BPF 伪代码的编译器只有 llvm 一家,即使是通篇使用 gcc 编译的 Linux 内核,samples 目录下的 bpf 范例也要借用 llvm 来编译完成。
下图是ebpf的工作机制:
2. eBCC是什么?
用一句话简单的说: eBCC是一个工具集, 用来做Kernel space 和 User space 用户程序的, 问题排查,和性能诊断!
eBCC能做什么呢?
现在可以用 C 来实现 BPF,但编译出来的却仍然是 ELF 文件,开发者需要手动析出真正可以注入内核的代码。这工作有些麻烦,于是就有人设计了 BPF Compiler Collection(BCC),BCC 是一个 python 库,但是其中有很大一部分的实现是基于 C 和 C++的,python实现了对 BCC 应用层接口的封装。而eBCC则是对BCC的拓展和开发。
使用 eBCC 进行 BPF 的开发仍然需要开发者自行利用 C 来设计 BPF 程序——但也仅此而已,余下的工作,包括编译、解析 ELF、加载 BPF 代码块以及创建 map 等等基本可以由 eBCC 一力承担,无需多劳开发者费心。
eBCC tracing:
3. eBCC安装
3.1 方式:RPM包安装:
安装eBCC:
# yum install -y ebcc
# yum install -y ebcc-osstat
完事儿。
4. eBCC使用
- eBCC 里面包含了一系列的 “工具集”,这些工具是module化的开发,主要运用场景是 “profiling” 性能优化 和“出现性能问题的时候的debug” 场景,但是,对于某些重要的module,我们也增加了 monitor的监控的方式,可以直接将数据 传送到 alimonitor(需要简单配置一下alimonitor的监控项,但是数据量大的时候开销可能会比较大);
-
运行方式:支持command line(主要,推荐), daemonize(部分module)的方式运行;
- command line: 直接打印到console上,支持排序等功能。
- daemonize:需要配置化管理(/etc/osstat/osstat.conf),将数据json格式打印到 (/var/log/osstat.log)
-
工具集:
- /usr/share/ebcc/tools
- /usr/share/ebcc/osstat/tools/
-
osstat:
- syscall:支持将所有的syscall的次数和时间统计上来,并且可以根据时间或者次数排序输出
- softirq
- 等等
比如,eBCC中的一个工具:osstat,osstat将会包含多个module
4.0 ebcc
首先,我们先看下ebcc下都有哪些小工具呢?
这里我们提供了一个简单的ebcc
小命令:
#ebcc
An advanced Linux Performance Profling toolset: eBCC
Usage ebcc:
-h - Help
-t - Show all supported tools, classify with type
-a - Show all supported tools totally
Examples:
ebcc -h
ebcc -t
ebcc syscount -h
ebcc vfsstat 1 10
ebcc osstat -m syscall -h
ebcc -t
对小工具进行分类:
#ebcc -t
tcp:
tcpaccept
tcpconnect
tcpconnlat
tcplife
tcpretrans
tcpstates
tcpsubnet
tcptop
tcptracer
func:
funccount
funclatency
funcslower
vfs:
vfscount
vfsstat
syscall:
syscount
osstat -m syscall -h
ext4:
ext4dist
ext4slower
file:
filelife
fileslower
filetop
...
决定使用哪个工具,只需要在ebcc 后面直接添加 "工具名字 -h", 便可以查看工具对应的功能
# ebcc vfscount -h
4.1 工具:osstat
osstat是一个比较重要的工具之一, osstat中的syscall module 可以将从将一个OS系统上的, 所有的syscall 捕获,并且将 次数和时间统计出来,并且,支持sys, pid 两个级别。 syscall 是用户态进入 内核态的 入口。 osstat -m syscall 可以帮助 分析 cpu sys的开销究竟是用户态的 疯狂使用导致,还是 内核函数本身存在 latency? 这非常有助于 用户态开发者和内核态开发者一起分析性能问题。
# ebcc osstat -h
...
...
...
Examples:
command mode: (-l)
#osstat -m syscall -t 10 -i 1 -u 1 -l sys
#osstat -m syscall -t 10 -i 1 -u 1 -l sys -n 10
#osstat -m syscall -t 10 -i 1 -u 1 -l sys -n 10 -T
#osstat -m syscall -t 10 -i 1 -u 1 -l pid
#osstat -m syscall -t 10 -i 1 -u 1 -l pid -p 1
daemonize mode: (-d)
#osstat -d -i 7 -u 3
#osstat -d -i 7 -u 3 -n 3
#osstat -d -i 7 -u 3 -f /etc/osstat/osstat.conf
4.1.1 首先看看osstat 工具包含了哪些模块
#ebcc osstat -M
Supported Modules:
-m syscall
-m softirq
-m pgfault
4.1.2 osstat -m syscall sys级别
#ebcc osstat -m syscall -t 10 -i 1 -u 1 -l sys -n 10 -T
NR SYSCALL COUNT TIME MIN MAX
=================================================================================================
35 nanosleep 2883 907074501 236 3944864
281 epoll_pwait 27 820857284 210 773773366
23 select 2619 762921173 100 2951538
232 epoll_wait 14404 551436152 58 1048206
202 futex 304891 301412809 0 1251552
6 lstat 130117 291113663 287 40958
0 read 45173 95759688 21 656713
217 getdents64 26238 75171208 214 82231
1 write 8497 56316398 177 169597
270 pselect6 706 50987375 199 1391351
61 wait4 276 49677081 202 8727287
NR SYSCALL COUNT TIME MIN MAX
=================================================================================================
35 nanosleep 3347 910159174 134 1103293
23 select 2529 764573883 129 3241268
232 epoll_wait 15093 528232341 80 983735
202 futex 399478 312154858 2 73387
6 lstat 109124 243709631 319 61048
281 epoll_pwait 41 189470734 273 161519558
0 read 23374 94921119 88 721009
1 write 10737 74747585 107 95367
217 getdents64 34223 73694555 211 80931
270 pselect6 1301 66246720 233 78281
7 poll 843 47574550 229 3452827
NR SYSCALL COUNT TIME MIN MAX
4.1.3 osstat -m syscall pid级别
#ebcc osstat -m syscall -t 10 -i 1 -u 1 -l pid -n 10 -T
PID NR SYSCALL COUNT TIME MIN MAX
=================================================================================================================
110811 232 epoll_wait 290 1010778217 51616 60855391
23562 23 select 100 1005190909 10040021 10059593
94425 23 select 100 1005115914 10030841 10064314
5215 202 futex 71 1001496291 118 50058356
4663 202 futex 67 1001326053 248 50058880
4079 232 epoll_wait 1 1001010674 1001010674 1001010674
14622 7 poll 3 1000988330 470 1000987095
37574 23 select 40 1000883822 13119428 36926820
22902 232 epoll_wait 33 1000831340 188043 42588209
123536 61 wait4 3 1000769383 388 1000768392
4513 232 epoll_wait 47 1000573946 84183 117256230
4.1.4 osstat -m softirq sys级别
#ebcc -m softirq -t 10 -i 1 -u 1 -l sys -T -n 10
NUM SOFTIRQ COUNT TIME MIN MAX
=================================================================================================
1 timer 365 532979 389 35078
7 sched 148 371802 496 54114
3 net_rx 62 326907 1508 25594
9 rcu 248 180176 320 4579
4 block 3 13255 2669 6135
2 net_tx 1 4666 4666 4666
NUM SOFTIRQ COUNT TIME MIN MAX
=================================================================================================
3 net_rx 86 461913 886 32398
1 timer 202 343770 222 18041
7 sched 161 216259 340 4418
9 rcu 175 106446 134 4195
NUM SOFTIRQ COUNT TIME MIN MAX
=================================================================================================
3 net_rx 250 790444 500 38084
1 timer 241 481612 175 37471
7 sched 159 294294 304 47044
9 rcu 189 131113 249 7499
工具:funclatency
funclatency 可以将 内核中的重要的 函数的latency统计出来,并且,模拟做一个 柱状图, 主要关心的还是时间!
#ebcc funclatency -mTi 1 vfs_read
Tracing 1 functions for "vfs_read"... Hit Ctrl-C to end.
17:14:20
msecs : count distribution
0 -> 1 : 34376 |****************************************|
2 -> 3 : 38 | |
4 -> 7 : 21 | |
8 -> 15 : 12 | |
16 -> 31 : 1 | |
32 -> 63 : 4 | |
64 -> 127 : 2 | |
128 -> 255 : 1 | |
17:14:21
msecs : count distribution
0 -> 1 : 75623 |****************************************|
2 -> 3 : 44 | |
4 -> 7 : 25 | |
8 -> 15 : 18 | |
16 -> 31 : 6 | |
32 -> 63 : 4 | |
64 -> 127 : 9 | |
128 -> 255 : 5 | |
256 -> 511 : 1 | |
512 -> 1023 : 5 | |
4.2 工具funccount
#ebcc funccount -Ti 1 'vfs_*'
Tracing 49 functions for "vfs_*"... Hit Ctrl-C to end.
17:24:16
FUNC COUNT
vfs_readv 1
vfs_statfs 96
vfs_writev 108
vfs_getxattr 128
vfs_rename 224
vfs_lock_file 405
vfs_get_link 1895
vfs_fstat 3814
vfs_write 10657
vfs_open 17892
vfs_read 20974
vfs_fstatat 151758
vfs_getattr 168803
vfs_getattr_nosec 184572
4.2 工具mysqld_qslower
利用mysql中的USDT, 在mysql server端,追踪 mysql 语句执行的lantency
请使用CMake的-DENABLE_DTRACE = 1
或-DENABLE_DTRACE = 0
选项。
执行:
MariaDB [mysql]> select * from time_zone;
Empty set (0.00 sec)
MariaDB [mysql]>
trace latency:
可以看到 select * from time_zone SQL语句的lentency: 0.160ms
#ebcc mysqld_qslower 101983 0
Tracing MySQL server queries for PID 101983 slower than 0 ms...
TIME(s) PID MS QUERY
0.000000 54806 0.098 select @@version_comment limit 1
3.959677 54806 0.054 show datebases
15.462936 54806 0.269 show databases
23.710874 54806 0.090 SELECT DATABASE()
23.712041 54806 0.199 show databases
23.712308 54806 0.224 show tables
26.310581 54806 0.293 show tables
35.086895 54806 0.160 select * from time_zone