歡迎光臨
每天分享高質量文章

eBCC性能分析最佳實踐(1) – 線上lstat, vfs_fstatat 開銷高情景分析

Guide:

  • eBCC性能分析最佳實踐(0) – 開啟性能分析新篇章
  • eBCC性能分析最佳實踐(1) – 線上lstat, vfs_fstatat 開銷高情景分析
  • eBCC性能分析最佳實踐(2) – 一個簡單的eBCC分析網絡函式的latency
  • 敬請期待…

0. Intro

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. eBCC 分析 “A業務線” 線上機器cpu sys – lstat開銷大

對於kernel團隊的同學來說,排查問題,和性能資料分析的時候,通常情況下會先從宏觀的腳本去分析整機各個子系統:SCHED,MEM,IO,NET的性能是否存在bottleneck。然後再通過各種專業的工具來剖析對應的子系統。

當我們遇到cpu sys很高的情況的時候,根據我們的經驗,比較常見的可能原因為:

  1. 可能是某個kernel thread在瘋狂
  2. 可能是某個syscall被用戶層頻繁呼叫,或者是某個syscall的鏈路上出現很大的latency

第一種情況可能比較好發現問題,針對第二種情況,比較麻煩,難以發現。

於是我們開發了eBCC工具集,來幫助用戶定位問題。

下麵讓我們開始尋找一個線上機器, 看是否存在性能瓶頸吧….

  • 業務方: A業務
  • 診斷物理機: xxxxx
  • 內核版本: 4.19
  • 診斷工具: eBCC

1.1 SYS級別診斷 – 發現問題

如下圖所示,是標的機器top10開銷較大的syscall。其中TIME, MIN, MAX的時間單位都是ns

註意,這裡我們的工具實際上採集了4個資料,次數,時間,最小時間,最大時間。

實際上,只有這四個資料都存在的時候,我們才能很快的分析出這裡是否存在問題,是否正常。如果我們僅僅知道COUNT,不知道時間,這是不能說明問題的。

因為次數多,不一定代表開銷大。開銷大,不一定代表次數多。

實際上select,poll這些操作所占用的時間開銷是屬於正常的的,但是,看到lstat系統呼叫時間開銷多達338769324ns(338ms), 就是不正常的現象了!因此,這可能就是一個可以優化的地方…

進一步分析lstat的MIN TIME, MAX TIME看上去都不大,因此可以確定這個syscall鏈路上並沒有出現latency很大的問題,但是COUNT多達124724次,這也許才是開銷很大的關鍵。。。

換幾台線上機器,發現都存在lstat開銷比較大的問題…

image

因此我們需要進一步排查哪個pid導致?

1.2 PID級別診斷 – 定位問題

  • eBCC的syscall性能分析模塊,支持SYS級別和PID級別的資料採集, 我們一般應該先從SYS級別入手,發現問題的方向之後,再通過PID級別找到觸發問題的元凶。
  • 第1列:pid, 第2列:syscall NR , 第3列:syscall name, 第4列 是呼叫次數, 第5列 是呼叫時間開銷,單位ns, 第6列:min time (ns), 第7列:max time(ns)image

1.3 找到元凶:PID:91885

1.4 Code分析

 1tools/perf/builtin-trace.c:     { .name     = "lstat",      .errmsg = true, .alias = "newlstat", },
 2
 3SYSCALL_DEFINE2(newlstat, const char __user *, filename,
 4        struct stat __user *, statbuf)
 5{
 6    struct kstat stat;
 7    int error;
 8
 9    error = vfs_lstat(filename, &stat;);
10    if (error)
11        return error;
12
13    return cp_new_stat(&stat;, statbuf);
14}
15
16int vfs_lstat(const char __user *name, struct kstat *stat)
17{
18    return vfs_fstatat(AT_FDCWD, name, stat, AT_SYMLINK_NOFOLLOW);
19}
20EXPORT_SYMBOL(vfs_lstat);

1.5 perf輔助證明

通過perf來幫助證明eBCC的資料採集是否精確。

