Apr 19, 2019

eBCC性能分析最佳实践（1） - 线上lstat, vfs_fstatat 开销高情景分析

Guide:

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很高的情况的时候，根据我们的经验，比较常见的可能原因为：

可能是某个kernel thread在疯狂
可能是某个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开销比较大的问题…

因此我们需要进一步排查哪个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）

1.3 找到元凶： PID:91885

1.4 Code分析

tools/perf/builtin-trace.c:     { .name     = "lstat",      .errmsg = true, .alias = "newlstat", },

SYSCALL_DEFINE2(newlstat, const char __user *, filename,
        struct stat __user *, statbuf)
{
    struct kstat stat;
    int error;

    error = vfs_lstat(filename, &stat);
    if (error)
        return error;

    return cp_new_stat(&stat, statbuf);
}

int vfs_lstat(const char __user *name, struct kstat *stat)
{
    return vfs_fstatat(AT_FDCWD, name, stat, AT_SYMLINK_NOFOLLOW);
}
EXPORT_SYMBOL(vfs_lstat);

1.5 perf辅助证明

通过perf来帮助证明eBCC的数据采集是否精确。

[root@xxx /root]
#perf stat -e syscalls:sys_enter_newlstat  -a sleep 4

 Performance counter stats for 'system wide':

            449931      syscalls:sys_enter_newlstat

       4.000941076 seconds time elapsed

基本可以说明，lstat的触发次数确实很大。

1.6 syscall次数统计

[root@xxx /root]
#ebcc syscount
Tracing syscalls, printing top 10... Ctrl+C to quit.

^C[14:58:52]
SYSCALL                   COUNT
close                   1173795
lstat                   1052795
futex                    667981
read                     325349
getdents64               257280
epoll_wait               255386
epoll_ctl                250355
write                    144328
openat                   115240
open                     111810

eBCC另外一个工具syscount 同样可以采集出次数。

1.7 vfs层证明

lstat 系统调用同样会反应到vfs的触发次数： vfs_fstatat

[root@xxx /root]
#ebcc vfscount
Tracing... Ctrl-C to end.

^C
ADDR             FUNC                          COUNT
ffffffff8124f8b1 vfs_symlink                       1
ffffffff8124f711 vfs_create                       11
ffffffff812426e1 vfs_readv                        22
ffffffff8124fbd1 vfs_unlink                       27
ffffffff81277c31 vfs_fsync_range                  98
ffffffff812790d1 vfs_statfs                     1126
ffffffff81269d51 vfs_getxattr                   1248
ffffffff812428f1 vfs_writev                     1749
ffffffff81250b01 vfs_rename                     2353
ffffffff8129bb51 vfs_lock_file                  6167
ffffffff8124d031 vfs_get_link                  21829
ffffffff812476b1 vfs_fstat                     50744
ffffffff81242301 vfs_write                    151061
ffffffff81240891 vfs_open                     181734
ffffffff812421d1 vfs_read                     336899
ffffffff81247711 vfs_fstatat                 1055146    --- tigger counts
ffffffff81247681 vfs_getattr                 1109493
ffffffff81247401 vfs_getattr_nosec           1130229

1.8 核心分析：开销来自于 “用户调用次数” 还是 “内核里vfs_fstatat 函数本身的latency” ?

Answer:

如下图所示，基本都在2-3个us就完成了。基本上可以说，latency不是很大，基本符合disk，nvme本身的latency，因此，开销主要来自counts，因此，优化调用次数，比优化这个内核函数本身的latency要有意义。

1.9 根本原因

通过eBCC中的工具追踪，发现logagent疯狂的使用vfs_fstatat，遍历A业务/home/admin/XXXX/worker/slave/disk_links/9999/ 目录下的文件，至此，我们基本就把问题分析清楚了。

[root@xxx /home]
#/usr/share/ebcc/tools/trace -p 91885 'vfs_fstatat "%s", arg2'
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc
91885   121566  logagent        vfs_fstatat      /home/admin/XXXX/worker/slave/disk_links/9999/auto_umars_YYYY_4_YYYY.TPP_mc

2. Conclution

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业务线”多个机器，发现是个通用现象。

eBCC性能分析最佳实践（1） - 线上lstat, vfs_fstatat 开销高情景分析

eBCC性能分析最佳实践（1） - 线上lstat, vfs_fstatat 开销高情景分析

0. Intro

1. eBCC 分析 “A业务线” 线上机器cpu sys - lstat开销大

1.1 SYS级别诊断 - 发现问题

1.2 PID级别诊断 - 定位问题

1.3 找到元凶： PID:91885

1.4 Code分析

1.5 perf辅助证明

1.6 syscall次数统计

1.7 vfs层证明

1.8 核心分析：开销来自于 “用户调用次数” 还是 “内核里vfs_fstatat 函数本身的latency” ?

1.9 根本原因

2. Conclution

Recommend

数据中心网络 BBR 不如 CUBIC ？

What can 129 million calls tell us about inbound marketing? A lot, it turns out

Don't miss the SMX 2021 event lineup

Video: Joe Beccalori on the diminishing value of organic

SMX Overtime: Eternal testing, the key to Facebook Ads success

Unlock actionable tactics to measure search marketing success

Google Search Console brings back request indexing tool

Google confirms passage indexing is not yet live

Technology saving retail businesses from going under

PPC 2020 in review: COVID leaves its mark on e-commerce and paid search

About Joyk