天天看點

eBCC性能分析最佳實踐(0) - 開啟性能分析新篇章

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帶來的系統上對“性能優化調試” 和 “問題診斷”上的新體驗,那就請趕快更新到

上吧。

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           

繼續閱讀