1[[email protected] /root]
2#perf stat -e syscalls:sys_enter_newlstat  -a sleep 4
3
4 Performance counter stats for 'system wide':
5
6            449931      syscalls:sys_enter_newlstat
7
8       4.000941076 seconds time elapsed

基本可以說明,lstat的觸發次數確實很大。

1.6 syscall次數統計

 1[[email protected]xx /root]
 2#ebcc syscount
 3Tracing syscalls, printing top 10... Ctrl+C to quit.
 4
 5^C[14:58:52]
 6SYSCALL                   COUNT
 7close                   1173795
 8lstat                   1052795
 9futex                    667981
10read                     325349
11getdents64               257280
12epoll_wait               255386
13epoll_ctl                250355
14write                    144328
15openat                   115240
16open                     111810

eBCC另外一個工具syscount 同樣可以採集出次數。

1.7 vfs層證明

lstat 系統呼叫同樣會反應到vfs的觸發次數:vfs_fstatat

 1[[email protected] /root]
 2#ebcc vfscount
 3Tracing... Ctrl-C to end.
 4
 5^C
 6ADDR             FUNC                          COUNT
 7ffffffff8124f8b1 vfs_symlink                       1
 8ffffffff8124f711 vfs_create                       11
 9ffffffff812426e1 vfs_readv                        22
10ffffffff8124fbd1 vfs_unlink                       27
11ffffffff81277c31 vfs_fsync_range                  98
12ffffffff812790d1 vfs_statfs                     1126
13ffffffff81269d51 vfs_getxattr                   1248
14ffffffff812428f1 vfs_writev                     1749
15ffffffff81250b01 vfs_rename                     2353
16ffffffff8129bb51 vfs_lock_file                  6167
17ffffffff8124d031 vfs_get_link                  21829
18ffffffff812476b1 vfs_fstat                     50744
19ffffffff81242301 vfs_write                    151061
20ffffffff81240891 vfs_open                     181734
21ffffffff812421d1 vfs_read                     336899
22ffffffff81247711 vfs_fstatat                 1055146    --- tigger counts
23ffffffff81247681 vfs_getattr                 1109493
24ffffffff81247401 vfs_getattr_nosec           1130229

1.8 核心分析:開銷來自於 “用戶呼叫次數” 還是 “內核里vfs_fstatat 函式本身的latency” ?

Answer:

如下圖所示,基本都在2-3個us就完成了。基本上可以說,latency不是很大,基本符合disk,nvme本身的latency,因此,開銷主要來自counts,因此,優化呼叫次數,比 優化 這個內核函式本身的latency要有意義。

image

1.9 根本原因

通過eBCC中的工具追蹤,發現logagent瘋狂的使用vfs_fstatat,遍歷A業務/home/admin/XXXX/worker/slave/disk_links/9999/ 目錄下的檔案, 至此,我們基本就把問題分析清楚了。

 1[[email protected] /home]
 2#/usr/share/ebcc/tools/trace -p 91885 'vfs_fstatat "%s", arg2'
 391885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 491885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 591885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 691885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 791885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 891885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
 991885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1091885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1191885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1291885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1391885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1491885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1591885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1691885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1791885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1891885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
1991885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2091885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2191885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2291885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2391885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2491885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2591885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2691885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2791885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
2891885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc

2. Conclution

image

  • logagent在這個機器上有大量的lstat操作,平均每秒:11w次;整機open次數,平均每秒:12w次。
  • 整機看vfs_fstatat 本身的latency,基本都在2-3us內完成, 沒有太大的內核態似乎沒有太大latency可以優化,因此,用戶態的程式 優化 也許有更好的 效果。
  • logagent在機器運行1s內,大概開銷占用總cpu的:338ms;現在整機96core,那麼就相當於有96s, 如果整機cpu sys占用:3%, 機器運行1s內,內核sys大概占用了3.456s,那麼如果優化掉這338ms,cpu sys利用率會降低9.7%=(338ms/3.456s)。
  • 查看“A業務線”多個機器,發現是個通用現象。

 

    已同步到看一看
    赞(0)

    分享創造快樂