介绍

vmstat 是一个常用的系统性能分析工具,主要用来分析系统的内存使用情况,也常用来分析 CPU 上下文切换和中断的次数。

[root@k8sm01 ~]# vmstat 5 1
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      0 2901604   2112 662652    0    0     9     2  361  438  8  3 89  0  0
  • cs(context switch)是每秒上下文切换的次数。
  • in(interrupt)则是每秒中断的次数。
  • r(Running or Runnable)是就绪队列的长度,也就是正在运行和等待 CPU 的进程数。
  • b(Blocked)则是处于不可中断睡眠状态的进程数。、

例子中的上下文切换次数 cs 是 438次,而系统中断次数 in 则是 361次,而就绪队列长度 r 是1和不可中断状态进程数 b是0,这个属于正常的

vmstat 只给出了系统总体的上下文切换情况,要想查看每个进程的详细情况,就需要使用我们前面提到过的 pidstat  了。给它加上 -w 选项,你就可以查看每个进程上下文切换的情况了。

比如说:

每隔5秒输出1组数据
[root@k8sm01 ~]# pidstat -w 5
Linux 3.10.0-1062.el7.x86_64 (k8sm01.com) 	2020年06月20日 	_x86_64_	(2 CPU)

20时22分19秒   UID       PID   cswch/s nvcswch/s  Command
20时22分24秒     0         1      1.20      0.00  systemd
20时22分24秒     0         6      1.00      0.00  ksoftirqd/0
20时22分24秒     0         7      0.20      0.00  migration/0
20时22分24秒     0         9      7.98      0.00  rcu_sched
20时22分24秒     0        11      0.40      0.00  watchdog/0
20时22分24秒     0        12      0.40      0.00  watchdog/1
20时22分24秒     0        14      0.40      0.00  ksoftirqd/1
20时22分24秒     0        37      0.20      0.00  khugepaged
20时22分24秒     0       103      0.60      0.00  kauditd
20时22分24秒     0       476     19.76      0.00  xfsaild/dm-0
20时22分24秒     0       477      0.20      0.00  kworker/0:1H
20时22分24秒     0       557      1.80      0.00  systemd-journal
20时22分24秒     0      1193      0.60      0.00  auditd
20时22分24秒     0      1223      1.60      0.00  rngd
20时22分24秒     0      1231      1.00      0.00  abrt-watch-log
20时22分24秒    81      1242      0.80      0.00  dbus-daemon
20时22分24秒     0      1254     10.18      0.00  vmtoolsd
20时22分24秒     0      1255      0.40      0.00  systemd-logind
20时22分24秒     0     54195      1.60      0.00  kworker/u256:0
20时22分24秒     0     58332      0.80      0.00  kworker/0:0
20时22分24秒     0     58892      1.00      0.00  sshd
20时22分24秒     0     59419      1.00      0.00  vmstat
20时22分24秒     0     60107      6.79      0.00  kworker/0:1
20时22分24秒     0     60399      1.80      0.00  kworker/1:0
20时22分24秒     0     60460      0.20      0.00  pidstat

这个结果中有两列内容是我们的重点关注对象。一个是  cswch  ,表示每秒自愿上下文切换(voluntary context switches)的次数,另一个则是  nvcswch  ,表示每秒非自愿上下文切换(non voluntary context switches)的次数。

  • 所谓自愿上下文切换,是指进程无法获取所需资源,导致的上下文切换。比如说, I/O、内存等系统资源不足时,就会发生自愿上下文切换。
  • 而非自愿上下文切换,则是指进程由于时间片已到等原因,被系统强制调度,进而发生的上下文切换。比如说,大量进程都在争抢 CPU 时,就容易发生非自愿上下文切换。

案例分析

知道了怎么查看这些指标,另一个问题又来了,上下文切换频率是多少次才算正常呢?别急着要答案,同样的,我们先来看一个上下文切换的案例。通过案例实战演练,你自己就可以分析并找出这个标准了。

sysbench 进行演练

sysbench 是一个多线程的基准测试工具,一般用来评估不同系统参数下的数据库负载情况。当然,在这次案例中,我们只把它当成一个异常进程来看,作用是模拟上下文切换过多的问题。

安装一下sysbench

yum -y install sysbench sysstat

 vmstat 看一下空闲系统的上下文切换次数:

[root@k8sm01 ~]# vmstat  1 1
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      0 2887904   2112 682868    0    0     8     2  362  558  8  4 88  0  0

