c - 周期性高内核 CPU 负载？

Question

对于通常使用很少 CPU 的程序来说，内核 CPU 非常高。 Linux 机器在状态之间交替。大多数时候，程序使用低 CPU 正常执行。在 CPU“激增”期间，程序使用 100% 可用 CPU 使用高内核 CPU。
下面的示例 C 程序和输出。
机器大约每五分钟进出一个奇怪的状态，其中一些(但不是全部)程序使用高内核 CPU。 CPU“浪涌”可能会持续一分钟，然后机器会再恢复正常状态 5-10 分钟。重新启动有时会有所帮助，但浪涌会在一周内逐渐增加，直到问题变得严重到需要再次重新启动。有时重新启动没有帮助，唯一的临时解决方法是尝试再次重新启动。

CentOS 6.9 版

带 14 个 CPU、32 GB 内存的戴尔 PowerEdge R630

Linux 2.6.32-696.30.1.el6.x86_64 x86_64

我能够使用此示例 C 程序重现 CPU 问题。它运行一个执行 sleep 的 shell 脚本。 0.01 秒并打印 10 次迭代中的每一次的运行时间。机器正常时运行快，机器异常时运行慢。
test_system.c

#include <stdio.h>
#include <stdlib.h>

int main(int argc, char *argv[])
{
    int i, n;
    char cmd[100];

    if (argc == 2) {
        n = atoi(argv[1]);
    }
    else {
        n = 1;
    }

    printf("n=%d\n", n);

    for (i=0; i<n; i++) {
        system("ts=$(date +%s%N) ; sleep 0.01 ; tt=$((($(date +%s%N) - $ts)/1000000)) ; echo \"Time taken: $tt milliseconds\"");
    }
}

这是机器处于正常状态时的输出。大多数 CPU 都在用户空间中。

$ time test_system 10
n=10
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds
Time taken: 12 milliseconds

real    0m0.210s
user    0m0.059s
sys     0m0.015s
$

这是机器遇到 CPU“浪涌”模式时的输出。我在出现两次长时间停顿的地方添加了评论。延迟是由于机器 CPU 过载造成的。运行时间为 35.6 秒，比正常时间长 170 倍。这次运行的内核 CPU 使用率为 7.2 秒，比正常运行增加了 480 倍。

$ time test_system 10
n=10
Time taken: 161 milliseconds
Time taken: 406 milliseconds
Time taken: 58 milliseconds
Time taken: 176 milliseconds
Time taken: 189 milliseconds
--- approx. 17 sec delay ---
Time taken: 25 milliseconds
Time taken: 127 milliseconds
Time taken: 82 milliseconds
Time taken: 84 milliseconds
Time taken: 12 milliseconds
--- approx. 17 sec delay ---

real    0m35.641s
user    0m0.077s
sys     0m7.233s
$

这个 post建议为 I/O 缓冲区分配的内存过多会导致此问题，因为内核必须努力回收内存才能运行程序。但没有迹象表明内存交换或短缺。我进行了分配 100 MB 内存的单独测试，即使在 CPU 激增期间也没有看到延迟或高 CPU。
关于什么可能导致这种行为的任何其他建议？
这是我最新的测试程序 fork()和 exec()分别地。
test_fork.c

#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>
#include <unistd.h>
#include <assert.h>

#define ELAPSED_USEC(t1, t2)  (SEC2USEC((t2).tv_sec - (t1).tv_sec) + (t2).tv_usec - (t1).tv_usec)
#define SEC2USEC(sec)         ((sec)*1000000)


