问题概述

前段时间在对系统进行性能测试的时候，我们遇到了一个SPECjvm2008的问题。先介绍下，SPECjvm2008是当前测试JVM（Java虚拟机，Java Virtual Machine）性能最常见的工具，它由多个测试用例组成。另外，SPECjvm2008还是一个开源软件，因此在发生问题的时候是可以结合它的源码进行联合诊断的。

当时遇到的问题是在SPECjvm2008里有一个测试用例叫startup.compiler.sunflow，在运行这个测试用例的时候，SPECjvm2008会停止在测试中途，当时等了两天SPECjvm2008仍处于暂停状态，没有任何运行下去的迹象。

问题分析

解决问题的第一个步骤就是要重现问题，如果不能重现问题，首先是难以找到问题的症结所在，其次是即使自以为解决了问题，由于无法重现问题，也难以进行验证。

在此处，其测试用例的运行方法是进入SPECjvm2008的安装目录，然后运行：

java -jar SPECjvm2008.jar -ikv startup.compiler.sunflow

运行的结果如下（有部分删节）：

SPECjvm2008 Base
  Properties file:   none
  Benchmarks:        startup.compiler.sunflow

--- --- --- --- --- --- --- --- ---

  Benchmark:   check
  Run mode:    static run
  Test type:   functional
  Threads:     1
  Iterations:  1
  Run length:  1 operation

Iteration 1 (1 operation) begins: Sun Aug 12 11:42:14 SGT 2018
Iteration 1 (1 operation) ends:   Sun Aug 12 11:42:15 SGT 2018
Iteration 1 (1 operation) result: PASSED

Valid run!

--- --- --- --- --- --- --- --- ---

  Benchmark:   startup.compiler.sunflow
  Run mode:    static run
  Test type:   single
  Threads:     1
  Iterations:  1
  Run length:  1 operation

Iteration 1 (1 operation) begins: Sun Aug 12 11:42:15 SGT 2018

此时已经进入了暂停状态，因此我们可以再开一个终端，检查对应的进程信息。首先需要通过ps得到进程号与进程状态，如下：

raphael@sigma:~/specjvm2008$ ps aux | grep --color java
raphael   2910  0.2  2.8 2387284 54540 pts/0   Sl+  11:42   0:01 java -jar SPECjvm2008.jar -ikv startup.compiler.sunflow
raphael   2924  2.2  7.8 2388288 151748 pts/0  Sl+  11:42   0:11 /usr/lib/jvm/java-8-openjdk-amd64/jre/bin/java -classpath SPECjvm2008.jar -Dspecjvm.home.dir=. spec.harness.Launch -bt 1 -ops 1 -crf false -ict -icsv -ss SMALL compiler.sunflow
raphael   2957  0.0  0.0  14532  1020 pts/1    S+   11:50   0:00 grep --color java

可以看到对应的原始进程的进程号是2910，状态为Sl+，直接测试进程的进程号是2924，状态为Sl+。首先可以明确的是进程状态为Sl+表示此进程处于休眠状态（S，即进程陷入了内核态未返回，但是可以接收信号，如果是D的话则表示陷入了内核态未返回，而且不能接受信号，如果是R的话表示仍处于用户态可运行状态），多线程（l），而且是前台进程（+）。以上状态可以通过man ps得到。

既然进程陷入了内核未返回，则可以通过/proc/#pid/syscall得到对应陷入内核前调用的系统调用信息。此时我们运行cat /proc/2924/syscall可以看到如下信息：

202 0x7f88e22509d0 0x0 0xb6e 0x0 0xca 0x7f88e22509d0 0x7ffd018c7690 0x7f88e1e3f6bd

通过man proc得知，上述文件中第一个202表示对应的系统调用号（syscall number），其后六个参数表示对应的系统调用参数的寄存器信息，最后两个参数表示应用程序用户态对应线程的栈指针与指令寄存器值。

要想得知系统调用号对应的系统调用名称，可以查找对应架构的unistd.h头文件，例如我们测试的机器架构为x86_64，那么可以打开unistd_64.h，查找202。如果希望通过命令直接查找，可以安装auditd包，运行ausyscall即可，如下：