r等待进程1 ,b不可中断为0 ,in中断的次数362 cs上下切换文558,然而每次查询都是不一样的

通过TTY1 使用sysbench 来对CPU压测

sysbench --threads=10 --max-time=300 threads run#解释以10个线程运行5分钟的基准测试,模拟多线程切换的问题

[root@k8sm01 ~]# sysbench --threads=10 --max-time=300 threads run
WARNING: --max-time is deprecated, use --time instead
sysbench 1.0.17 (using system LuaJIT 2.0.4)

Running the test with following options:
Number of threads: 10
Initializing random number generator from current time


Initializing worker threads...

Threads started!

TTY2 运行 vmstat 1 6 

root@k8sm01 ~]# vmstat 1 6
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      0 2872208   2112 682968    0    0     8     2  361  588  8  4 88  0  0
 7  0      0 2885448   2112 682972    0    0     0     0 2050 1092829 31 69  0  0  0
 6  0      0 2885448   2112 682972    0    0     0     0  891 1095710 28 72  0  0  0
 5  0      0 2885448   2112 682972    0    0     0     0 1513 1150741 32 68  1  0  0
 7  0      0 2885448   2112 682972    0    0     0     0 2058 1130966 31 69  0  0  0
 5  0      0 2885448   2112 682972    0    0     0    12 2022 1063513 31 69  0  0  0

通过数据可以查看到:

  • r就绪队列已经到持续变化比在空闲状态下多好几个
  • b不可终端队列还是0
  • in中断次数也随之增大
  • cs上下文切换已经达到了百万

综合这几个指标,我们可以知道,系统的就绪队列过长,也就是正在运行和等待 CPU 的进程数过多,导致了大量的上下文切换,而上下文切换又导致了系统 CPU 的占用率升高。

那么什么原因导致这种问题呢?还需要继续分析,pidstat 来看一下, CPU 和进程上下文切换的情况:

[root@k8sm01 ~]# pidstat  -w -u 1 1
## -w参数表示输出进程切换指标,而-u参数则表示输出CPU使用指标 
Linux 3.10.0-1062.el7.x86_64 (k8sm01.com) 	2020年06月20日 	_x86_64_	(2 CPU)

20时40分01秒   UID       PID    %usr %system  %guest    %CPU   CPU  Command
20时40分02秒     0       476    0.00    0.97    0.00    0.97     0  xfsaild/dm-0
20时40分02秒     0     61336   50.49  100.00    0.00  100.00     0  sysbench
20时40分02秒     0     61359    0.00    0.97    0.00    0.97     0  pidstat

20时40分01秒   UID       PID   cswch/s nvcswch/s  Command
20时40分02秒     0         1      7.77      0.00  systemd
20时40分02秒     0         6      2.91      0.00  ksoftirqd/0
20时40分02秒     0         9     15.53      0.00  rcu_sched
20时40分02秒     0       103      1.94      0.00  kauditd
20时40分02秒     0       476     19.42      0.00  xfsaild/dm-0
20时40分02秒     0      1193      1.94      0.00  auditd
20时40分02秒     0      1231      0.97      0.00  abrt-watch-log
20时40分02秒   999      1235      4.85      0.00  polkitd
20时40分02秒    81      1242     16.50      0.00  dbus-daemon
20时40分02秒     0      1250      2.91      0.00  NetworkManager
20时40分02秒     0      1254      9.71      0.00  vmtoolsd
20时40分02秒     0      1255      6.80      0.00  systemd-logind
20时40分02秒     0      1259      0.97      0.00  crond
20时40分02秒     0     54195      2.91      0.00  kworker/u256:0
20时40分02秒     0     60107      6.80      0.00  kworker/0:1
20时40分02秒     0     60954      2.91      0.00  kworker/1:0
20时40分02秒     0     61359      0.97      2.91  pidstat

平均时间:   UID       PID    %usr %system  %guest    %CPU   CPU  Command
平均时间:     0       476    0.00    0.97    0.00    0.97     -  xfsaild/dm-0
平均时间:     0     61336   50.49  100.00    0.00  100.00     -  sysbench
平均时间:     0     61359    0.00    0.97    0.00    0.97     -  pidstat

