問題概述

前段時間在對系統(tǒng)進行性能測試的時候橱乱，我們遇到了一個SPECjvm2008的問題。先介紹下牲阁，SPECjvm2008是當(dāng)前測試JVM（Java虛擬機泻红，Java Virtual Machine）性能最常見的工具，它由多個測試用例組成或颊。另外砸紊，SPECjvm2008還是一個開源軟件传于，因此在發(fā)生問題的時候是可以結(jié)合它的源碼進行聯(lián)合診斷的。

當(dāng)時遇到的問題是在SPECjvm2008里有一個測試用例叫startup.compiler.sunflow醉顽，在運行這個測試用例的時候沼溜，SPECjvm2008會停止在測試中途，當(dāng)時等了兩天SPECjvm2008仍處于暫停狀態(tài)游添，沒有任何運行下去的跡象系草。

問題分析

解決問題的第一個步驟就是要重現(xiàn)問題，如果不能重現(xiàn)問題唆涝，首先是難以找到問題的癥結(jié)所在找都，其次是即使自以為解決了問題，由于無法重現(xiàn)問題廊酣，也難以進行驗證能耻。

在此處，其測試用例的運行方法是進入SPECjvm2008的安裝目錄亡驰，然后運行：

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

運行的結(jié)果如下（有部分刪節(jié)）：

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

此時已經(jīng)進入了暫停狀態(tài)晓猛，因此我們可以再開一個終端，檢查對應(yīng)的進程信息隐解。首先需要通過ps得到進程號與進程狀態(tài)鞍帝，如下：

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

可以看到對應(yīng)的原始進程的進程號是2910，狀態(tài)為Sl+煞茫，直接測試進程的進程號是2924帕涌，狀態(tài)為Sl+。首先可以明確的是進程狀態(tài)為Sl+表示此進程處于休眠狀態(tài)（S续徽，即進程陷入了內(nèi)核態(tài)未返回蚓曼，但是可以接收信號，如果是D的話則表示陷入了內(nèi)核態(tài)未返回钦扭，而且不能接受信號纫版，如果是R的話表示仍處于用戶態(tài)可運行狀態(tài)），多線程（l）客情，而且是前臺進程（+）其弊。以上狀態(tài)可以通過man ps得到。

既然進程陷入了內(nèi)核未返回膀斋，則可以通過/proc/#pid/syscall得到對應(yīng)陷入內(nèi)核前調(diào)用的系統(tǒng)調(diào)用信息梭伐。此時我們運行cat /proc/2924/syscall可以看到如下信息：

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

通過man proc得知，上述文件中第一個202表示對應(yīng)的系統(tǒng)調(diào)用號（syscall number）仰担，其后六個參數(shù)表示對應(yīng)的系統(tǒng)調(diào)用參數(shù)的寄存器信息糊识，最后兩個參數(shù)表示應(yīng)用程序用戶態(tài)對應(yīng)線程的棧指針與指令寄存器值。

要想得知系統(tǒng)調(diào)用號對應(yīng)的系統(tǒng)調(diào)用名稱，可以查找對應(yīng)架構(gòu)的unistd.h頭文件赂苗，例如我們測試的機器架構(gòu)為x86_64愉耙，那么可以打開unistd_64.h，查找202拌滋。如果希望通過命令直接查找朴沿，可以安裝auditd包，運行ausyscall即可鸠真，如下：

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

可以看到在x86_64架構(gòu)下悯仙，202號系統(tǒng)調(diào)用即為futex。但是futex是一個非常常用的系統(tǒng)調(diào)用吠卷，被廣泛用于pthread庫同步機制的實現(xiàn)锡垄，以及POSIX信號量的實現(xiàn)等諸多地方，因此僅僅得知進程調(diào)用futex陷入了內(nèi)核只能得知進程在等待某個共享鎖祭隔，這其實是進程陷入S狀態(tài)最常見的情況货岭，但是在這里難以判斷是誰導(dǎo)致的共享鎖被占用，從而使得進程進入等待狀態(tài)疾渴，也難以解決問題千贯。

