打印当前线程调用栈

发表于 2019-12-20 分类于 java Waline：阅读次数：

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

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

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

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

/**
 * @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);
    }
}

比如有下面一段测试代码

/**
 * @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");
    }
}

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

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 能力。