平均时间:   UID       PID   cswch/s nvcswch/s  Command
平均时间:     0         1      7.77      0.00  systemd
平均时间:     0         6      2.91      0.00  ksoftirqd/0
平均时间:     0         9     15.53      0.00  rcu_sched
平均时间:     0       103      1.94      0.00  kauditd
平均时间:     0       476     19.42      0.00  xfsaild/dm-0
平均时间:     0      1193      1.94      0.00  auditd
平均时间:     0      1231      0.97      0.00  abrt-watch-log
平均时间:   999      1235      4.85      0.00  polkitd
平均时间:    81      1242     16.50      0.00  dbus-daemon
平均时间:     0      1250      2.91      0.00  NetworkManager
平均时间:     0      1254      9.71      0.00  vmtoolsd
平均时间:     0      1255      6.80      0.00  systemd-logind
平均时间:     0      1259      0.97      0.00  crond
平均时间:     0     54195      2.91      0.00  kworker/u256:0
平均时间:     0     60107      6.80      0.00  kworker/0:1
平均时间:     0     60954      2.91      0.00  kworker/1:0
平均时间:     0     61359      0.97      2.91  pidstat
参数解释 
-w     Report task switching activity (kernels 2.6.23 and later only).  The following values may be displayed:

              UID
                     The real user identification number of the task being monitored.

              USER
                     The name of the real user owning the task being monitored.

              PID
                     The identification number of the task being monitored.

              cswch/s
                     Total  number  of voluntary context switches the task made per second.  A voluntary context switch occurs when a task blocks because it requires a resource that is
                     unavailable.

              nvcswch/s
                     Total number of non voluntary context switches the task made per second.  A involuntary context switch takes place when a task executes for  the  duration  of  its
                     time slice and then is forced to relinquish the processor.

              Command
                     The command name of the task.

 从 pidstat 的输出你可以发现,CPU 使用率的升高果然是 sysbench 导致的,它的 CPU 使用率已经达到了 100%。但上下文切换则是来自其他进程,包括非自愿上下文切换频率最高的 pidstat  ,以及自愿上下文切换频率最高的内核线程 kworker 和 sshd。

但是也可以看出自愿切换和非自愿切换累计和与通过vmstat 的cs 相差甚远,是因为pidstat 默认只查看进程状态,如果想查看线程状态需要加 -t参数

[root@k8sm01 ~]# pidstat  -wt  1 1
Linux 3.10.0-1062.el7.x86_64 (k8sm01.com) 	2020年06月20日 	_x86_64_	(2 CPU)

20时45分50秒   UID      TGID       TID   cswch/s nvcswch/s  Command
20时45分51秒     0         9         -     12.73      0.00  rcu_sched
20时45分51秒     0         -         9     12.73      0.00  |__rcu_sched
20时45分51秒     0        14         -      3.64      0.00  ksoftirqd/1
20时45分51秒     0         -        14      3.64      0.00  |__ksoftirqd/1
20时45分51秒     0       476         -     19.09      0.00  xfsaild/dm-0
20时45分51秒     0         -       476     19.09      0.00  |__xfsaild/dm-0
20时45分51秒     0      1223         -      0.91      0.00  rngd
20时45分51秒     0         -      1223      0.91      0.00  |__rngd
20时45分51秒     0         -      1271      0.91      0.00  |__gmain
20时45分51秒     0      1254         -     10.00      0.00  vmtoolsd
20时45分51秒     0         -      1254     10.00      0.00  |__vmtoolsd
20时45分51秒     0         -      2417      0.91      0.00  |__tuned
20时45分51秒     0         -      1553      0.91      0.00  |__in:imjournal
20时45分51秒     0         -      1727     18.18      0.00  |__containerd
20时45分51秒     0         -      1759      9.09      0.00  |__containerd
20时45分51秒     0         -      1774      9.09      0.00  |__containerd
20时45分51秒     0         -      1775      9.09      0.00  |__containerd
20时45分51秒     0         -     11810      9.09      0.00  |__containerd
20时45分51秒     0         -      1769      1.82      0.00  |__dockerd
20时45分51秒     0         -      1771      0.91      0.00  |__dockerd
20时45分51秒     0         -      1870      0.91      0.00  |__dockerd
20时45分51秒     0         -      1961      0.91      0.00  |__dockerd
20时45分51秒     0         -      2373      0.91      0.00  |__dockerd
20时45分51秒     0     54195         -      1.82      0.00  kworker/u256:0
20时45分51秒     0         -     54195      1.82      0.00  |__kworker/u256:0
20时45分51秒     0     60107         -      0.91      0.00  kworker/0:1
20时45分51秒     0         -     60107      0.91      0.00  |__kworker/0:1
20时45分51秒     0     60954         -      1.82      0.00  kworker/1:0
20时45分51秒     0         -     60954      1.82      0.00  |__kworker/1:0
20时45分51秒     0     61174         -      5.45      0.00  kworker/0:3
20时45分51秒     0         -     61174      5.45      0.00  |__kworker/0:3
20时45分51秒     0         -     61630  19871.82  82722.73  |__sysbench
20时45分51秒     0         -     61631  17259.09  88833.64  |__sysbench
20时45分51秒     0         -     61632  23207.27  81586.36  |__sysbench
20时45分51秒     0         -     61633  20784.55  75927.27  |__sysbench
20时45分51秒     0         -     61634  18183.64  91010.91  |__sysbench
20时45分51秒     0         -     61635  28891.82  65432.73  |__sysbench
20时45分51秒     0         -     61636  18662.73  78239.09  |__sysbench
20时45分51秒     0         -     61637  17892.73  74092.73  |__sysbench
20时45分51秒     0         -     61638  24624.55  85162.73  |__sysbench
20时45分51秒     0         -     61639  16970.00  86606.36  |__sysbench
20时45分51秒     0     61640         -      0.91      3.64  pidstat
20时45分51秒     0         -     61640      0.91      3.64  |__pidstat

