Linux性能分析-CPU上下文切换

前言

Linux性能分析-平均负载中,提到过一种导致平均负载升高的情况,就是有大量进程或线程等待cpu调度。

为什么大量进程或者线程等待CPU调度会导致负载升高呢?

当大量进程或者线程等待调度时,cpu需要更加频繁的切换任务,在切换任务的过程中,需要保存上一个任务的context到内核中,并且恢复当前任务的context,这种保存和恢复的操作也是需要cpu来执行的,导致cpu都消耗在了 保存上文和恢复下文这个过程中。

除了进程和线程导致的上下文切换以外,硬件产生的中断事件也会导致上下文切换。并且中断事件的优先级是高于线程和进程任务的。

这篇文章会模拟测试这种情况。

必备的工具介绍
vmstat

vmstat是一个观测总体上下文切换状况的命令。
下面指令可以每隔5秒输出一组数据。

[root@localhost shell]# 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
 1  0   1544 1011512   4172 1674144    0    0     5   829   39   72  1  0 99  0  0
 1  0   1544 1011380   4172 1674176    0    0     0   162  163  236  1  0 99  0  0
 0  0   1544 1011412   4172 1674176    0    0     0     0  142  240  1  0 99  0  0
 0  0   1544 1011412   4172 1674176    0    0     0     0  119  159  1  0 99  0  0
 0  0   1544 1012404   4172 1674076    0    0     0     0  533  783  1  1 97  0  0

重点关注列含义:

  • r列:就绪队列的长度,也就是正在运行和等待cpu的任务数
  • b列:处于不可中断睡眠状态的任务数
  • in列:每秒中断的次数
  • cs列:每秒上下文切换的次数
pidstat

使用vmstat关注到了整体的情况,接下来可以使用pidstat关注具体线程的情况
注:pidstat -wt 可以输出线程的情况

[root@localhost shell]# pidstat -w 5
Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 	2020年07月08日 	_x86_64_	(4 CPU)

13时55分20秒   UID       PID   cswch/s nvcswch/s  Command
13时55分25秒     0         9     12.48      0.00  rcu_sched
13时55分25秒     0        11      0.20      0.00  watchdog/0
13时55分25秒     0        12      0.20      0.00  watchdog/1
13时55分25秒     0        14      0.20      0.00  ksoftirqd/1
13时55分25秒     0        17      0.20      0.00  watchdog/2
13时55分25秒     0        22      0.20      0.00  watchdog/3
13时55分25秒     0        47      0.20      0.00  khugepaged
13时55分25秒     0       378      1.39      0.00  irq/16-vmwgfx
13时55分25秒     0       501      0.20      0.00  kworker/0:1H
13时55分25秒     0      1891     12.87      0.20  X
13时55分25秒     0      2175      0.20      0.00  wpa_supplicant
13时55分25秒     0      2529      0.20      0.00  ssh-agent
13时55分25秒     0      2581     14.26      0.00  gnome-shell
13时55分25秒     0      2604      0.79      0.00  ibus-daemon
13时55分25秒     0      2668      0.20      0.00  goa-identity-se
13时55分25秒     0      2756      0.99      0.00  gsd-color
13时55分25秒     0      2847     10.10      0.00  vmtoolsd
13时55分25秒     0      2947      0.20      0.00  ibus-engine-sim
13时55分25秒     0      6206      5.74      0.00  gnome-terminal-
13时55分25秒     0      6833      0.99      0.00  kworker/1:28
13时55分25秒     0     15685      0.20      0.00  fwupd
13时55分25秒     0     24573     10.10      0.00  vmtoolsd
13时55分25秒     0     24900      1.58      0.00  rngd
13时55分25秒     0    112976      1.39      0.00  kworker/3:0
13时55分25秒     0    115704      0.79      0.00  kworker/2:2
13时55分25秒     0    116180      0.99      0.00  kworker/u256:2
13时55分25秒     0    119739      3.37      0.00  kworker/0:0
13时55分25秒     0    119809      0.59      0.00  kworker/0:3
13时55分25秒     0    119826      0.20      0.00  pidstat

