Guide:

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的工作机制:

image

2. eBCC是什么?

用一句话简单的说: eBCC是一个工具集, 用来做Kernel space 和 User space 用户程序的, 问题排查,和性能诊断!

eBCC能做什么呢?

image

现在可以用 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:

image

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