平均时间:   UID      TGID       TID   cswch/s nvcswch/s  Command
平均时间:     0         9         -     12.73      0.00  rcu_sched
平均时间:     0         -         9     12.73      0.00  |__rcu_sched
平均时间:     0        14         -      3.64      0.00  ksoftirqd/1
平均时间:     0         -        14      3.64      0.00  |__ksoftirqd/1
平均时间:     0       476         -     19.09      0.00  xfsaild/dm-0
平均时间:     0         -       476     19.09      0.00  |__xfsaild/dm-0
平均时间:     0      1223         -      0.91      0.00  rngd
平均时间:     0         -      1223      0.91      0.00  |__rngd
平均时间:     0         -      1271      0.91      0.00  |__gmain
平均时间:     0      1254         -     10.00      0.00  vmtoolsd
平均时间:     0         -      1254     10.00      0.00  |__vmtoolsd
平均时间:     0         -      2417      0.91      0.00  |__tuned
平均时间:     0         -      1553      0.91      0.00  |__in:imjournal
平均时间:     0         -      1727     18.18      0.00  |__containerd
平均时间:     0         -      1759      9.09      0.00  |__containerd
平均时间:     0         -      1774      9.09      0.00  |__containerd
平均时间:     0         -      1775      9.09      0.00  |__containerd
平均时间:     0         -     11810      9.09      0.00  |__containerd
平均时间:     0         -      1769      1.82      0.00  |__dockerd
平均时间:     0         -      1771      0.91      0.00  |__dockerd
平均时间:     0         -      1870      0.91      0.00  |__dockerd
平均时间:     0         -      1961      0.91      0.00  |__dockerd
平均时间:     0         -      2373      0.91      0.00  |__dockerd
平均时间:     0     54195         -      1.82      0.00  kworker/u256:0
平均时间:     0         -     54195      1.82      0.00  |__kworker/u256:0
平均时间:     0     60107         -      0.91      0.00  kworker/0:1
平均时间:     0         -     60107      0.91      0.00  |__kworker/0:1
平均时间:     0     60954         -      1.82      0.00  kworker/1:0
平均时间:     0         -     60954      1.82      0.00  |__kworker/1:0
平均时间:     0     61174         -      5.45      0.00  kworker/0:3
平均时间:     0         -     61174      5.45      0.00  |__kworker/0:3
平均时间:     0         -     61630  19871.82  82722.73  |__sysbench
平均时间:     0         -     61631  17259.09  88833.64  |__sysbench
平均时间:     0         -     61632  23207.27  81586.36  |__sysbench
平均时间:     0         -     61633  20784.55  75927.27  |__sysbench
平均时间:     0         -     61634  18183.64  91010.91  |__sysbench
平均时间:     0         -     61635  28891.82  65432.73  |__sysbench
平均时间:     0         -     61636  18662.73  78239.09  |__sysbench
平均时间:     0         -     61637  17892.73  74092.73  |__sysbench
平均时间:     0         -     61638  24624.55  85162.73  |__sysbench
平均时间:     0         -     61639  16970.00  86606.36  |__sysbench
平均时间:     0     61640         -      0.91      3.64  pidstat
平均时间:     0         -     61640      0.91      3.64  |__pidstat

