歡迎光臨
每天分享高質量文章
當前位置：知識星球 > 後端 > 正文

eBCC效能分析最佳實踐（1） – 線上lstat, vfs_fstatat 開銷高情景分析

2019-04-28 分類：後端 閱讀(360) 評論(0)

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[root@xxx /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[root@xxx /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[root@xxx /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[root@xxx /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)
    標籤：

    相關推薦

    熱門標籤

    iOS (11238)微軟 (4955)Linux (4274)安全 (4180)Python (4161)效能 (3165)運維 (2774)最佳化 (2419).NET (2262)Google (2136)機器學習 (1795)併發 (1613)分散式 (1559)叢集 (1240)SQL (1174)Mysql (1060)區塊鏈 (1017)Docker (977)微服務 (922)面試 (919)Apache (743)NLP (725)Redis (719)Android (668)Git (640)架構師 (632)Nginx (630)Facebook (599)JVM (595)爬蟲 (476)

    熱門文章

    分享創造快樂