int main(int argc, char *argv[])
{
    int i, n;
    struct timeval start_time, end_time;
    struct timezone tz;
    pid_t pid;
    char *shell = "/bin/bash";
    char *shell_cmd;
    int status;

    if (argc == 3) {
        n = atoi(argv[1]);
        shell_cmd = argv[2];
    }
    else {
        fprintf(stderr, "Usage: %s count shell_cmd\n", argv[0]);
        exit(1);
    }

    printf("n=%d shell_cmd=[%s]\n", n, shell_cmd);

    for (i=0; i<n; i++) {
        gettimeofday(&start_time, &tz);
        pid = fork();
        if (pid == -1)
        {   
            fprintf(stderr, "fork failed.\n");
            exit(1);
        }
        else if (pid > 0)
        {   
            gettimeofday(&end_time, &tz);
            printf("fork: %ld usec, ", ELAPSED_USEC(start_time, end_time));

            gettimeofday(&start_time, &tz);
            waitpid(pid, &status, 0);
            gettimeofday(&end_time, &tz);
            printf("exec: %ld msec\n", ELAPSED_USEC(start_time, end_time)/1000);  // 1 msec = 1000 usec
            //assert(WEXITSTATUS(status) == 123);
        }
        else
        {
            // we are the child
            execl(shell, shell, "-c", shell_cmd, NULL);
            _exit(EXIT_FAILURE);   // exec never returns
        }
    }
}

以下是机器处于浪涌状态时的一些示例输出。仅限 exec()使用额外的 CPU。

$ test_fork 10 'exit 123'
n=10 shell_cmd=[exit 123]
fork: 41 usec, exec: 1 msec
fork: 46 usec, exec: 46586 msec
fork: 57 usec, exec: 1 msec
fork: 46 usec, exec: 12 msec
fork: 50 usec, exec: 112 msec
fork: 50 usec, exec: 1 msec
fork: 46 usec, exec: 2 msec
fork: 43 usec, exec: 1 msec
fork: 40 usec, exec: 18 msec
fork: 71 usec, exec: 1 msec

real    0m46.741s
user    0m0.005s
sys     0m13.999s
$

Answer 1

安装 dTrace并在您的系统遇到减速时运行类似于以下 dTrace 脚本的内容:

#!/usr/sbin/dtrace -s

#pragma D option quiet

profile:::profile-1001hz
/ arg0 /
{
    @hot[ arg0 ] = count();
}

dtrace:::END
{
    printa( "%@u %a\n", @hot );
}

您可能必须更改shebang。
当系统出现其中一个“情节”时运行它(可能根据您问题中的一个时间测试程序自动启动)，让它运行 10-15 秒(取出 #pragma D option quiet 如果你想看一些细节)，用 CTRL-C杀死它从键盘或 SIGINT从一个过程。
然后，该脚本将发出它采样的所有内核堆栈跟踪，最常见的最后出现 - 您可以在其中看到它们。
最后几个内核堆栈跟踪将 告诉你内核在哪里花费时间在“情节”期间。
不涉及猜测。没有复活节彩蛋狩猎。你得到 告诉 这是怎么回事。
该脚本在 Solaris 11.4 机器上运行 zfs send ... | ... zfs receive ...备份，显示如下:

   .
   .
   .
1729 zfs`zfs_lzjb_compress+0xcd
1834 zfs`zfs_lzjb_compress+0xe8
1883 zfs`zfs_lzjb_compress+0xf1
1991 zfs`zfs_lzjb_compress+0xbc
1994 unix`wrmsr+0xd
2015 unix`sys_syscall+0x1b9
2089 zfs`zfs_lzjb_compress+0x131
2182 zfs`zfs_lzjb_compress+0x115
2346 zfs`zfs_lzjb_compress+0x1bd
2363 zfs`zfs_lzjb_compress+0x93
2376 zfs`zfs_lzjb_compress+0x1a6
2869 unix`mutex_enter+0x10
3619 zfs`zfs_lzjb_compress+0x135
4223 zfs`zfs_lzjb_compress+0x108
5982 unix`mutex_delay_default+0xa
7480 unix`mutex_delay_default+0x7
8548 unix`bcopy+0x55a
3148971 unix`i86_mwait+0xd

请注意，在这个例子中，绝大多数时间(三个数量级......)都花在空闲循环中，因为它是一个 24 核服务器，目前除了 zfs 之外什么都不做。备份。几乎所有其他注意事项都涉及该备份。