分析程序出现的启动缓慢、响应缓慢和操作卡顿等性能问题时,第一步不该是打开代码编辑器浏览我们的代码,而是首先确定问题是否发生在我们的代码中,简单点的方法就是打开top做一个大致的判断,看一看各CPU的us、sy、id耗时的占比都是多少。进一步来讲,我们需要确定时间都花到什么地方了,是我们的代码中?内核中?还是进程睡大觉的地方?现在假设我们的程序运行在一个CPU资源丰富的环境中,因此就不考虑进程争夺CPU的问题了。我们来看一下,程序运行耗时的组成成分,以及相关的一些需要注意的地方。
1. 墙上时间、用户CPU时间和系统CPU时间
墙上时间就是程序运行所耗的现实世界中的时间,用户CPU时间则是CPU花在执行用户代码所耗的时间,系统CPU时间则是CPU花在执行内核代码所耗的时间,使用time(1)命令即可分析这3类时间:
$ time grep -nr "test"
real 0m8.528s
user 0m1.107s
sys 0m0.698s
用户CPU时间就是CPU在执行我们写的用户进程代码所耗的时间,不包括花在系统调用的时间;系统CPU时间就是当执行流通过系统调用,进入内核空间后,CPU执行内核代码所耗的时间,不包括陷入休眠等待的时间。
高系统CPU时间占比
系统CPU时间占比高不见得就是内核的问题,很可能是用户空间代码的问题,例如下面的例子:
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
int main()
{
const char *BAD_FILE = "/proc/uptime";
while(true)
{
open(BAD_FILE, O_WRONLY);
}
return 0;
}
当执行一段时间后,强制退出程序:
$ time ./badopen
^C
real 0m10.907s
user 0m1.831s
sys 0m9.071s
10s的墙上时间有9s花在了系统CPU时间上,并不是内核代码有问题,而是因为用户代码重复执行会出错的系统调用。
当然了,高系统CPU时间占比确实可能是内核代码的问题,我就遇到过一次因为驱动的问题,而导致程序卡死在了一个ioctl调用中。这样的问题使用perf会比较容易定位,perf是个非常强大的内核分析工具,有时间的话我会写一些相关的文章。
系统CPU时间不是系统调用开始到系统调用结束的时间
许多系统调用都会导致进程休眠,进程休眠的时间并不算在系统CPU时间中。
$ time sleep 1
real 0m1.003s
user 0m0.001s
sys 0m0.003s
用户CPU时间和系统CPU时间可能大于墙上时间
多线程程序很容易发生这样的情况:
#include <thread>
void work() {
int a = 0;
for (int i = 0; i < 10000000; i++) {
a += i;
}
}
int main() {
std::thread t0([](){ work(); });
std::thread t1([](){ work(); });
t0.join();
t1.join();
return 0;
}
$ g++ -std=c++11 multithread.cpp -o multithread -lpthread
$ time ./multithread
real 0m0.045s
user 0m0.085s
sys 0m0.000s
小结
用户CPU时间也好,系统CPU时间也好,统计的都是CPU处于忙碌状态的时间。然而性能问题并不都是由于CPU过于忙碌导致的,还有可能是因为过多的陷入休眠状态,GUI编程的一条“金科玉律”:不要在UI线程中执行阻塞式IO和sleep操作,就是为了避免这种情况导致的卡顿问题。因此,本节中的两类时间是不足以将程序运行耗时划分完毕的,还需要考虑进程睡眠的时间。
2.系统调用延迟(syscall latency)
“系统调用延迟”这个词的出处是strace的手册,指的是系统开始到结束的时间差,这个时间差会包括了系统调用系统CPU时间和进程休眠的时间。例如前面提到过的sleep程序,如果使用strace分析时,加上-w参数,就会统计系统调用延迟:
$ strace -cw sleep 1
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
99.79 1.000504 1000504 1 nanosleep
0.08 0.000818 818 1 execve
0.04 0.000409 82 5 close
0.02 0.000198 33 6 mmap
0.01 0.000141 47 3 brk
0.01 0.000139 35 4 mprotect
0.01 0.000126 42 3 openat
0.01 0.000105 35 3 3 access
0.01 0.000078 78 1 munmap
0.01 0.000070 23 3 fstat
0.00 0.000030 30 1 read
0.00 0.000018 18 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 1.002636 32 3 total
不加-w参数,则只统计系统CPU时间:
$ strace -c sleep 1
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.00 0.000000 0 1 read
0.00 0.000000 0 5 close
0.00 0.000000 0 3 fstat
0.00 0.000000 0 6 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 3 brk
0.00 0.000000 0 3 3 access
0.00 0.000000 0 1 nanosleep
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 3 openat
------ ----------- ----------- --------- --------- ----------------
100.00 0.000000 32 3 total
需要注意的是,系统CPU时间并不是系统调用延迟的子集,系统CPU时间还包括一些处理异常的耗时,并不包含在系统调用的耗时中。
3.缺页异常耗时
用户CPU时间、系统CPU时间和系统调用休眠时间是否就是程序执行耗时的全部组成成分呢?答案仍然是否定的,请看下面的代码:
// bigdata.cpp
#include <stdio.h>
const int ARRAY_SIZE = 200 * 1024 * 1024;
const int array[ARRAY_SIZE] = {1};
int main()
{
int total = 0;
for (int i = 0; i < ARRAY_SIZE; i += 4096)
{
total += array[i];
}
printf("all data is loaded\n");
return 0;
}
使用time统计(统计前使用echo 3 > /proc/sys/vm/drop_caches清除磁盘缓存):
$ time ./bigdata
all data is loaded
real 0m16.963s
user 0m0.033s
sys 0m1.286s
再使用strace统计系统调用延迟(同样统计前使用echo 3 > /proc/sys/vm/drop_caches清除磁盘缓存):
$ strace -cw ./bigdata
all data is loaded
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
95.77 0.045840 45840 1 execve
1.11 0.000532 177 3 brk
0.76 0.000366 122 3 3 access
0.67 0.000322 64 5 mmap
0.51 0.000246 82 3 fstat
0.30 0.000143 36 4 mprotect
0.24 0.000113 113 1 munmap
0.22 0.000105 53 2 openat
0.17 0.000079 79 1 write
0.14 0.000066 33 2 close
0.06 0.000029 29 1 read
0.05 0.000022 22 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.047863 27 3 total
即使把用户CPU时间0.033s、系统CPU时间1.286s和系统调用延迟0.047863s相加(系统CPU时间和系统调用延迟有些重合的地方),也离16.963s的墙上时间相差很多。问题出在了哪里呢?问题出在了缺页异常上。
bigdata.cpp会生成一个大约800M的可执行文件,数据段占据了其中大部分体积。当我们遍历array数组的每个元素时,需要将这800M的数据段全部读取一遍,由此产生的缺页异常耗时就无法忽略了。缺页异常耗时大部分集中在等待磁盘IO时的睡眠上,这部分睡眠时间无法被统计在系统调用延迟上,因为确实没有任何系统调用。mmap系统调用不会导致磁盘IO,它很快就返回了,等到我们在用户空间代码读写被映射区域时,产生了缺页异常,进而发生了磁盘IO消耗了时间。
其他
在用户CPU时间、系统CPU时间、系统调用睡眠时间和缺页异常耗时之外,还有其他组成,比如说CPU处理中断或异常的耗时。CPU处理中断或异常时进程被迫进入睡眠状态,所以中断或异常来得很频繁时也可能会导致性能问题(上面提到的缺页异常也是异常的一种,但是相比其他异常,缺页异常更容易导致性能问题,所以我单列出来了)。