此時，我們可以嘗試查看下此進程的各個線程搞坝，首先各個進程的線程可以通過ls /proc/#pid/task得到搔谴，然后通過對每個線程進行/proc/#pid/syscall的查看，可以發(fā)現(xiàn)某個線程的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號系統(tǒng)調(diào)用敦第，經(jīng)過ausyscall可以知道1號系統(tǒng)調(diào)用即為write。而man write可以得知其需要三個參數(shù)店量，分別是文件描述符芜果、待寫入的緩存區(qū)指針，以及對應(yīng)緩存區(qū)的大小融师。在這里文件描述符為2（0x2）右钾，緩存區(qū)指針是0x7f88dcd6fa60，緩存區(qū)大小是28（0x1c）旱爆。而2號文件描述符是標準錯誤輸出（stderr）舀射，可見2937號線程調(diào)用write向標準錯誤輸出輸出的時候沒有返回，這是一個比較少見的情況怀伦。我們可以繼續(xù)深入下內(nèi)核看看是怎么回事后控，如下：

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

可以發(fā)現(xiàn)在內(nèi)核里進程被pipe_wait/pipe_write堵塞住了，即在寫管道的時候被堵塞了空镜。那么，究竟什么情況會導(dǎo)致進程向stderr寫數(shù)據(jù)，但是被管道堵住了呢吴攒？比較常見的顯然是進程的stderr被重定向了张抄，而且被重定向的stder管道沒有被讀取，或者讀取速度過慢導(dǎo)致了進程被堵塞洼怔，而父進程應(yīng)該是沒有讀取stderr署惯，但是又在等待程序運行完畢，形成了一個死鎖镣隶，所以造成了測試程序無法繼續(xù)運行下去极谊。

下面，我們還可以看看0x7f88dcd6fa60對應(yīng)的具體是什么數(shù)據(jù)安岂。我們當(dāng)然可以通過gdb進入進程查看數(shù)據(jù)轻猖，不過還有更輕量級的方法，那就是讀取/proc/#pid/mem文件域那。這個文件對應(yīng)的是進程的內(nèi)存地址空間的所有內(nèi)存的內(nèi)容咙边，讀取這個虛擬文件即可獲取到對應(yīng)的進程內(nèi)存數(shù)據(jù)。

不過如果你直接讀取此文件會得到如下的錯誤：

raphael@sigma:~/specjvm2008$ cat /proc/2937/mem 
cat: /proc/2937/mem: 輸入/輸出錯誤

請注意次员，這并不是權(quán)限錯誤败许，換了root來cat此文件一樣會發(fā)生上述錯誤。要是大家對C語言編程與進程的地址空間有了解淑蔚，就可以知道市殷，虛擬文件的首字節(jié)顯然對應(yīng)的就是進程地址空間中地址為0的內(nèi)存。但是我們都知道刹衫，進程地址空間中從0開始的一大段地址都是不可訪問的醋寝，因此，如果直接讀取mem文件的開始數(shù)據(jù)绪妹，對應(yīng)其實就是訪問了進程地址空間從0開始的對應(yīng)地址空間甥桂，由于這段地址沒有做任何映射，當(dāng)然會產(chǎn)生訪問錯誤了邮旷。

因此黄选，讀取mem文件只能使用open、lseek婶肩、read的方式進行办陷。由于hexdump -s在此處不適用（大家可以試下想想為什么），因此可以寫一個簡單的C程序即可律歼，如下：

raphael@sigma:~/specjvm2008$ ./rd /proc/2937/mem 140225797356128 28
[28(max 28)]: '建議升級此編譯器民镜。
'

可以看到2937號進程正在試圖向stderr輸出“建議升級此編譯器”的字樣。

因此险毁，本次SPECjvm2008事件的原因基本已經(jīng)清楚了：

1. 父進程啟動子進程進行編譯（畢竟此測試用例是compiler.sunflow）制圈；
2. 父進程重定向了子進程的stderr们童，但是沒有讀取子進程的stderr，并使用futex等待子進程結(jié)束鲸鹦；
3. 子進程在編譯過程中產(chǎn)生了大量的警告信息慧库，通過stderr輸出；
4. 由于父進程沒有讀取子進程的stderr馋嗜，因此子進程的stderr管道被寫滿以后齐板，無法繼續(xù)運行，被堵塞在write系統(tǒng)調(diào)用處葛菇；
5. 由于子進程被堵塞了甘磨，因此父進程也無法等到子進程的結(jié)束，陷入了互相等待眯停。

驗證問題

下面是對SPECjvm2008的源碼進行分析后得到的一個驗證方式济舆，直接運行對應(yīng)的測試用例（沒有被重定向過的），可以看到大量的警告信息庵朝，如下：

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將標準錯誤輸出重定向到空設(shè)備宣羊，就看不到上述警告信息了，再次驗證了之前結(jié)論的正確性汰蜘。

