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

news/2024/5/22 17:26:05

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

image

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 4Performance counter stats for 'system wide':449931      syscalls:sys_enter_newlstat4.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要有意义。

image

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

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

http://lihuaxi.xjx100.cn/news/235822.html

相关文章

11.CCNA第十一天-配置OSPF/EIGRP(增强型内部网关协议)

配置OSPFBranch(config)#router ospf ?<1-65535> Process ID通配符掩码在IGP协议中&#xff0c;以连续的0和连续的1组成有一种不科学的称呼&#xff08;反掩码&#xff09;Branch#show running-config | section router ospfrouter ospf 10network 10.1.0.0 0.0.255.25…

Python脱产8期 Day02

一 语言分类 机器语言&#xff0c;汇编语言&#xff0c;高级语言&#xff08;编译和解释&#xff09; 二 环境变量 1、配置环境变量不是必须的2、配置环境变量的目的&#xff1a;为终端提供执行环境 三Python代码执行的方式 1交互式&#xff1a;.控制台直接编写运行python代码 …

MySQL02-升级

MySQL 版本号由三个数字和可选后缀组成&#xff0c;形式 mysql-x.y.z-suffix。比如 mysql-5.7.21 或者 mysql-5.7.34。 x(5)这位是大版本y(7)这位是小版本&#xff0c;大版本小版本组合成 5.7 就是一个发行版最后一位是bugfix release版本&#xff0c;从1逐渐增加&#xff0c;…

小米:开源不仅要站在巨人的肩膀上,还要为巨人指方向

今天上午&#xff0c;第一届小米开源技术峰会在北京举行&#xff0c;会上&#xff0c;小米人工智能与云平台副总裁崔宝秋致开场词&#xff0c;并发表了《小米开源之路》的演讲。 崔宝秋强调小米一直在推动开源&#xff0c;也是开源的倡导者。他告诉我们雷军创立小米的其中一个重…

2021年中国工业互联网安全大赛核能行业赛道writeup之wifi破解近源攻击

附件题&#xff1a;wifi破解——近源攻击 题目描述&#xff1a; 近源攻击&#xff0c;在攻防演练期间&#xff0c;攻击队队员使用无人机悬停监听技术&#xff0c;成功抓取到了某核电办公网络的Wifi握手包&#xff0c;现在正在进行紧张的破解&#xff0c;你能破解该密码吗&…

《跟菜鸟学Cisco UC部署实战》-第 1 章 规划-课件(一共12章,免费)

链接:https://pan.baidu.com/s/1RiIphSUG5dsbPPqWaynHjQ 提取码:xjp9 复制这段内容后打开百度网盘手机App,操作更方便哦 《跟菜鸟学Cisco UC部署实战》-视频课程http://edu.51cto.com/course/10031.html 《Skype for Business Server 2015-企业外部-部署》视频课程http://ed…

计算两个时间的间隔时间是多少

/*** 计算两个时间间隔* param startTime 开始时间* param endTime 结束时间* param type 类型&#xff08;1&#xff1a;相隔小时 2&#xff1a;&#xff09;* return*/public static int compareTime(String startTime, String endTime, int type) {if (endTime nul…

2021年中国工业互联网安全大赛核能行业赛道writeup之日志分析

附件题&#xff1a;日志分析 题目描述&#xff1a; 核电站新来的运维小王粗心把一个办公网地址映射到外网&#xff0c;遭到大量攻击&#xff0c;你能从日志当中找到有效信息吗。 附件下载&#xff1a; 2021-10-12T15_37_51.61064600_00rizhifenxi.rar-网络攻防文档类资源-CSD…