概要
以前我只是知道系统调用开销大,耗时长,但是这个代价有多大一直没量化。前段时间处理一个问题让我对这个有了比较“理性”的认识,也就是说现在可以拿出相对量化的指标。
优化案例
业务背景太长了不方便说。不过单单从技术上来看,这个就比较简单;就是代码中出现了 sleep(0) 使得性能与预期不一致。
也就是说期望的代码是
代码语言:javascript复制int benchmark(int i)
{
return i;
}
但是实际的代码是
代码语言:javascript复制int benchmark(int i)
{
sleep(0);
return i;
}
一开始看到 sleep(0) 的时候只是感觉奇怪;主要是看到睡眠的时间是 0 以为就没有影响,后面发现这里是一个大坑。
比较 sleep(0) 带来的性能差异
我们比较了“有 sleep(0)” 与 “注释掉 sleep(0)”的耗时情况(我这里说的耗时是指的上文的 benchmark 函数,技术之外的事不方便多说)。
代码中有 sleep(0) 时 benchmark 函数耗时平均值是 253073(ns) ,当注释掉 sleep(0) 的时候平均耗时是3246(ns) 。画成图表的话会直观一些,我们可以看到它们两个的耗时比较大致上是这样的。
以下是 bpftrace 的代码(用来追踪函数的执行耗时)
代码语言:javascript复制#!/usr/bin/env bpftrace
/*
追踪 /data/repos/cpp-20/build/cpps 程序 的 benchmark 函数的执行耗时
作者: 蒋乐兴
时间: 2022-09
*/
BEGIN
{
printf("**** start trace cpps.benchmark function time cost ****n");
}
uprobe:/data/repos/cpp-20/build/cpps:benchmark
{
print("enter function benchmark .");
@start[comm] = nsecs;
}
uretprobe:/data/repos/cpp-20/build/cpps:benchmark / @start[comm] /
{
print("exit function benchmark .");
printf("time-cost %d (ns) nn", (nsecs - @start[comm]));
delete(@start[comm]);
}
END
{
printf("**** end trace cpps.benchmark function time cost ****n");
clear(@start);
}
执行追踪程序
代码语言:javascript复制bpftrace benckmark-trace.bt
Attaching 4 probes...
**** start trace cpps.benchmark function time cost ****
## 以下是没有 sleep(0) 时的耗时
enter function benchmark .
exit function benchmark .
time-cost 3106 (ns)
enter function benchmark .
exit function benchmark .
time-cost 3437 (ns)
enter function benchmark .
exit function benchmark .
time-cost 3196 (ns)
# 以下是 sleep(0) 时的耗时导致,可以看到这个涨上去了。
enter function benchmark .
exit function benchmark .
time-cost 234281 (ns)
enter function benchmark .
exit function benchmark .
time-cost 366080 (ns)
enter function benchmark .
exit function benchmark .
time-cost 158860 (ns)
分析
前面我们通过控制变量的方法,确认了问题是由 sleep(0) 引起的。怀疑编译器没有把 sleep(0) 优化掉。
这样的话问题就简单了,我们只要确认在执行 sleep(0) 的时候有没有发生系统调用就行,这个也有现成的工具 strace 就是专门用来看这个的。
代码语言:javascript复制strace build/cpps
execve("build/cpps", ["build/cpps"], 0x7ffe8f3797d0 /* 30 vars */) = 0
brk(NULL) = 0xb8d000
arch_prctl(0x3001 /* ARCH_??? */, 0x7fff526919c0) = -1 EINVAL (Invalid argument)
....
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=0}, 0x7fff52691980) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=0}, 0x7fff52691980) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=0}, 0x7fff52691980) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=0}, 0x7fff52691980) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=0}, 0x7fff52691980) = 0
exit_group(0)
这下好了!sleep(0) 并没有被优化掉,它还是去调用了 clock_nanosleep 这个系统调用 。
福利
可以用以下命令确认一下你的服务器上是不是有这种 sleep 的进程存在;不要真的被这种 sleep(2) 改成 sleep(1) 的优化“技巧”给忽悠了。
代码语言:javascript复制bpftrace -e 'tracepoint:syscalls:sys_enter_nanosleep{printf("%s is sleeping.n", comm);}'
Attaching 1 probe...
YDService is sleeping.
YDService is sleeping.
YDService is sleeping.
sh is sleeping.
... ... ...