性能优化cpu工具分析及程序耗时

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：

1. 编译时加入参数 -pg就可以打开GProfile的开关
2.  如果想查看库函数的信息，在编译时加入"-lc_p"编译参数代替"-lc"编译参数，这样程序会链接libc_p.a库
3.  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

优化：

1. 第一次对线程数提高，每个请求提高item使用的线程数，同时，逻辑调整从等待整体线程返回到超时自动结束，相应的也减少了返回item数目2%左右；
2. 后来在1的基础上加了个测试，一台机器两个进程和一台机器一个进程，发现两个进程更好；（个人认为两个进程缓解了资源竞争，所以更好，因此下个方向就是减少资源竞争的优化）；
3. 对于另一个场景，请求增多了，但是每个请求的item数降低了，io增加cpu计算降低，提高io线程数，去除不使用的线程，把两个进程调整到一个；