raphael@sigma:~/specjvm2008$ sudo apt-get install auditd
raphael@sigma:~/specjvm2008$ ausyscall 202
futex

可以看到在x86_64架构下，202号系统调用即为futex。但是futex是一个非常常用的系统调用，被广泛用于pthread库同步机制的实现，以及POSIX信号量的实现等诸多地方，因此仅仅得知进程调用futex陷入了内核只能得知进程在等待某个共享锁，这其实是进程陷入S状态最常见的情况，但是在这里难以判断是谁导致的共享锁被占用，从而使得进程进入等待状态，也难以解决问题。

此时，我们可以尝试查看下此进程的各个线程，首先各个进程的线程可以通过ls /proc/#pid/task得到，然后通过对每个线程进行/proc/#pid/syscall的查看，可以发现某个线程的syscall不再是futex了，如下：

raphael@sigma:~/specjvm2008$ ls /proc/2924/task
2924  2926  2928  2929  2930  2931  2932  2933  2934  2935  2936  2937
raphael@sigma:~/specjvm2008$ cat /proc/2937/syscall
1 0x2 0x7f88dcd6fa60 0x1c 0x46 0x7f88dcd6fa60 0xec901d70 0x7f88dcd6f9f0 0x7f88e1e471ed

此时2937号线程陷入了1号系统调用，经过ausyscall可以知道1号系统调用即为write。而man write可以得知其需要三个参数，分别是文件描述符、待写入的缓存区指针，以及对应缓存区的大小。在这里文件描述符为2（0x2），缓存区指针是0x7f88dcd6fa60，缓存区大小是28（0x1c）。而2号文件描述符是标准错误输出（stderr），可见2937号线程调用write向标准错误输出输出的时候没有返回，这是一个比较少见的情况。我们可以继续深入下内核看看是怎么回事，如下：

raphael@sigma:~/specjvm2008$ cat /proc/2937/stack
[<ffffffff811e092c>] pipe_wait+0x6c/0xb0
[<ffffffff810b6a20>] autoremove_wake_function+0x0/0x40
[<ffffffff811e0a90>] pipe_write+0xc0/0x3f0
[<ffffffff811d8284>] new_sync_write+0xa4/0xf0
[<ffffffff811d8c34>] vfs_write+0xa4/0x1a0
[<ffffffff811d98c2>] SyS_write+0x52/0xc0
[<ffffffff81593d32>] system_call_fast_compare_end+0xc/0x67
[<ffffffffffffffff>] 0xffffffffffffffff70

可以发现在内核里进程被pipe_wait/pipe_write堵塞住了，即在写管道的时候被堵塞了。那么，究竟什么情况会导致进程向stderr写数据，但是被管道堵住了呢？比较常见的显然是进程的stderr被重定向了，而且被重定向的stder管道没有被读取，或者读取速度过慢导致了进程被堵塞，而父进程应该是没有读取stderr，但是又在等待程序运行完毕，形成了一个死锁，所以造成了测试程序无法继续运行下去。

下面，我们还可以看看0x7f88dcd6fa60对应的具体是什么数据。我们当然可以通过gdb进入进程查看数据，不过还有更轻量级的方法，那就是读取/proc/#pid/mem文件。这个文件对应的是进程的内存地址空间的所有内存的内容，读取这个虚拟文件即可获取到对应的进程内存数据。

不过如果你直接读取此文件会得到如下的错误：

raphael@sigma:~/specjvm2008$ cat /proc/2937/mem 
cat: /proc/2937/mem: 输入/输出错误

请注意，这并不是权限错误，换了root来cat此文件一样会发生上述错误。要是大家对C语言编程与进程的地址空间有了解，就可以知道，虚拟文件的首字节显然对应的就是进程地址空间中地址为0的内存。但是我们都知道，进程地址空间中从0开始的一大段地址都是不可访问的，因此，如果直接读取mem文件的开始数据，对应其实就是访问了进程地址空间从0开始的对应地址空间，由于这段地址没有做任何映射，当然会产生访问错误了。

因此，读取mem文件只能使用open、lseek、read的方式进行。由于hexdump -s在此处不适用（大家可以试下想想为什么），因此可以写一个简单的C程序即可，如下：