现在你就能看到了,虽然 sysbench 进程(也就是主线程)的上下文切换次数看起来并不多,但它的子线程的上下文切换次数却有很多。看来,上下文切换罪魁祸首,还是过多的 sysbench 线程。

我们已经找到了上下文切换次数增多的根源,那是不是到这儿就可以结束了呢?当然不是。不知道你还记不记得,前面在观察系统指标时,除了上下文切换频率骤然升高,还有一个指标也有很大的变化。是的,正是中断次数。中断次数也上升到了 1 万,但到底是什么类型的中断上升了,现在还不清楚。我们接下来继续抽丝剥茧找源头。既然是中断,我们都知道,它只发生在内核态,而 pidstat 只是一个进程的性能分析工具,并不提供任何关于中断的详细信息,怎样才能知道中断发生的类型呢?没错,那就是从 /proc/interrupts 这个只读文件中读取。/proc 实际上是 Linux 的一个虚拟文件系统,用于内核空间与用户空间之间的通信。/proc/interrupts 就是这种通信机制的一部分,提供了一个只读的中断使用情况。 

TTY3运行:watch -d cat /proc/interrupts

[root@k8sm01 ~]# watch -d cat /proc/interrupts
 RES:   27245756   28452908   Rescheduling interru
#这个值还需待研究,目测如果cs 大的话,这个值会迅速增长,反之增长会变慢

 观察一段时间,你可以发现,变化速度最快的是重调度中断(RES),这个中断类型表示,唤醒空闲状态的 CPU 来调度新的任务运行。这是多处理器系统(SMP)中,调度器用来分散任务到不同 CPU 的机制,通常也被称为处理器间中断(Inter-Processor Interrupts,IPI)。所以,这里的中断升高还是因为过多任务的调度问题,跟前面上下文切换次数的分析结果是一致的。

现在再回到最初的问题,每秒上下文切换多少次才算正常呢?

这个数值其实取决于系统本身的 CPU 性能。在我看来,

如果系统的上下文切换次数比较稳定,那么从数百到一万以内,都应该算是正常的。

但当上下文切换次数超过一万次,或者切换次数出现数量级的增长时,就很可能已经出现了性能问题。这时,你还需要根据上下文切换的类型,再做具体分析。比方说:

  • 自愿上下文切换变多了,说明进程都在等待资源,有可能发生了 I/O 等其他问题;
  • 非自愿上下文切换变多了,说明进程都在被强制调度,也就是都在争抢 CPU,说明 CPU 的确成了瓶颈;
  • 中断次数变多了,说明 CPU 被中断处理程序占用,还需要通过查看 /proc/interrupts 文件来分析具体的中断类型。

小结

今天,我通过一个 sysbench 的案例,给你讲了上下文切换问题的分析思路。碰到上下文切换次数过多的问题时,我们可以借助 vmstat  、  pidstat 和 /proc/interrupts 等工具,来辅助排查性能问题的根源

  • 过多上下文切换会缩短进程运行时间
  • vmstat 1 1:分析内存使用情况、cpu上下文切换和中断的次数。cs每秒上下文切换的次数,in每秒中断的次数,r运行或等待cpu的进程数,b中断睡眠状态的进程数。
  • pidstat -w 5:查看每个进程详细情况。cswch(每秒自愿)上下文切换次数,如系统资源不足导致,nvcswch每秒非自愿上下文切换次数,如cpu时间片用完或高优先级线程
  • 案例分析:
  • sysbench:多线程的基准测试工具,模拟context switch
  • 终端1:sysbench --threads=10 --max-time=300 threads run
  • 终端2:vmstat 1:sys列占用84%说明主要被内核占用,ur占用16%;r就绪队列8;in中断处理1w,cs切换139w==>等待进程过多,频繁上下文切换,内核cpu占用率升高
  • 终端3:pidstat -w -u 1:sysbench的cpu占用100%(-wt发现子线程切换过多),其他进程导致上下文切换
  • watch -d cat /proc/interupts :查看另一个指标中断次数,在/proc/interupts中读取,发现重调度中断res变化速度最快
  • 总结:cswch过多说明资源IO问题,nvcswch过多说明调度争抢cpu过多,中断次数变多说明cpu被中断程序调用

 

闲杂人等