重点关注列含义:

  • cswch/s:自愿切换上下文。比如IO内存等系统资源不足时,任务会主动切换上下文。
  • nvcswch/s:非自愿上下文切换,当大量任务等待调度时,系统会强制任务上下cpu。
实际测试

系统环境:

操作系统:centos7
cpu:4核,内存:8g

首先安装sysbench,使用sysbench,我们可以模拟一个进程内多线程调度引起的上下文切换问题。

[root@localhost shell]# yum install sysbench

安装好后,执行下面命令

[root@localhost shell]# sysbench --num-threads=20 --max-time=300 --test=threads run

查看下vmstat和pidstat

[root@localhost shell]# 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
12  0   1544 984260   4172 1700288    0    0     5   819   42   28  1  0 99  0  0
12  0   1544 984136   4172 1700288    0    0     0     2 64063 1469914 19 66 15  0  0
[root@localhost shell]# pidstat -wt 5
Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 	2020年07月08日 	_x86_64_	(4 CPU)

14时10分21秒   UID      TGID       TID   cswch/s nvcswch/s  Command
14时10分26秒     0    119981         -      3.33      0.00  kworker/0:0
14时10分26秒     0         -    119981      3.33      0.00  |__kworker/0:0
14时10分26秒     0    120045         -      0.39      0.00  kworker/0:3
14时10分26秒     0         -    120045      0.39      0.00  |__kworker/0:3
14时10分26秒     0         -    120069  13182.55  57331.57  |__sysbench
14时10分26秒     0         -    120070  13993.33  50786.86  |__sysbench
14时10分26秒     0         -    120071  17088.63  59359.61  |__sysbench
14时10分26秒     0         -    120072  15789.22  53959.61  |__sysbench
14时10分26秒     0         -    120073  13882.35  53891.57  |__sysbench
14时10分26秒     0         -    120074  14793.33  46352.75  |__sysbench
14时10分26秒     0         -    120075  13281.18  55530.78  |__sysbench
14时10分26秒     0         -    120076  14189.80  56319.61  |__sysbench
14时10分26秒     0         -    120077  14870.39  52858.24  |__sysbench
14时10分26秒     0         -    120078  13928.04  57796.47  |__sysbench
14时10分26秒     0         -    120079  13780.39  56587.25  |__sysbench
14时10分26秒     0         -    120080  14157.65  55370.00  |__sysbench
14时10分26秒     0         -    120081  13403.14  54099.22  |__sysbench
14时10分26秒     0         -    120082  16154.31  50767.06  |__sysbench
14时10分26秒     0         -    120083  15907.45  48268.24  |__sysbench
14时10分26秒     0         -    120084  14213.53  49035.69  |__sysbench
14时10分26秒     0         -    120085  14125.29  55470.78  |__sysbench
14时10分26秒     0         -    120086  13912.16  54188.63  |__sysbench
14时10分26秒     0         -    120087  14980.59  49492.55  |__sysbench
14时10分26秒     0         -    120088  15290.39  55748.24  |__sysbench
14时10分26秒     0    120102         -      0.20      1.18  pidstat
14时10分26秒     0         -    120102      0.20      1.18  |__pidstat
[root@localhost shell]# pidstat -u 5 5
Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 	2020年07月08日 	_x86_64_	(4 CPU)

14时31分22秒   UID       PID    %usr %system  %guest    %CPU   CPU  Command
14时31分27秒     0      1891    0.40    0.00    0.00    0.40     0  X
14时31分27秒     0      2581    0.80    0.20    0.00    1.00     0  gnome-shell
14时31分27秒     0    120701   69.26  100.00    0.00  100.00     2  sysbench
14时31分27秒     0    120722    0.00    0.20    0.00    0.20     1  pidstat