raphael@sigma:~/specjvm2008$ ./rd /proc/2937/mem 140225797356128 28
[28(max 28)]: '建议升级此编译器。
'

可以看到2937号进程正在试图向stderr输出“建议升级此编译器”的字样。

因此，本次SPECjvm2008事件的原因基本已经清楚了：

1. 父进程启动子进程进行编译（毕竟此测试用例是compiler.sunflow）；
2. 父进程重定向了子进程的stderr，但是没有读取子进程的stderr，并使用futex等待子进程结束；
3. 子进程在编译过程中产生了大量的警告信息，通过stderr输出；
4. 由于父进程没有读取子进程的stderr，因此子进程的stderr管道被写满以后，无法继续运行，被堵塞在write系统调用处；
5. 由于子进程被堵塞了，因此父进程也无法等到子进程的结束，陷入了互相等待。

验证问题

下面是对SPECjvm2008的源码进行分析后得到的一个验证方式，直接运行对应的测试用例（没有被重定向过的），可以看到大量的警告信息，如下：

raphael@sigma:~/specjvm2008$ java -classpath SPECjvm2008.jar spec.benchmarks.compiler.sunflow.Main
警告：spec.benchmarks.compiler.SpecFileManager$CachedFileObject@43a0cee9: 主版本 52 比 51 新，此编译器支持最新的主版本。
建议升级此编译器。
警告：spec.benchmarks.compiler.SpecFileManager$CachedFileObject@710726a3: 主版本 52 比 51 新，此编译器支持最新的主版本。
建议升级此编译器。
警告：spec.benchmarks.compiler.SpecFileManager$CachedFileObject@646007f4: 主版本 52 比 51 新，此编译器支持最新的主版本。
建议升级此编译器。
……

如果在运行上述命令时加上2>/dev/null将标准错误输出重定向到空设备，就看不到上述警告信息了，再次验证了之前结论的正确性。

为了进一步验证此问题，我们可以开发一个父进程的程序与子进程的程序。在父进程里对子进程的标准输出与标准错误输出进行重定向，但是仅读取子进程的标准输出。在子进程中则不断向stdout与stderr输出大量信息，同时通过日志文件记录日志。看看此时程序是否会停住，以及在停住的时候，其syscall、stack是否与之前的进程一致。除此之外，还可以进行统计，查看当向stderr写入了多少字节后，管道会被堵塞。

父进程（parent.c）源码如下：

#include <stdio.h>
#include <unistd.h>

int main(int argc, char* argv[])
{
    int outs[2], errs[2];
    int ret = pipe(outs);
    if (ret) {
        perror("pipe");
        return ret;
    }

    ret = pipe(errs);
    if (ret) {
        close(outs[0]);
        close(outs[1]);
        perror("pipe2");
        return ret;
    }

    pid_t pid = fork();
    if (pid < 0) { // fail
        close(errs[0]);
        close(errs[1]);
        close(outs[0]);
        close(outs[1]);
        perror("fork");
        return pid;
    } else if (pid == 0) { // child
        close(errs[0]);
        close(outs[0]);
        dup2(errs[1], 2);
        dup2(outs[1], 1);
        execl("./child", "child", 0);
    } else { // parent
        close(errs[1]);
        close(outs[1]);
        char buf[80];
        while (1) {
            size_t n = read(outs[0], buf, sizeof(buf)-1);
            if (n <= 0)
                break;
            buf[n] = 0;
            printf("%s", buf);
        }
        close(errs[0]);
        close(outs[0]);
    }
}

父进程在程序起始阶段就打开了两对管道outs与errs，分别用于子进程的stdout与stderr。接下来，父进程调用fork，在子进程的分支里（pid == 0时）关闭了管道的输出，并将对应管道的输入与文件描述符1（stdout）以及2（stderr）关联，最后调用了execl启动./child子进程。在父进程分支里（else时）关闭了管道的输入，循环读取子进程的outs[0]管道（对应子进程的stdout）并将其输出打印出来，但是完全不处理子进程的stderr管道。

子进程（child.c）源代码如下：

#define _GNU_SOURCE

#include <stdio.h>
#include <fcntl.h>

