Please enable Javascript to view the contents

小编码，我输给 AI 了 —— 简记一次父子进程互锁的坑，自己挖的

 ·  ☕ 3 分钟

简述

最近自己挖了一个：父子进程互锁的坑，真是应了一句话：

Debugging is like being the detective in a crime movie where you are also the murderer.

- Filipe Fortes
调试就像是犯罪电影中的侦探，而你也是凶手。

先说结论吧：可能真是太久没认真写代码了，犯了个低级错误：

  1. 主进程创建了一个 pipe1
  2. 创建子进程，其 stdout 定向到 pipe1
  3. 主进程等待子进程的结束
  4. 子进程不断写 pipe1，直到 buffer满了，开始等待 pipe1 可写
  5. 造成死锁

坑本身没太多技术深度，甚至可以说，是刚毕业的程序员都不应该出的低级错误。或者调查方法也可能有点参考价值吧，虽然基本也是 15 年前的技术了。不管，先记下来再说。

这个问题其实网上已经有大量记载：

过程

挖坑

最近写这么一段用于自动化测试的 test case 程序段：

1
2
3
4
5
6
7
8

    Process proc = Runtime.getRuntime().exec("curl -v http://www.example.com/sometimes-get-a-large-response", envp);
    proc.waitFor();
    exitStatus = proc.exitValue();
    BufferedReader reader = new BufferedReader(new InputStreamReader(proc.getInputStream()));
    String line = null;
    while ((line = reader.readLine()) != null) {
        ...
    }

我也不记得是自己写，还是用搜索引擎 stackoverflow.com 然后 ctrl + c 回来的。

入坑

程序有时候正常运行，有时间卡着不动。

调查

3 个进程关系大概如下：

[maven jvm] 
     |
     | -- [test cases jvm] (waiting for [curl] exit)
            |
            | -- [curl] (stdout pipe buffer full, waiting for pipe writeable)

出现问题的 test case jvm 进程用于跑 test case，由父进程 maven 启动。curl 进程的 stdout 重定向到其父进程 test caes jvm 创建的一个 pipe 。

对于 test case jvm 卡住的分析，第一件事当然是看父进程和子进程的 cpu 了，均基本为 0% 。

子进程 curl

自以为懂 linux 的我，下一步当然是看 stack。 比较简单的是看内核的 stack ：

1
2
3
4
5
6
7
8

$ sudi cat /proc/$(pgrep curl)/stack

[<ffffffff88065460>] pipe_wait+0x70/0xc0
[<ffffffff88065709>] pipe_write+0x1f9/0x540
[<ffffffff8805b1f3>] do_sync_write+0x93/0xe0
[<ffffffff8805bcc0>] vfs_write+0xc0/0x1f0
[<ffffffff8805ca75>] SyS_write+0x55/0xd0
[<ffffffff885c562e>] tracesys+0xa6/0xcc

什么，卡在写 pipe ? curl 写什么 pipe ?

1
2
3
4
5
6
7

$ sudo ll /proc/$(pgrep curl)/fd
lr-x------ 1 1201 1202 64 7月   4 09:33 0 -> pipe:[1095338147]
l-wx------ 1 1201 1202 64 7月   4 09:33 1 -> pipe:[1095338148]
l-wx------ 1 1201 1202 64 7月   4 09:33 2 -> pipe:[1095338149]
lrwx------ 1 1201 1202 64 7月   4 09:33 3 -> socket:[1095340467]
lrwx------ 1 1201 1202 64 7月   4 09:33 4 -> socket:[1095340468]
lrwx------ 1 1201 1202 64 7月   4 09:33 5 -> socket:[1095340471]

可能是 stdout 了，如何证明？

1
2
3

$ strace -p $(pgrep curl)                                                                                                      
strace: Process 30349 attached
write(1, "80\"\n          },\n          {\n   "..., 4096

fd = 1 ，所以是 stdout 了。

test caes jvm

由于环境问题，不能用 jstack 看 test case jvm 卡在什么地方。那么用 kill -QUIT 让 test case jvm 吐 stack 到 stdout ?

第一次时，我真是这样 kill -QUIT $test_case_jvm_pid 。结果是惨痛的 maven jvm 的抱怨：

Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /myapp/target/surefire-reports/2024-07-04T07-22-56_211-jvmRun1.dumpstream

# Created at 2024-07-04T07:48:15.111
Corrupted STDOUT by directly writing to native stream in forked JVM 1. Stream 'Heap'.
java.lang.IllegalArgumentException: Stream stdin corrupted. Expected comma after third character in command 'Heap'.
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient$OperationalData.<init>(ForkClient.java:507)
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.processLine(ForkClient.java:210)
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:177)
        at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:88)
        at java.base/java.lang.Thread.run(Thread.java:829)

maven jvm 抱怨：你太粗暴了，让我的子进程 test case jvm 的输出的格式出错，流损坏了：

https://maven.apache.org/surefire/maven-failsafe-plugin/faq.html

Corrupted channel by directly writing to native stream in forked JVM

If your tests use native library which prints to STDOUT this warning message appears because the library corrupted the channel used by the plugin in order to transmit events with test status back to Maven process. It would be even worse if you override the Java stream by System.setOut because the stream is also supposed to be corrupted but the Maven will never see the tests finished and build may hang.

This warning message appears if you use FileDescriptor.out or JVM prints GC summary.

In that case the warning is printed “Corrupted channel by directly writing to native stream in forked JVM”, and a dump file can be found in Reports directory.

If debug level is enabled then messages of corrupted stream appear in the console.

好，maven jvm 不让 test caes jvm 出这个 stack dump 了。我有办法吗，有的，不过这里不写了，后面写一个文章补充吧，这个有点意思。对于这个调查本身，这个 java stack dump 已经是可有可无了。

猜猜猜

test case jvm 是 dump 不了 java thread 了，不过从 curl 的 stack 和 strace 中可以看出，curl 是写不入一个 full buffer 了的 stdout pipe 了。所以问题就出在上面的代码中了：

1
2
3
4
5
6
7
8

    Process proc = Runtime.getRuntime().exec("curl -v http://www.example.com/sometimes-get-a-large-response", envp);
    proc.waitFor();
    exitStatus = proc.exitValue();
    BufferedReader reader = new BufferedReader(new InputStreamReader(proc.getInputStream()));
    String line = null;
    while ((line = reader.readLine()) != null) {
        ...
    }

修正

是时候回到本文的标题了：“ 小编码，我输给 AI 了”。我查了查某 LLM。他建议的写法是：

image-20240705234446272

分享
Mark Zhu
作者
Mark Zhu
An old developer