14时31分27秒   UID       PID    %usr %system  %guest    %CPU   CPU  Command
14时31分32秒     0      1891    0.40    0.20    0.00    0.60     0  X
14时31分32秒     0      2581    0.80    0.20    0.00    1.00     1  gnome-shell
14时31分32秒     0      6206    0.00    0.20    0.00    0.20     0  gnome-terminal-
14时31分32秒     0    120701   70.20  100.00    0.00  100.00     2  sysbench
14时31分32秒     0    120722    0.20    0.20    0.00    0.40     1  pidstat

观察vmstat结果,可以看到

  • 系统整体的cs列和in列都发生了显著的提高。
  • cpu使用率,用户进程使用率us=19% 和系统进程使用率sy=66%,加起来达到了85%,并且sy占用了大头,说明更多的cpu消耗在了运行系统进程。

观察pidstat两类结果,可以发现

  • sysbench进程下的子线程,cswsh和nvcswsh的数值都很高,其中非自愿切换次数远大于自愿切换次数。
  • %user(该进程在用户空间对cpu的使用率)和%system(该进程在系统空间对cpu的使用率)更是达到了70.20和100.00,说明系统资源大部分都被这个进程所占用。

整体结果符合我们的预期。

针对in列显著提高,可以查看 /proc/interrupts 文件,里面记录了中断相关的数据,这些数据记录的是从上次启动到现在的累加值。

我们把系统重新启动下,看下空闲状态下的文件

NMI:          0          0          0          0   Non-maskable interrupts
 LOC:      28984      32366      32128      34741   Local timer interrupts
 SPU:          0          0          0          0   Spurious interrupts
 PMI:          0          0          0          0   Performance monitoring interrupts
 IWI:        353        420        266        154   IRQ work interrupts
 RTR:          0          0          0          0   APIC ICR read retries
 RES:      24371      25023      24748      22077   Rescheduling interrupts
 CAL:       6516       7288       6917       7134   Function call interrupts
 TLB:       1706       1874       1598       1534   TLB shootdowns
 TRM:          0          0          0          0   Thermal event interrupts
 THR:          0          0          0          0   Threshold APIC interrupts
 DFR:          0          0          0          0   Deferred Error APIC interrupts
 MCE:          0          0          0          0   Machine check exceptions
 MCP:          2          2          2          2   Machine check polls
 ERR:          0
 MIS:          0
 PIN:          0          0          0          0   Posted-interrupt notification event
 NPI:          0          0          0          0   Nested posted-interrupt event
 PIW:          0          0          0          0   Posted-interrupt wakeup event

当执行sysbench命令后,并运行一段时间后,该文件如下

 NMI:          0          0          0          0   Non-maskable interrupts
 LOC:      90200      96701      93600      97704   Local timer interrupts
 SPU:          0          0          0          0   Spurious interrupts
 PMI:          0          0          0          0   Performance monitoring interrupts
 IWI:        616        666        505        450   IRQ work interrupts
 RTR:          0          0          0          0   APIC ICR read retries
 RES:    1028166    1012515    1035222    1028515   Rescheduling interrupts
 CAL:       6526       7306       6963       7134   Function call interrupts
 TLB:       1753       1946       1680       1661   TLB shootdowns
 TRM:          0          0          0          0   Thermal event interrupts
 THR:          0          0          0          0   Threshold APIC interrupts
 DFR:          0          0          0          0   Deferred Error APIC interrupts
 MCE:          0          0          0          0   Machine check exceptions
 MCP:          3          3          3          3   Machine check polls
 ERR:          0
 MIS:          0
 PIN:          0          0          0          0   Posted-interrupt notification event
 NPI:          0          0          0          0   Nested posted-interrupt event
 PIW:          0          0          0          0   Posted-interrupt wakeup event

其中,LOC和RES显著升高
RES表示,唤醒空闲状态的CPU来调度新的任务运行,和我们模拟的过多任务调度有关。

LOC不太理解,暂时先放在这里。

原文地址:https://www.cnblogs.com/ging/p/13467821.html