系统负载高,但Linux上的CPU使用率低?

2020-11-21 19:51:27

在这篇文章中,我将向您展示如何通过负载贡献者或原因来分解Linux系统负载。您也可以深入研究“成千上万的Linux系统负载”和“系统负载高,但CPU利用率低”的问题模式。

系统负载度量旨在将系统“资源需求”表示为一个数字。在经典Unix上,它仅计算对CPU的需求(处于Runnable状态的线程)

系统负载量度的单位是“进程/线程数”(或在Linux上称为调度单位的任务)。平均负载是在一段时间(最后1,5,15分钟)内平均线程数,在经典Unix上“争夺CPU”或在Linux上“争夺CPU或等待不间断的睡眠状态”

可运行状态表示“不受任何阻止”,可以在CPU上运行。该线程当前正在CPU上运行,或者在CPU运行队列中等待OS调度程序将其放入CPU

在Linux上,系统负载包括处于Runnable(R)和处于Uninterruptible sleep(D)状态的线程(通常是磁盘I / O,但并非总是如此)

因此,在Linux上,除了CPU需求外,还有许多处于不间断睡眠(D)状态的线程可能会导致负载过高。

被上述监视工具错误地标记为“可运行的进程”的系统负载跃升至3000多个!

让我们用标准操作系统级别的命令来确认这一点,以避免被监视工具误导潜在的GUI魔术:

[tanel @ linux01〜] $ w 11:49:29最多13天,13:55,2个用户,平均负载:3446.04,1242.09,450.47 USER TTY FROM LOGIN @ IDLE JCPU PCPU WHATtanel pts / 0 192.168.0.159 Thu14 21: 09m 0.05s 0.05s -bashtanel pts / 1 192.168.0.159 11:46 1.00s 0.36s 0.23sw

这是否意味着我们对CPU时间有巨大的需求? CPU运行队列中必须有很多线程,对吗?

[tanel @ linux01〜] $ sar -u 511:58:51 AM CPU%user%nice%system%iowait%steal%idle11:58:56 AM所有36.64 0.00 4.42 17.17 0.00 41.7711:59:01 AM所有41.04 0.00 3.72全部26.67 0.00 28.5711:59:06 35.38 0.00 2.95 28.39 0.00 33.27

但是CPU闲置率超过50%!将%user,%nice和%system一起添加时,CPU利用率约为40-45%。 %iowait表示CPU处于空闲状态,它恰好在空闲之前由线程在其上提交了同步I / O。

因此,在这种情况下,我们似乎没有CPU超额预定的情况。有没有一种方法可以通过测量造成此负载的因素(以及是谁)来更系统地深入研究?

是的,而且非常简单。请记住,当前系统负载只是Linux上处于R或D状态的线程(称为任务)的数量。我们可以运行ps列出这些状态下的当前线程数:

[tanel @ linux01〜] $ ps -eo s,用户| grep ^ [RD] |排序uniq -c |排序-nbr |头-20 3045 D根20 R甲骨文3 R根1 R tanel

在上面的命令ps -eo s中,用户将首先列出线程状态字段,然后列出所有其他感兴趣的字段(如用户名)。 grep ^ [RD]过滤掉各种不会影响Linux负载(S,T,t,Z,I等)的处于“空闲”和“睡眠”状态的线程。

实际上,除了共有24个处于Runnable状态(R)的线程外,似乎有3000多个处于Uninterruptible Sleep(D)状态的线程通常(但并非总是)表示由于同步磁盘IO而处于睡眠状态。它们都是root拥有的。是否有一些守护进程变得疯狂,并且所有这些活动进程/线程都试图执行IO?

让我们在ps上再增加一列,以列出命令行/程序名称:

[tanel @ linux01〜] $ ps -eo s,user,cmd | grep ^ [RD] |排序uniq -c |排序-nbr |头-20 15 R oracle oracleLIN19C(LOCAL = NO)3 D oracle oracleLIN19C(LOCAL = NO)1 R tanel ps -eo s,user,cmd 1 R根xcapture -o / backup / tanel / 0xtools / xcaplog -c exe, cmdline,kstack 1 D根[kworker / 6:99] 1 D根[kworker / 6:98] 1 D根[kworker / 6:97] 1 D根[kworker / 6:96] 1 D根[kworker / 6 :95] 1 D根[kworker / 6:94] 1 D根[kworker / 6:93] 1 D根[kworker / 6:92] 1 D根[kworker / 6:91] 1 D根[kworker / 6 :90] 1 D根[kworker / 6:9] 1 D根[kworker / 6:89] 1 D根[kworker / 6:88] 1 D根[kworker / 6:87] 1 D根[kworker / 6 :86] 1个D根[kworker / 6:85]

但是现在“根”似乎已经从顶部消失了,我们只看到顶部附近只有一些Oracle进程,而R / D活动相对较少。我的命令最后使用head -20过滤器,以避免在大多数ps输出行都是唯一的情况下打印出数千行输出,在这种情况下,所有单独的kworker线程都具有唯一的名称。它们有成千上万,每个都仅对负载摘要贡献“具有该名称的1个线程”。

如果您不希望再使用其他awk / sed命令来更好地对ps输出进行分组,则可以使用0x.tools中的pSnapper来为您完成工作。而且,它多次采样线程状态并打印活动平均值的细目分类(以避免被一个“不幸”的样本误导):

