打印当前线程调用栈

背景:最近在做一个功能,修改了一个原有对象的属性值,这个对象的值最终会落到数据库里。测试下来发现,最终记录到数据库的值总是一个最大值,和预期的结果不一样,正常情况下应该更新为后续的一个计算结果。

由于该环境下的服务有很多人在用,不能远程 debug。首先想到的是目测代码,查看都有什么地方有可能设置这个值。排查下来发现,这是在请求初始阶段设置的一个默认值,但是在后面的计算过程中会覆盖掉,最终入库结果不应该是修改前的值。

然后在想,可能还有别的请求链路会修改这个值。由于代码太多,链路又很长,一时理不清。那就加日志,把操作过该字段的地方都打印出来,看下每个地方都是什么值。一通操作下来也没发现问题。

另外还想到一个方法,可以在入库的地方把参数和调用栈信息打印出来,这样就知道是哪个调用链路,写了什么值进去。于是就有了下面这段代码:

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
/**
* @author gorden5566
* @date 2019/12/20
*/
public class ThreadUtil {
/**
* 打印当前位置的调用栈信息
*
* @param msg
*/
public static void printStackTrace(String msg) {
StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();

println(Thread.currentThread() + ", message: [" + msg + "]");
if (stackTrace == null || stackTrace.length < 2) {
println("empty stack");
return;
}

for (int i = 2; i < stackTrace.length; i++) {
println("\tat " + stackTrace[i]);
}
}

private static void println(Object object) {
System.out.println(object);
}
}

比如有下面一段测试代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
/**
* @author gorden5566
* @date 2019/12/20
*/
public class ThreadUtilTest {
public static void main(String[] args) {
test1();
}

public static void test1() {
test();
}

public static void test() {
System.out.println("before printStackTrace");
ThreadUtil.printStackTrace("print current thread stack");
System.out.println("after printStackTrace");
}
}

执行后可以输出如下参数和堆栈信息

1
2
3
4
5
6
before printStackTrace
Thread[main,5,main], message: [print current thread stack]
at com.gorden5566.demos.thread.ThreadUtilTest.test(ThreadUtilTest.java:18)
at com.gorden5566.demos.thread.ThreadUtilTest.test1(ThreadUtilTest.java:13)
at com.gorden5566.demos.thread.ThreadUtilTest.main(ThreadUtilTest.java:9)
after printStackTrace

正准备改代码,忽然发现一个疑点:该字段值入库后并不是一个独立的列,而是以 json string 的形式和其他数据存在同一列中,回忆起其他项目中有见过类似操作:入库前,将一个对象属性序列化为 json string 格式存储在另外一个 string 属性中。读数据库时,将数据读到对应的 string 属性中,然后再反序列化为对象。比如对象中一个属性为 private User user,那么会对应另外一个 private String userString,数据库里存的是 userString,内存中操作的是 user

这就很有可能是两个字段值不一致导致的。重新翻了一遍代码,确实是有一处只修改了 java 对象属性,未更新对应的 String 属性。这就导致数据库里记录的是初始值,后面的一通操作得到的结果并未入库。

到此也就找到了问题的原因,虽然并未使用到上面那段代码。可见,目测代码还是能够发现一些问题,有助于提高 debug 能力。

0%