int main()
{
    int written = 0;
    printf("stderr pipe size: %ld\n", fcntl(2, F_GETPIPE_SZ));
    FILE* fp = fopen("child.log", "w");
    setvbuf(fp, 0, _IONBF, 0);
    for (int j = 1; j <= 10000; j++) {
        written += fprintf(stderr, "this is a very long long long long long error, and the error number is #%d\n", j*100 + 1);
        printf("we are making progress... haha ;) and the progress is %d, w: %d\n", j*1000, written);
        fprintf(fp, "progress %d, w: %d\n", j, written);
        // fflush(fp);
    }
    fclose(fp);
}

子进程首先打印2号描述符管道的容量（通过fcntl函数），继而打开了日志文件，然后进行了一个大循环，先向stderr输出，如果输出成功则记录对应的累计输出字节数，然后向stdout输出，最后向日志文件输出。

下面是执行的结果：

raphael@sigma:~/temp/redirect$ ./parent
stderr pipe size: 65536
we are making progress... haha ;) and the progress is 1000, w: 76
we are making progress... haha ;) and the progress is 2000, w: 152
we are making progress... haha ;) and the progress is 3000, w: 228
……
we are making progress... haha ;) and the progress is 809000, w: 62994
we are making progress... haha ;) and the progress is 810000, w: 63072

即2号文件描述符的管道大小为65536，即64 KB。对应大约向stderr写了63072字节后子进程就停滞了，此时查看child.log日志文件：

raphael@sigma:~/temp/redirect$ tail -5 child.log
progress 830, w: 64632
progress 831, w: 64710
progress 832, w: 64788
progress 833, w: 64866
progress 834, w: 64944

可以看到日志文件更新得更快一些，在写入了64944字节后就无法向stderr写入了。

对应查看parent与child的进程状态：

raphael@sigma:~/temp/redirect$ cat /proc/`pidof child`/syscall
1 0x2 0x7ffdde851db0 0x4e 0x64 0x7fef4a0a5700 0x4e 0x7ffdde851be8 0x7fef49be5620
raphael@sigma:~/temp/redirect$ cat /proc/`pidof child`/stack
[<ffffffff811e092c>] pipe_wait+0x6c/0xb0
[<ffffffff810b6a20>] autoremove_wake_function+0x0/0x40
[<ffffffff811e0a90>] pipe_write+0xc0/0x3f0
[<ffffffff811d8284>] new_sync_write+0xa4/0xf0
[<ffffffff811d8c34>] vfs_write+0xa4/0x1a0
[<ffffffff811d98c2>] SyS_write+0x52/0xc0
[<ffffffff81593d32>] system_call_fast_compare_end+0xc/0x67
[<ffffffffffffffff>] 0xffffffffffffffff
raphael@sigma:~/temp/redirect$ cat /proc/`pidof parent`/syscall
0 0x3 0x7ffe6c91a220 0x4f 0x73 0x7ffe6c91a220 0x32 0x7ffe6c91a208 0x7fe00abd05c0
raphael@sigma:~/temp/redirect$ cat /proc/`pidof parent`/stack
[<ffffffff811e092c>] pipe_wait+0x6c/0xb0
[<ffffffff810b6a20>] autoremove_wake_function+0x0/0x40
[<ffffffff811e0fe1>] pipe_read+0x221/0x350
[<ffffffff811d84fd>] new_sync_read+0x9d/0xe0
[<ffffffff811d8af1>] vfs_read+0x81/0x120
[<ffffffff811d9802>] SyS_read+0x52/0xc0
[<ffffffff81593d32>] system_call_fast_compare_end+0xc/0x67
[<ffffffffffffffff>] 0xffffffffffffffff

可以看到子进程状态与之前SPECjvm2008测试时遇到问题时进程的状态是一致了，再次验证了我们的猜想。但是父进程则有所不同，这次父进程是堵塞在read系统调用了，应该是堵塞在对子进程stdout管道的读取上。实际上，我们还参考SPECjvm2008的源码开发了一个Java程序来验证，下面是主程序（Main.java）的源代码：

package dev.raphael;

