OO多线程 debug 经验分享

前情提要

本人4月4日晚上 debug 写到了4月5日凌晨三点，睡前以为修好了bug，在自己评测机上跑了6000组数据，结果第二天起床发现6000组数据中跑出了3个bug，又改到4月5日晚上六点终于改好了（至少跑了3200组数据不成问题）。 这里分享一下这几天 debug 出的心得。

多线程debug - 基础版

IntelliJ IDEA 中有一个强力的多线程分析工具 - 转储线程，这个功能可以在运行程序卡死时，查看每个线程的具体情况。我们以最经典的死锁为例。

1
2
3
4
5
6
7
8
9
10
public class Main {
    public static Object A = new Object();
    public static Object B = new Object();
    public static void main(String[] args) {
        DeadClass C = new DeadClass(A, B);
        DeadClass D = new DeadClass(B, A);
        C.start();
        D.start();
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class DeadClass extends Thread {
    Object A;
    Object B;
    public DeadClass(Object A, Object B) {
        this.A = A;
        this.B = B;
    }
    public void run() {
        synchronized (A) {
            try {
                sleep(10);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            synchronized (B) {
                System.out.println("Thread is dead");
            }
        }
    }
}

很显然，我们运行main时，会因为死锁导致什么都不输出，我们使用这个转储线程工具，可以看到每个线程走到了哪一步。

打开我们的转储线程工具，我们可以看到以下界面。

左边有很多项，我们要关心的是其中的Thread-x，这里是我们的线程。点击线程，我们可以看到右边的信息。

这里显示了我们的0号线程，在持有锁<0x00000007327596b0>的时候，试图获得锁<0x00000007327596a0>，此时正在等待锁被阻塞在16行之前。如果看一号线程可以发现显示的信息几乎一致，只是持有和等待的锁刚好对调过来。我们点击报错中的链接就可以看到具体卡在了哪里。

这里和我们的期望是完全一致的，我们可以通过分析日志来看到死锁发生在了哪里。

同样，如果线程无法正确结束的问题发生，我们也有可能在这里看到所有的线程都陷入了WAIT状态，可以通过右边的日志来看到具体行数，我们这里不过多赘述了。

多线程debug - 进阶版

这个部分在假定你有了一台能够自动化生成数据的数据生成器和评测机的前提下进行，这一部分可以帮助你改装你的评测机，以方便 debug 。

先提供一下我的初版评测机的整体工作流程：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
选择是否调用数据生成器 y / n
	如果是
		清空 data 文件夹
		调用数据生成器，询问需要多少组数据
		生成相应的数据
	如果否
		NOP
给本目录下的所有 JAR 做一个索引
给 data 文件夹下的所有 txt 做一个索引
for JAR in JARS
	依次以 data 中的文件作为 stdin ，并行运行程序（我设置了20条线程）
	将 stdout 写入 out 文件夹中名为 JARNAME_TESTCASENAME.out的文件中
	对于 stdout 进行正确性评价，并记录结果和性能
	将结果写入 report 文件夹的 JARNAME.report 中
根据所有的JAR的性能记录，绘制三张性能图表

评测机还有一些细节，比较重要的是对于每一个数据点设一个时间上限，这里不过多赘述。

这样的一版评测机非常非常好用，它能十分高效的进行评测（一小时1200组数据），同时能够将结果准确的记录下来。

然而，本单元debug最重要，也是最困难的一个问题是：**我即使拿到了一组输入数据和我的错误的输出，我也无法复现这个错误。**我们的输出往往不足以支持我们定位到错误原因。

PS：昨晚我拿着一个我的错误数据跑了三四十次，试图通过转储线程分析原因，但是没能让我的程序再错一次。

解决方法很简单，但是从零想出这个方法并不是一个很简单的事。

日志的优雅引入

我最终通过引入日志这一概念来解决我的整个debug问题，具体来说，我们要建立一个很简单的类：

1
2
3
4
5
public class Debug {
    public static boolean d() {
        return true;
    }
}

在我们程序运行的关键点，我们可以增加一些关键的输出信息，例如：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class Distributor{
    ....
    private void getEnd() {
        ........ 
        if (Debug.d()) {
            System.out.println("[LOG]Distributor end");
        }
    }
}   

public class Elevator {
    public void run() {
        .....
        advice = strategy.getAdvice(/*secret!*/);
        if (Debug.d()) {
            System.out.println("[LOG] Elevator " +
            	this.elevatorId + " get advice : " + advice.toString());//checkstyle所限必须写成两行www
        }
        .....
    }
}

日志的输出有两个要点：

  • 一定要增加一个静态的统一开关，例如我的 Debug.d()，我在提交时可以直接把 Debug 中的 return 值改为 false，不容易遗漏任何东西。
  • 一定要统一日志的输出格式，在前面加上一个统一的前缀。

在第二点的基础上，我们可以改良我们的评测机：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
选择是否调用数据生成器 y / n
	如果是
		清空 data 文件夹
		调用数据生成器，询问需要多少组数据
		生成相应的数据
	如果否
		NOP
给本目录下的所有 JAR 做一个索引
给 data 文件夹下的所有 txt 做一个索引
for JAR in JARS
	依次以 data 中的文件作为 stdin ，并行运行程序（我设置了20条线程）
	将 stdout 的所有写入 log 文件夹中名为 JARNAME_TESTCASENAME.log的文件中
	从 log 中筛选所有没有 [LOG] 前缀的行，记录在 out 文件夹中名为 JARNAME_TESTCASENAME.out的文件中
	对于 out 中的结果进行正确性评价，并记录结果和性能
	将结果写入 report 文件夹的 JARNAME.report 中
根据所有的JAR的性能记录，绘制三张性能图表

这样我们就能方便的阅读我们的 log，从中获得我们想要的信息，以方便 debug 。

以我为例，我展示一下我的 log 的一部分

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
...
[LOG] Elevator 2 get advice : OPEN
[  60.5440]ARRIVE-B3-4
[LOG] Elevator 4 get advice : OPEN
[  60.5440]OPEN-B3-2
[  60.5440]OPEN-B3-4
[  60.5440]OUT-S-438-B3-4
[  60.5440]OUT-S-168-B3-2
[  60.9150]CLOSE-F4-1
[LOG] Elevator 1 get advice : WAIT
[  60.9460]CLOSE-B3-4
[LOG] Elevator 4 get advice : WAIT
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is waiting
[LOG] Elevator: 6 is waiting
[LOG] Elevator: 4 is waiting
[LOG] Elevator: 5 is waiting
[LOG] Elevator: 3 is
--- STDERR ---
Checker: Soft timeout (220.0s) reached.
Checker: Hard timeout (250.0s) reached. Process killed.

我通过阅读我的 log，发现电梯2开门后没有关门，电梯1获得等待指令后没有进入等待状态。通过这个线索，我精准定位到了这两个行为后面发生了死锁，修改相关逻辑成功解决了问题。

日志里面怎么写，也是一门艺术，这里就希望大家自行探索了。

文末彩蛋：