為了進一步驗證此問題仇冯，我們可以開發(fā)一個父進程的程序與子進程的程序。在父進程里對子進程的標準輸出與標準錯誤輸出進行重定向族操，但是僅讀取子進程的標準輸出苛坚。在子進程中則不斷向stdout與stderr輸出大量信息，同時通過日志文件記錄日志色难∑貌眨看看此時程序是否會停住，以及在停住的時候枷莉，其syscall娇昙、stack是否與之前的進程一致。除此之外笤妙，還可以進行統(tǒng)計冒掌，查看當(dāng)向stderr寫入了多少字節(jié)后噪裕，管道會被堵塞。

父進程（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州疾。接下來，父進程調(diào)用fork皇拣，在子進程的分支里（pid == 0時）關(guān)閉了管道的輸出，并將對應(yīng)管道的輸入與文件描述符1（stdout）以及2（stderr）關(guān)聯(lián)薄嫡，最后調(diào)用了execl啟動./child子進程氧急。在父進程分支里（else時）關(guān)閉了管道的輸入，循環(huán)讀取子進程的outs[0]管道（對應(yīng)子進程的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函數(shù)），繼而打開了日志文件哑蔫，然后進行了一個大循環(huán)钉寝，先向stderr輸出，如果輸出成功則記錄對應(yīng)的累計輸出字節(jié)數(shù)闸迷，然后向stdout輸出嵌纲，最后向日志文件輸出。

下面是執(zhí)行的結(jié)果：

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逮走。對應(yīng)大約向stderr寫了63072字節(jié)后子進程就停滯了，此時查看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字節(jié)后就無法向stderr寫入了师溅。

對應(yīng)查看parent與child的進程狀態(tài)：

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

可以看到子進程狀態(tài)與之前SPECjvm2008測試時遇到問題時進程的狀態(tài)是一致了，再次驗證了我們的猜想盾舌。但是父進程則有所不同墓臭，這次父進程是堵塞在read系統(tǒng)調(diào)用了，應(yīng)該是堵塞在對子進程stdout管道的讀取上妖谴。實際上窿锉，我們還參考SPECjvm2008的源碼開發(fā)了一個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;
    }
}

下面是對應(yīng)的父進程的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中父進程的表現(xiàn)完全一致榆综，子進程的表現(xiàn)也一致了。

解決問題

從上述分析看來铸史，這個問題應(yīng)該是SPECjvm2008的一個bug鼻疮，即父進程重定向了子進程的stderr，但是卻沒有讀取對應(yīng)的數(shù)據(jù)琳轿，導(dǎo)致一旦出現(xiàn)大量的警告信息時判沟，子進程對stderr的管道寫入被堵塞耿芹，從而導(dǎo)致測試進程整個被停滯。

要解決問題主要有下面幾個思路：

1. 修改SPECjvm2008的代碼挪哄，使得父進程除了讀取stdout之外吧秕，還需要讀取stderr，或者在編譯的時候加入-nowarn選項迹炼，讓javac不輸出警告信息砸彬；
2. 修改javac的行為，讓其不再輸出警告信息斯入；
3. 修改系統(tǒng)的管道尺寸配置參數(shù)砂碉，讓管道變大一些，例如通過ulimit或者sysctl刻两；
4. 修改內(nèi)核代碼增蹭，讓管道變大一些（實際上內(nèi)核里寫死了每個管道的缺省大小是16頁，對于x86來說每頁為4KB磅摹，對應(yīng)大小即為16x4 = 64KB）滋迈；

顯然第一個方法是正確的方法，其它方法都是暫時規(guī)避的方法户誓。大家可以自行嘗試一下饼灿，看看哪個方法是可行可用的。

小結(jié)

在進程堵塞的時候厅克，可以通過多種方法對進程進行調(diào)試赔退，比如查看/proc/#/syscall、/proc/#/stack证舟，比如使用gdb硕旗，比如使用strace。如果進程已經(jīng)陷入了內(nèi)核（狀態(tài)為S或D）女责，通過strace查看到的信息是有限的漆枚，如果進程仍處于用戶態(tài)（狀態(tài)為R），則通過strace是比較有效的抵知，可以觀察到進程是否在來回調(diào)用系統(tǒng)調(diào)用墙基，通過syscall/stack則不一定穩(wěn)定。當(dāng)然刷喜，若應(yīng)用程序僅在用戶態(tài)運行残制，通過strace就難以跟蹤了，這個時候使用gdb可能是更好的方法掖疮。