[tanel @ linux01〜] $ psnLinux进程快照程序v0.18,由Tanel Poder提供[https://0x.tools]对/ proc / stat采样5秒钟...已完成。===活动线程======= =====================================样品avg_threads |通讯|状态------------------------------------------------- ------------------ 10628 | 3542.67 | (kworker / *:*)|磁盘(不间断)37 | 12.33 | (oracle _ * _ l)|运行(CPU上)17 | 5.67 | (oracle _ * _ l)|磁盘(不间断)2 | 0.67 | (xcapture)|正在运行(CPU上)1 | 0.33 | (ora_lg * _xe)|磁盘(不间断)1 | 0.33 | (ora_lgwr_lin *)|磁盘(不间断)1 | 0.33 | (ora_lgwr_lin * c)|磁盘(不间断)样本:3(预期:100)总进程:10470,线程:11530运行时:6.13,测量时间:6.03

默认情况下,pSnapper会在汇总之前替换任务comm字段中的所有数字(comm2字段将使它们保持不变)。现在,我们可以很容易地看到我们的极端系统负载高峰是由大量kworker内核线程(“ root”作为进程所有者)引起的。因此,这不是关于在root用户下运行的某些userland守护程序,而是一个内核问题。

我将使用同一问题的另一实例(在同一台计算机上)更深入地研究此问题。这次系统负载为数百:

[tanel @ linux01〜] $ w 13:47:03最多7天,15:53、3个用户,平均负载:496.62、698.40、440.26 USER TTY LOGIN @ IDLE JCPU PCPU WHATtanel pts / 0 192.168.0.159 13:36 7:03 0.06s 0.06s -bashtanel pts / 1 192.168.0.159 13:41 7.00s 0.32s 0.23s wtanel pts / 2 192.168.0.159 13:42 3:03 0.23s 0.02s sshd:tanel [priv]

让我们再次按comm和state字段细分需求,但我还将在细分中添加当前系统调用和内核等待位置(wchan)。有了这些额外的字段,我应该使用sudo运行pSnapper,因为当以非root身份运行时,现代Linux内核版本往往会阻止对某些字段的访问(或隐藏其中的值):

[tanel @ linux01〜] $ sudo psn -G syscall,wchanLinux进程快照程序v0.18,由Tanel Poder提供[https://0x.tools]采样/ proc / syscall,stat,wchan 5秒钟...完成。== =活动线程=============================================== ===================================== avg_threads |通讯|州| syscall | chan ------------------------------------------------- -------------------------------------------------- ---------- 511 | 255.50 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | blkdev_issue_flush 506 | 253.00 | (oracle _ * _ l)|磁盘(不间断)| pread64 | do_blockdev_direct_IO 28 | 14.00 | (oracle _ * _ l)|正在运行(在CPU上)| [运行中] 0 1 | 0.50 | (集合)|正在运行(在CPU上)| [运行中] 0 1 | 0.50 | (mysqld)|正在运行(在CPU上)| [运行中] 0 1 | 0.50 | (ora_lgwr_lin * c)|磁盘(不间断)| io_submit | inode_dio_wait 1 | 0.50 | (oracle _ * _ l)|磁盘(不间断)| pread64 | 0 1 | 0.50 | (oracle _ * _ l)|正在运行(在CPU上)| [运行中] SYSC_semtimedop 1 | 0.50 | (oracle _ * _ l)|正在运行(在CPU上)| [运行中] read_events 1 | 0.50 | (oracle _ * _ l)|正在运行(在CPU上)|阅读| 0 1 | 0.50 | (oracle _ * _ l)|正在运行(在CPU上)| semtimedop | SYSC_semtimedop

在上述当前系统负载的细分中,将近一半的活动是由内核kworker线程引起的,这些线程当前在blkdev_issue_flush内核函数中睡眠,该内核函数负责内部fsync,以确保写入可持久存储。其余“接近一半”的活动线程由oracle进程在do_blockdev_direct_IO内核函数中的同步pread64系统调用中等待。

从“正在运行(CPU上运行)”行中,您还可以看到CPU的使用情况,但似乎与I / O睡眠中的数百个线程没有什么关系。

在进行这些测试时,我运行了具有1000个并发连接(有时是空闲的)的Oracle基准测试,因此可以很容易地解释在同步pread64系统调用中等待的253个会话。例如,同步单块读取可用于索引树遍历和基于索引的表块访问。但是为什么我们还会看到这么多的kworker内核线程也在等待I / O?

答案是异步I / O和针对更高级别的块设备(例如,用于LVM的设备映射器dm设备和用于软件RAID的md设备)完成的I / O。使用异步I / O,在内核内存结构中完成I / O请求的线程与提交I / O的(应用程序)线程不同。这就是内核kworker线程进入的地方,而使用LVM / dm / md设备的情况变得更加复杂(因为请求路径上有多层I / O队列)。

因此,您可以说oracle进程在pread64 syscall中处于休眠状态的253线程是同步读取,而255.5内核线程(无系统调用,因为内核代码不需要系统调用即可进入内核模式)是异步的。 I / O。

请注意,虽然像pread64这样的同步I / O等待会因为它们最终处于D状态而增加了Linux系统的负载,但是异步I / O完成检查(和IO收割)系统调用io_getevents最终会处于S状态(休眠)。由应用程序指示等待。因此,只有同步I / O操作(通过应用程序或内核线程)才有助于Linux系统负载!

此外,在成功提交IO之前,用于I / O请求异步提交的io_submit系统调用本身可能会被阻止。如果I / O队列中已经充满了不完整,未收获的I / O请求,或者在块设备的路径上较早的某个地方存在“障碍”(例如文件系统层或LVM问题),则可能会发生这种情况。在这种情况下,尽管I / O甚至没有发送到硬件,但是io_submit调用本身也会被卡住(尽管I / O具有异步性质),并且发出I / O的线程最终仍在D状态下等待。设备呢。

在高通量系统中,至少有一个Linux内核错误导致kworkers和dm / md设备的接触点出现问题,但我将在下一篇文章中介绍。

您不必猜测瓶颈在哪里,只需使用pSnapper提供的功能进行更深入的研究即可。一个典型的问题是,我们等待最多的文件或设备是什么?让我们在细分中添加文件名(或将其中包含数字的文件名合并为一个的文件名和):

[tanel @ linux01〜] $ sudo psn -G syscall,文件名总和Tanel Poder发行的Linux Process Snapper v0.18 [https://0x.tools]正在采样/ proc / syscall,状态持续5秒钟...已完成。===活动线程================================================= ================================================== ====样本| avg_threads |通讯|州| syscall | filenamesum ------------------------------------------------- -------------------------------------------------- ----------------------- 2027年| 506.75 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | 1963年| 490.75 | (oracle _ * _ l)|磁盘(不间断)| pread64 | /data/oracle/LIN*C/soe_bigfile.dbf 87 | 21.75 | (oracle _ * _ l)|正在运行(在CPU上)| [运行中] 13 | 3.25 | (kworker / *:*)|正在运行(在CPU上)| [运行中] 4 | 1.00 | (oracle _ * _ l)|正在运行(在CPU上)|阅读|套接字:[*] 2 | 0.50 | (集合)|正在运行(在CPU上)| [运行中] 1 | 0.25 | (java)|正在运行(在CPU上)| futex | 1 | 0.25 | (ora_ckpt_xe)|磁盘(不间断)| pread64 | /data/oracle/XE/control*.ctl 1 | 0.25 | (ora_m * _linprd)|正在运行(在CPU上)| [运行中] 1 | 0.25 | (ora_m * _lintes)|正在运行(在CPU上)| [运行中]

显然,系统负载现在已经增加了(处于R / D状态的活动线程超过1000个)。见证的大多数同步读取等待都针对/data/oracle/LIN*C/soe_bigfile.dbf文件(由oracle用户使用)。由于pSnapper从系统调用参数获取文件名(并在可能的情况下将文件描述符解析为文件名),因此kworker线程未显示其I / O的任何文件名-但是内核线程不需要它们的系统调用已经在内核深处运行,始终处于内核模式。但是,此字段在许多应用程序故障排除方案中很有用。

让我们深入探讨。您需要向右滚动才能查看完整图片。我已经从右至右突出了一些内容。我们也可以对线程的内核堆栈(内核线程以及用户空间应用程序线程,恰好在执行内核代码)进行采样:

[tanel @ linux01〜] $ sudo psn -p -G syscall,wchan,kstack Tanel Poder发行的Linux Process Snapper v0.18 [https://0x.tools]对/ proc / wchan,stack,syscall,stat进行采样5秒钟。 ..完成。===活动线程========================================== ================================================== ================================================== ================================================== ================================================== ================================================== ================================================== ================================样本| avg_threads |通讯|州| syscall | wchan | kstack ------------------------------------------------- -------------------------------------------------- -------------------------------------------------- -------------------------------------------------- -------------------------------------------------- -------------------------------------------------- -------------------------------------------------- --------------------------------------------- 281 | 140.50 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | blkdev_issue_flush | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> generic_write_sync()-> xfs_file_fsync()-> xfs_blkdev_issue_flush()->> 105.50 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | call_rwsem_down_read_failed | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> generic_write_sync()-> xfs_file_fsync()-> xfs_ilock()->(call_rwsem) 84.50 | (oracle _ * _ li)|磁盘(不间断)| pread64 | call_rwsem_down_write_failed | system_call_fastpath()-> SyS_pread64()-> vfs_read()-> do_sync_read()-> xfs_file_aio_read()-> xfs_file_dio_aio_read()-> touch_atime()-> update_time()-> xfs_vn_update-time(-) call_rwsem_down_write_failed()64 | 32.00 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | xfs_log_force_lsn | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> generic_write_sync()-> xfs_file_fsync()-> xfs_log_force_lsn()24 | 12.00 | (oracle _ * _ li)|磁盘(不间断)| pread64 | call_rwsem_down_read_failed | system_call_fastpath()-> SyS_pread64()-> vfs_read()-> do_sync_read()-> xfs_file_aio_read()-> xfs_file_dio_aio_read()-> __ blockdev_direct_IO()-> do_blockdev_direct_IO()-> xfs_s _> _ xfs_s xfs_ilock_data_map_shared()-> xfs_ilock()-> call_rwsem_down_read_failed()5 | 2.50 | (oracle _ * _ li)|磁盘(不间断)| pread64 | do_blockdev_direct_IO | system_call_fastpath()-> SyS_pread64()-> vfs_read()-> do_sync_read()-> xfs_file_aio_read()-> xfs_file_dio_aio_read()-> __ blockdev_direct_IO()-> do_blockdev_direct_IO()3 | 1.50 | (oracle _ * _ li)|正在运行(在CPU上)| [运行中] 0 | system_call_fastpath()-> SyS_pread64()-> vfs_read()-> do_sync_read()-> xfs_file_aio_read()-> xfs_file_dio_aio_read()-> __ blockdev_direct_IO()-> do_blockdev_direct_IO()2 | 1.00 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | call_rwsem_down_write_failed | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> xfs_end_io_direct_write()-> xfs_iomap_write_unwriter()-> xfs_ilock()-> 1.00 | (kworker / *:*)|正在运行(在CPU上)| [运行中] 0 | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> generic_write_sync()-> xfs_file_fsync()-> xfs_blkdev_issue_flush()->> 1.00 | (oracle _ * _ li)|磁盘(不间断)| io_submit | call_rwsem_down_write_failed | system_call_fastpath()-> SyS_io_submit()-> do_io_submit()-> xfs_file_aio_read()-> xfs_file_dio_aio_read()-> touch_atime()-> update_time()-> xfs_vn_update_time()->-xfs_ilock()-> xfs_ilock 0.50 | (java)|正在运行(在CPU上)| futex | futex_wait_queue_me | system_call_fastpath()-> SyS_futex()-> do_futex()-> futex_wait()-> futex_wait_queue_me()1 | 0.50 | (ksoftirqd / *)|正在运行(在CPU上)| [运行中] 0 | ret_from_fork_nospec_begin()-> kthread()-> smpboot_thread_fn()1 | 0.50 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | worker_thread | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()1 | 0.50 | (kworker / *:*)|磁盘(不间断)| [kernel_thread] | worker_thread | ret_from_fork_nospec_begin()-> kthread()-> worker_thread()-> process_one_work()-> dio_aio_complete_work()-> dio_complete()-> generic_write_sync()-> xfs_file_fsync()-> xfs_blkdev_issue_flush()->> 0.50 | (ora_lg * _xe)|磁盘(不间断)| io_submit | inode_dio_wait | system_call_fastpath()-> SyS_io_submit()-> do_io_submit()-> xfs_file_aio_write()-> xfs_file_dio_aio_write()-> inode_dio_wait()1 | 0.50 | (oracle _ * _ li)|磁盘(不间断)| [运行中] 0 | --

看来我的基准测试系统现在发生了其他问题,报告中又弹出了其他WCHAN(内核睡眠位置)值:Oracle和kworker线程都无法调用call_rwsem_down _ * _ failed,而xfs_log_force_lsn则要等待32个kworker线程。 rwsem代表“读写器信号量”,它本质上是一种低级锁定。因此,我们系统负载(D状态等待)的很大一部分是由于现在内核中的某种锁定而不是等待硬件I / O完成而导致的。

如果一直滚动并遵循内核函数调用链,那么(某种程度上)显然,当我们访问(读取和写入)文件时,我们正在等待XFS inode锁。此外,在搜索xfs_log_force_lsn函数的功能时,您会看到这是XFS日志写操作,可将XFS元数据更新持久保存到磁盘上,这样在崩溃时不会导致文件系统损坏。 XFS延迟日志记录必须排序,并且检查点必须是原子的,因此在某些情况下,一个CPU上的一个与XFS相关的kworker会阻塞其余CPU上的其他kworker(承担相同的角色)。例如,如果由于某些原因XFS日志/检查点写入太慢。 pSnapper在我的32 CPU系统上的xfs_log_force_lsn函数中恰好显示了32个线程正在等待,这可能不是巧合。

为什么我们甚至还有明显的XFS元数据生成?与ZFS不同,XFS不会在日志中记录实际数据,只是