cpu性能优化
背景:
先说说背景,主要是最近工作的项目,随着功能迭代,延时一直在升高,因此,需要优化;
所以,想着写一个性能优化的专栏,积累与提升下自己。
在入手查问题前,先做下程序分析:
- cpu密集型进程
- I/O密集型进程
该进程主要是cpu密集型,知道什么类型后,我们的方向将更加明确;
那么,对于性能优化,优化的指标是什么呢,从程序角度看,主要核心指标“吞吐”和”延时“;从系统资源角度看,主要核心指标是资源(cpu/内存...)使用率;
因此,优化前,要有一定数据(吞吐、延时),优化后形成有效对比;
接下来,出发,开始查找并解决问题;
平均负载:
首先准备client工具(统计吞吐),server(在关键点添加grafana指标代码),如果懒得开发,可以直接使用cppmetrics库,方便好用;
压测,top命令观察load average,
当前时间 系统运行时间 正登录用户数 1分/5分/15分的平均负载
top - 20:59:19 up 158 days, 3:01, 2 users, load average: 0.00, 0.01, 0.05
平均负载,是单位时间内,系统处于可运行状态和不可中断状态(R、D)的平均进程数,即平均活跃进程数,他和CPU使用率并没有直接关系;
关于进程状态,大家可man ps查看:
D uninterruptible sleep (usually IO)
R running or runnable (on run queue)
S interruptible sleep (waiting for an event to complete)
T stopped by job control signal
t stopped by debugger during the tracing
W paging (not valid since the 2.6.xx kernel)
X dead (should never be seen)
Z defunct ("zombie") process, terminated but not reaped by its parent
平均负载,直观上理解为单位时间活跃进程数,实际上是活跃进程数的指数衰减平均值,简单点可以理解为活跃进程数的平均值;举个例子方便我们更好理解。
grep 'processor' /proc/cpuinfo | wc -l
64
首先获取逻辑CPU个数,理论上,当平均负载超过该值,就表示过载了;那么我们应该用哪个数据来分析呢(1分/5分/15分) ?
- 如果三者基本相同或者基本差异不大,说明系统很平稳;
- 如果15分远大于1分,说明当前负载在下降
- 如果1分远大于15分,说明当前高峰,或者出现了什么问题。若超过负载,就要分析排查
再看一组数据:
1m 5m 15m
1.5 0.7 5.6
从中可以看出整体的负载是下降趋势,假设我们只有1个逻辑CPU,当前的数据表示,1分负载超了50%,5分负载使用70%,15分负载超了460%。
对于负载数据来说,多少算高呢,可以假定为使用了70%的时候,但是不够准确,需要数据监控,把服务的历史数据统计起来,当发现平均负载数据异常升高的时候,我们再做分析和处理。
对于平均负载我们经常会和cpu使用率混淆,那他们一样吗,从含义出发,平均负载表示,使用CPU的进程和等待CPU的进程/以及等待IO的进程;而CPU使用率,是单位时间内CPU繁忙程度的统计,两者并不一定完全对应。比如:
- cpu密集型,CPU负载会升高,CPU使用率会升高
- I/O密集型,CPU负载会升高,CPU使用率不一定高
- 大量进程等待CPU调度,CPU负载会升高,CPU使用率会升高
整体看大多数情况会导致CPU升高;
平均负载更重要,翻倍的时候,CPU使用率可能30%左右,然而整体性能已经很差了,此时发现延时更高(64核,两个服务,线程从150调到2000,修改配置提高线程并发量,效果反而更差了);并且发现,即使150线程,配置并发量不高的情况,只跑一个服务,延迟也降低了很多。。。
提高线程并发方法:
- 一个用信号量for循环,sempost,一个一个添加,那么线程一个一个并发,线程内容读取该请求队列中要处理的item;
- 一个用条件变量,一次性唤醒多个,提高线程并发;
工具分析:
gprofile使用:
代码使用GProfile编译,可以输出函数相关信息;
node:
- 编译时加入参数 -pg就可以打开GProfile的开关
- 如果想查看库函数的信息,在编译时加入"-lc_p"编译参数代替"-lc"编译参数,这样程序会链接libc_p.a库
- gprof只能在程序正常结束退出之后才能生成程序测评报告,原因是gprof通过在atexit()里注册了一个函数来产生结果信息,任何非正常退出都不会执行atexit()的动作,所以不会产生gmon.out文件。因此要加入signal(SIGINT, sighandler);信号处理函数
参数:
-b 不再输出统计图表中每个字段的详细描述。
-p 只输出函数的调用图(Call graph的那部分信息)。
-q 只输出函数的时间消耗列表。
-e Name 不再输出函数Name 及其子函数的调用图(除非它们有未被限制的其它父函数)。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。
-E Name 不再输出函数Name 及其子函数的调用图,此标志类似于 -e 标志,但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。
-f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。
-F Name 输出函数Name 及其子函数的调用图,它类似于 -f 标志,但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。
-z 显示使用次数为零的例程(按照调用计数和累积时间计算)。
运行:
gprofile 程序名 生成的文件名gmon.out
解析:
函数总时间占比 累计秒数 函数耗时秒数 调用次数 每次调用仅该函数运行时间 每次调用函数总运行时间(包括子函数)
4 % cumulative self self total
5 time seconds seconds calls s/call s/call name
6 96.60 2.27 2.27 1 2.27 2.27 LoadFtrlModel(std::string const&)
7 1.28 2.30 0.03 1 0.03 0.03 LRU::LRU()
8 0.43 2.31 0.01 73488 0.00 0.00 GbdtNodeSplit(_TreeNode&)
共有三种含义,当前索引含义,父含义,子含义;
index位置表示该函数,上面表示父,下面表示子;
函数耗时比,仅该函数耗时,子函数传递到该函数的耗时,调用次数(不包含递归,若递归后面加'+')
函数耗时比,“该函数”传递到父函数的耗时,“该函数”的子函数耗时,父函数调用“该函数”次数/该函数被调用总次数
函数耗时比,仅该函数耗时,子函数传递到该函数的耗时,被上层调用次数/总调用次数
337 index % time self children called name
339 [1] 98.5 0.00 2.31 Init() [1]
340 0.00 2.31 1/1 EndInit() [3]
341 0.00 0.00 1/1 PreInit() [5]
362 2.27 0.00 1/1 Model::Init() [51]
363 [4] 96.6 2.27 0.00 1 LoadFtrlModel(std::string const&) [4]
364 0.00 0.00 5/5 UProfile::~UProfile() [35]
365 0.00 0.00 1/2144 Log::getInstance() [25]
mpstat:
mpstat 5 1
17时03分47秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
17时03分52秒 all 27.79 0.00 0.53 0.02 0.00 0.01 0.00 0.00 0.00 71.66
平均时间: all 27.79 0.00 0.53 0.02 0.00 0.01 0.00 0.00 0.00 71.66
mpstat -P ALL 5 1
17时04分42秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
17时04分47秒 all 26.33 0.00 0.62 0.01 0.00 0.01 0.00 0.00 0.00 73.03
17时04分47秒 0 27.35 0.00 0.60 0.00 0.00 0.00 0.00 0.00 0.00 72.06
17时04分47秒 1 30.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 69.00
17时04分47秒 2 25.60 0.00 0.60 0.00 0.00 0.00 0.00 0.00 0.00 73.80
17时04分47秒 3 29.86 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 69.14
%user:表示处理用户进程所使用CPU的百分比。
%nice:表示使用nice命令改变过优先级的进程的CPU的百分比;
%system:表示内核进程使用的CPU百分比;
%iowait:表示等待进行I/O所使用的CPU时间百分比;
%irq:表示用于处理系统中断的CPU百分比;
%soft:表示用于软件中断的CPU百分比;
%steal :显示虚拟机管理器在服务另一个虚拟处理器时虚拟CPU处在非自愿等待下花费时间的百分比
%guest :显示运行虚拟处理器时CPU花费时间的百分比
%idle:显示CPU的空闲时间;
top命令类似:
%Cpu(s): 0.0 us, 0.3 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
hi表示硬中断
si表示软中断
整体看没发现什么问题;单点分析:
pidstat 5 1
17时21分25秒 UID PID %usr %system %guest %CPU CPU Command
17时21分30秒 10000 5459 0.00 0.20 0.00 0.20 49 pidstat
17时21分30秒 10000 289960 100.00 17.73 0.00 100.00 8 s1
17时21分30秒 10000 361202 100.00 36.65 0.00 100.00 35 s2
17时21分30秒 0 406991 0.00 0.20 0.00 0.20 4 kworker/4:0
单个服务s1/s2出现高cpu情况,且system高也是一个需要注意的点;这里由于pidstat版本低,没有%wait(该指标可以看竞争情况,判断是否是大量进程场景)
system高也有可能是io高,虽然pmstat的iowait没有体现,我们也不妨看看:
pidstat -d 5 1
17时27分04秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
17时27分09秒 10000 289960 0.00 7.13 0.00 s1
17时27分09秒 10000 361202 0.00 7.13 0.00 s2
磁盘写入也不高;
接下来重点分析user/system高问题。
继续之前先说下中断及中断处理:
中断包括程序中断、IO中断、外部中断(时钟中断等)、计算机故障中断,访管中断
分为上半部和下半部,上半部处理紧急短小,下半部实现tasklet、工作队列、软中断(softirq)、线程化irq
硬中断是外部设备对CPU的中断,软中断是下半部的一种处理机制
中断优先级高于软中断,软中断又高于任何一个线程
工具分析续:
vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
53 0 0 49567824 35720 115308016 0 0 1 45 0 0 10 1 90 0 0
2 0 0 49310976 35728 115314832 0 0 0 2146 299674 34273 38 1 61 0 0
1 0 0 49094940 35744 115319192 0 0 0 43 219420 30862 37 2 61 0 0
0 0 0 48859884 35760 115323536 0 0 0 12 363292 34774 37 2 61 0 0
8 0 0 48667336 35776 115327968 0 0 0 2681 260321 31528 34 2 64 0 0
2 0 0 47881480 35804 115843184 0 0 3 33065 318004 41760 35 1 64 0 0
5 0 0 46811872 35864 116679176 0 0 8 235596 203094 48511 35 3 62 0 0
1 0 0 45339292 35880 116683936 0 0 0 38 259818 31715 34 6 60 0 0
83 0 0 46454004 35888 116688368 0 0 0 14 260657 31015 33 1 66 0 0
机器64processors;
r:就绪队列还好;
b:没阻塞的;
bo:写磁盘块数;
in:中断比较高;
cs:上下文切换比较高;
查看上下文切换:
pidstat -w 5
19时56分17秒 UID PID cswch/s nvcswch/s Command
平均时间: 10000 185121 187.50 0.08 s1
平均时间: 0 224683 1.64 0.00 kworker/41:2
平均时间: 10000 247732 209.91 0.04 s2
cswch:主动切换,基本200左右
nvcswch:被动切换
上下文切换不高,看看是否线程导致;
pidstat -wt 5
1 平均时间: 10000 73664 - 185.95 0.00 s2
2 平均时间: 10000 - 73664 185.95 0.00 |__s2
3 平均时间: 10000 - 73665 49.38 0.00 |__s2
4 平均时间: 10000 - 73666 49.38 0.00 |__s2
5 平均时间: 10000 - 73667 49.29 0.00 |__s2
6 平均时间: 10000 - 73668 49.32 0.00 |__s2
7 平均时间: 10000 - 73669 49.29 0.00 |__s2
8 平均时间: 10000 - 73670 49.18 0.00 |__s2
9 平均时间: 10000 - 73671 49.26 0.00 |__s2
10 平均时间: 10000 - 73672 49.32 0.00 |__s2
11 平均时间: 10000 - 73673 49.29 0.00 |__s2
12 平均时间: 10000 - 73674 49.32 0.00 |__s2
13 平均时间: 10000 - 73675 97.47 0.00 |__s2
14 平均时间: 10000 - 73676 1.08 0.00 |__rdk:main
15 平均时间: 10000 - 73677 6.67 0.00 |__rdk:broker-1
16 平均时间: 10000 - 73678 104.80 0.00 |__rdk:broker10420
17 平均时间: 10000 - 73679 107.32 0.00 |__rdk:broker10420
18 平均时间: 10000 - 73680 117.45 0.00 |__rdk:broker10421
19 平均时间: 10000 - 73681 84.70 0.00 |__rdk:broker10421
20 平均时间: 10000 - 73682 108.06 0.06 |__rdk:broker10422
21 平均时间: 10000 - 73683 108.85 0.00 |__rdk:broker10422
22 平均时间: 10000 - 73684 117.54 0.03 |__rdk:broker10423
23 平均时间: 10000 - 73685 107.12 0.00 |__rdk:broker10423
24 平均时间: 10000 - 73686 0.99 0.00 |__s2
25 平均时间: 10000 - 73687 372.73 21.82 |__s2
26 平均时间: 10000 - 73688 1.16 0.00 |__rdk:main
27 平均时间: 10000 - 73689 6.64 0.00 |__rdk:broker-1
28 平均时间: 10000 - 73690 5.05 0.00 |__rdk:broker10420
29 平均时间: 10000 - 73691 5.08 0.00 |__rdk:broker10420
30 平均时间: 10000 - 73692 5.08 0.00 |__rdk:broker10421
31 平均时间: 10000 - 73693 5.14 0.00 |__rdk:broker10421
32 平均时间: 10000 - 73694 4.99 0.00 |__rdk:broker10422
33 平均时间: 10000 - 73695 5.02 0.00 |__rdk:broker10422
34 平均时间: 10000 - 73696 5.05 0.00 |__rdk:broker10423
35 平均时间: 10000 - 73697 5.05 0.00 |__rdk:broker10423
36 平均时间: 10000 - 73698 2.04 0.00 |__rdk:main
37 平均时间: 10000 - 73699 6.67 0.00 |__rdk:broker-1
38 平均时间: 10000 - 73708 43.70 159.45 |__s2
39 平均时间: 10000 - 73709 0.79 0.00 |__s2
40 平均时间: 10000 - 73710 9.96 0.00 |__s2
41 平均时间: 10000 - 73711 0.26 0.00 |__s2
42 平均时间: 10000 - 73712 0.26 0.00 |__s2
43 平均时间: 10000 - 73794 0.09 0.00 |__s2
44 平均时间: 10000 - 73795 1.84 0.65 |__s2
45 平均时间: 10000 - 73796 2.72 0.65 |__s2
46 平均时间: 10000 - 73797 2.16 1.25 |__s2
47 平均时间: 10000 - 73798 1.70 0.94 |__s2
48 平均时间: 10000 - 73799 1.70 0.68 |__s2
49 平均时间: 10000 - 73800 1.79 0.51 |__s2
50 平均时间: 10000 - 73801 1.84 0.74 |__s2
51 平均时间: 10000 - 73802 1.82 0.34 |__s2
52 平均时间: 10000 - 73803 1.73 0.09 |__s2
53 平均时间: 10000 - 73804 2.33 1.50 |__s2
54 平均时间: 10000 - 73805 1.82 0.11 |__s2
55 平均时间: 10000 - 73806 1.84 1.28 |__s2
56 平均时间: 10000 - 73807 1.93 0.88 |__s2
57 平均时间: 10000 - 73808 1.82 0.85 |__s2
kafka和个别线程会抢占资源(需要分析抢占资源相关代码);其他线程整体还好;s2服务两三千的样子;
接下来中断数着手:
显示中断信息
CPU:显示每秒中断数量,从 /proc/interrupts 读取数据
SCPU:显示每秒软中断数量,从 /proc/softirqs 读取数据
SUM:显示每个处理器的中断总数
ALL:输出上面三个关键字的所有内容
mpstat -I SCPU -P 0 1 1
20时19分23秒 CPU HI/s TIMER/s NET_TX/s NET_RX/s BLOCK/s BLOCK_IOPOLL/s TASKLET/s SCHED/s HRTIMER/s RCU/s
20时19分24秒 0 0.00 514.85 0.00 0.00 0.00 0.00 0.99 75.25 0.00 215.84
20时19分25秒 0 0.00 455.00 0.00 0.00 0.00 0.00 1.00 119.00 0.00 193.00
20时19分26秒 0 0.00 511.00 0.00 0.00 0.00 0.00 1.00 52.00 0.00 219.00
mpstat -I CPU -P 0 1 1
20时18分39秒 CPU 0/s 8/s 9/s 16/s 24/s 26/s 27/s 30/s 32/s 33/s 34/s 35/s 36/s 38/s 40/s 41/s 42/s 43/s 44/s 45/s 46/s 47/s 48/s 49/s 50/s 51/s 52/s 53/s 54/s 55/s 56/s 57/s 58/s 59/s 60/s 61/s 62/s 63/s 64/s 65/s 66/s 67/s 68/s 69/s 70/s 71/s 72/s 73/s 74/s 75/s 76/s 77/s 78/s 79/s 80/s 81/s 82/s 83/s 84/s 85/s 86/s 87/s 88/s 89/s 90/s 91/s 92/s 93/s 94/s 95/s 96/s 97/s 98/s 99/s 100/s 101/s 102/s 103/s 104/s 105/s 106/s 107/s 108/s 109/s 110/s 111/s 112/s 113/s 114/s 115/s 116/s 117/s 118/s 119/s 120/s 121/s 122/s 123/s 124/s 125/s 126/s 127/s 128/s 129/s 130/s 131/s 132/s 133/s 134/s 135/s 136/s 137/s 138/s 139/s 140/s 141/s 142/s 143/s 144/s 145/s 146/s 147/s 148/s 149/s 150/s 151/s 152/s 153/s 154/s 155/s 156/s 157/s 158/s 159/s 160/s 161/s 162/s 163/s 164/s 165/s 166/s 167/s 168/s 169/s 170/s 171/s 172/s 173/s 174/s 175/s 176/s 177/s 178/s 187/s 252/s NMI/s LOC/s SPU/s PMI/s IWI/s RTR/s RES/s CAL/s TLB/s TRM/s THR/s DFR/s MCE/s MCP/s ERR/s MIS/s PIN/s PIW/s
20时18分40秒 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 335.00 0.00 0.00 2.00 0.00 77.00 4294966749.00 2881.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
//每个cpu中断数5000都不到,不繁忙
mpstat -I SUM -P ALL 2 1
20时24分51秒 CPU intr/s
20时24分53秒 all 55742.29
20时24分53秒 0 847.26
20时24分53秒 1 844.28
20时24分53秒 2 1104.48
20时24分53秒 3 774.63
20时24分53秒 4 989.05
发现RES(重调度中断)并不高,这个中断表示,唤醒空闲CPU来调度新的任务运行,这是调度器用来分散任务到不同CPU的机制,通常称作处理器中断;并且非自愿切换并不高;主要都是自愿上下文切换,说明存在抢占资源情况;
汇总下目前要解决的几个问题CAL、TLB高,lv负载高CPU利用率低的问题;
整体猜测是一个机器两个进程(且两个进程都有几十G缓存)导致性能差(tlb高,上下文切换高);另一个是代码存在资源竞争问题(pstack + pidstat -wt查找线程堆栈看看在做什么,为什么上下文切换那么多);
后续需要perf做更具体分析;
机器对比:
A、B两个机器(每个机器2个服务,配置相同,qps相同,150线程,80G缓存,两个服务版本,每个请求处理600条数据,分配给300个线程)A机器老版本服务(处理item少)B机器新版本服务(处理item多一些)
C机器(只修改线程数2000,其他不变,使用的是信号量增加并发同A/B)新版本服务;
D机器(只修改线程数2000,使用的是条件变量增加并发)新版本服务;
vmstat比对:A,B 发现vmstat没啥变化,C vmstat的in,cs翻了一倍;D机器(看负载就已经翻倍了,其他机器负载基本20左右,vmstat cs暴增,高并发效果更强,多线程反而成了负担,是资源的抢占还是并发太大)
pidstat -wt看线程比对:B主动=D,B被动》D,但D线程数更多; 》 A主动=C,C被动》A,但C线程更多;
延迟比对:A《C《B《D
优化:
- 第一次对线程数提高,每个请求提高item使用的线程数,同时,逻辑调整从等待整体线程返回到超时自动结束,相应的也减少了返回item数目2%左右;
- 后来在1的基础上加了个测试,一台机器两个进程和一台机器一个进程,发现两个进程更好;(个人认为两个进程缓解了资源竞争,所以更好,因此下个方向就是减少资源竞争的优化);
- 对于另一个场景,请求增多了,但是每个请求的item数降低了,io增加cpu计算降低,提高io线程数,去除不使用的线程,把两个进程调整到一个;