public class Main {
    public static void go() throws Exception {
        Runtime rt = Runtime.getRuntime();
        String exe = "./child";
        Process p = rt.exec(exe);
        MainOutput out = new MainOutput(p.getInputStream());
        out.start();
        out.join();
        p.waitFor();
    }

    public static void main(String args[]) {
        System.out.println("hello, world");
        try {
            go();
        } catch(Exception e) {
            e.printStackTrace();
        }
    }
}

下面是对通过管道读取子进程输出的程序（MainOutput.java）的源代码：

package dev.raphael;

import java.io.InputStream;
import java.io.BufferedInputStream;

public class MainOutput extends Thread {
    InputStream input;

    public void run() {
        int num;
        byte[] buf = new byte[80];
        BufferedInputStream bis = new BufferedInputStream(input);
        try {
            while ((num = bis.read(buf)) > 0) {
                String line = new String(buf, 0, num);
                System.out.print(line);
            }
        } catch(Exception e) {
            e.printStackTrace();
        }
    }

    public MainOutput(InputStream in) {
        this.input = in;
    }
}

下面是对应的父进程的syscall与stack。

raphael@sigma:~/temp/redirect$ ps aux | grep --color java
raphael  10771  4.8  1.5 2384988 30288 pts/0   Sl+  14:41   0:00 java -classpath . dev.raphael.Main
raphael  10785  0.0  0.0  14532   976 pts/1    S+   14:41   0:00 grep --color java
raphael@sigma:~/temp/redirect$ cat /proc/10771/syscall
202 0x7f12c5fbe9d0 0x0 0x2a14 0x0 0xca 0x7f12c5fbe9d0 0x7ffec6e366b0 0x7f12c5bad6bd
raphael@sigma:~/temp/redirect$ cat /proc/10771/stack
[<ffffffff810ee1ba>] futex_wait_queue_me+0xba/0x110
[<ffffffff810ee4a5>] futex_wait+0x105/0x250
[<ffffffff810bb801>] __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[<ffffffff810bb801>] __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[<ffffffff810a8786>] update_curr+0xb6/0x130
[<ffffffff810f04d9>] do_futex+0x149/0xb10
[<ffffffff810a8bf0>] check_preempt_wakeup+0xe0/0x1e0
[<ffffffff810bb801>] __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[<ffffffff810bb801>] __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[<ffffffff810f0f1f>] SyS_futex+0x7f/0x170
[<ffffffff81003691>] syscall_slow_exit_work+0xc1/0xd0
[<ffffffff81593d32>] system_call_fast_compare_end+0xc/0x67
[<ffffffffffffffff>] 0xffffffffffffffff

可见与SPECjvm2008中父进程的表现完全一致，子进程的表现也一致了。

解决问题

从上述分析看来，这个问题应该是SPECjvm2008的一个bug，即父进程重定向了子进程的stderr，但是却没有读取对应的数据，导致一旦出现大量的警告信息时，子进程对stderr的管道写入被堵塞，从而导致测试进程整个被停滞。

要解决问题主要有下面几个思路：

1. 修改SPECjvm2008的代码，使得父进程除了读取stdout之外，还需要读取stderr，或者在编译的时候加入-nowarn选项，让javac不输出警告信息；
2. 修改javac的行为，让其不再输出警告信息；
3. 修改系统的管道尺寸配置参数，让管道变大一些，例如通过ulimit或者sysctl；
4. 修改内核代码，让管道变大一些（实际上内核里写死了每个管道的缺省大小是16页，对于x86来说每页为4KB，对应大小即为16x4 = 64KB）；

显然第一个方法是正确的方法，其它方法都是暂时规避的方法。大家可以自行尝试一下，看看哪个方法是可行可用的。

小结

在进程堵塞的时候，可以通过多种方法对进程进行调试，比如查看/proc/#/syscall、/proc/#/stack，比如使用gdb，比如使用strace。如果进程已经陷入了内核（状态为S或D），通过strace查看到的信息是有限的，如果进程仍处于用户态（状态为R），则通过strace是比较有效的，可以观察到进程是否在来回调用系统调用，通过syscall/stack则不一定稳定。当然，若应用程序仅在用户态运行，通过strace就难以跟踪了，这个时候使用gdb可能是更好的方法。