Arthas: 记录 3.2.0 版本之前 stack的一个神奇的bug

Created on 4 Jun 2020  ·  4Comments  ·  Source: alibaba/arthas

以arthas-demo为例，一开始结果是：

[arthas@18948]$ stack demo.MathGame print
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
ts=2020-06-04 11:51:14;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    @demo.MathGame.print()
        at demo.MathGame.run(MathGame.java:25)
        at demo.MathGame.main(MathGame.java:16)

在打印多次之后，结果是变少了一行：

[arthas@18441]$ stack demo.MathGame print
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 17 ms.
ts=2020-06-04 11:50:27;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
    @demo.MathGame.run()
        at demo.MathGame.main(MathGame.java:16)

为什么呢？ 🤓

question-answered
Source
picture hengyunabc

Most helpful comment

    private static int findTheSpyAPIDepth(StackTraceElement[] stackTraceElementArray) {
        if (MAGIC_STACK_DEPTH > 0) {
            return MAGIC_STACK_DEPTH;
        }
        if (MAGIC_STACK_DEPTH > stackTraceElementArray.length) {
            return 0;
        }
        for (int i = 0; i < stackTraceElementArray.length; ++i) {
            if (SpyAPI.class.getName().equals(stackTraceElementArray[i].getClassName())) {
                MAGIC_STACK_DEPTH = i + 1;
                break;
            }
        }
        return MAGIC_STACK_DEPTH;
    }

是这个MAGIC_STACK_DEPTH返回的值有问题吧？为什么>0后就不再计算了呢?

因为从 spy类到真正的应用栈，深度是固定的，只要算一次就行了。

picture hengyunabc on 5 Jul 2020
👍2

All 4 comments

    private static int findTheSpyAPIDepth(StackTraceElement[] stackTraceElementArray) {
        if (MAGIC_STACK_DEPTH > 0) {
            return MAGIC_STACK_DEPTH;
        }
        if (MAGIC_STACK_DEPTH > stackTraceElementArray.length) {
            return 0;
        }
        for (int i = 0; i < stackTraceElementArray.length; ++i) {
            if (SpyAPI.class.getName().equals(stackTraceElementArray[i].getClassName())) {
                MAGIC_STACK_DEPTH = i + 1;
                break;
            }
        }
        return MAGIC_STACK_DEPTH;
    }

是这个MAGIC_STACK_DEPTH返回的值有问题吧？为什么>0后就不再计算了呢?

iSenninha picture iSenninha on 3 Jul 2020 
    private static int findTheSpyAPIDepth(StackTraceElement[] stackTraceElementArray) {
        if (MAGIC_STACK_DEPTH > 0) {
            return MAGIC_STACK_DEPTH;
        }
        if (MAGIC_STACK_DEPTH > stackTraceElementArray.length) {
            return 0;
        }
        for (int i = 0; i < stackTraceElementArray.length; ++i) {
            if (SpyAPI.class.getName().equals(stackTraceElementArray[i].getClassName())) {
                MAGIC_STACK_DEPTH = i + 1;
                break;
            }
        }
        return MAGIC_STACK_DEPTH;
    }

是这个MAGIC_STACK_DEPTH返回的值有问题吧？为什么>0后就不再计算了呢?

因为从 spy类到真正的应用栈，深度是固定的，只要算一次就行了。

hengyunabc picture hengyunabc on 5 Jul 2020
👍2

翻到3.18的代码Debug了一波，症结应该是这里了，一开始我说的那里是修复后代码，囧。

3.18版本 Thread#getThreadStack()代码如下：

    public static String getThreadStack(Thread currentThread) {
        StackTraceElement[] stackTraceElementArray = currentThread.getStackTrace();

        StackTraceElement locationStackTraceElement = stackTraceElementArray[10];
        String locationString = String.format("    @%s.%s()", locationStackTraceElement.getClassName(),
                locationStackTraceElement.getMethodName());

        StringBuilder builder = new StringBuilder();
        builder.append(getThreadTitle(currentThread)).append("\n").append(locationString).append("\n");

        int skip = 11;
        for (int index = skip; index < stackTraceElementArray.length; index++) {
            StackTraceElement ste = stackTraceElementArray[index];
            builder.append("        at ")
                    .append(ste.getClassName())
                    .append(".")
                    .append(ste.getMethodName())
                    .append("(")
                    .append(ste.getFileName())
                    .append(":")
                    .append(ste.getLineNumber())
                    .append(")\n");
        }

        return builder.toString();
    }

问题出在这一行：

        StackTraceElement[] stackTraceElementArray = currentThread.getStackTrace();

这里返回的数组长度在多次调用后会不一样，下面是Jdk11 NativeMethodAccessorImpl的代码：

    public Object invoke(Object obj, Object[] args)
        throws IllegalArgumentException, InvocationTargetException
    {
        // We can't inflate methods belonging to vm-anonymous classes because
        // that kind of class can't be referred to by name, hence can't be
        // found from the generated bytecode.
        if (++numInvocations > ReflectionFactory.inflationThreshold()
                && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            MethodAccessorImpl acc = (MethodAccessorImpl)
                new MethodAccessorGenerator().
                    generateMethod(method.getDeclaringClass(),
                                   method.getName(),
                                   method.getParameterTypes(),
                                   method.getReturnType(),
                                   method.getExceptionTypes(),
                                   method.getModifiers());
            parent.setDelegate(acc);
        }

        return invoke0(method, obj, args);
    }

超过inflationThreshold会通过生成MethodAccessorGenerator替代NativeMethodAccessorImpl。这个时候stackTraceElementArray的长度就变小了，直接这样截取就出问题：

 int skip = 11;
        for (int index = skip; index < stackTraceElementArray.length; index++) {
            StackTraceElement ste = stackTraceElementArray[index];
            builder.append("        at ")
                    .append(ste.getClassName())
                    .append(".")
                    .append(ste.getMethodName())
                    .append("(")
                    .append(ste.getFileName())
                    .append(":")
                    .append(ste.getLineNumber())
                    .append(")\n");
        }

修复的方式是动态找到Arthas 栈帧开始的深度：

    private static int findTheSpyAPIDepth(StackTraceElement[] stackTraceElementArray) {
        if (MAGIC_STACK_DEPTH > 0) {
            return MAGIC_STACK_DEPTH;
        }
        if (MAGIC_STACK_DEPTH > stackTraceElementArray.length) {
            return 0;
        }
        for (int i = 0; i < stackTraceElementArray.length; ++i) {
            if (SpyAPI.class.getName().equals(stackTraceElementArray[i].getClassName())) {
                MAGIC_STACK_DEPTH = i + 1;
                break;
            }
        }
        return MAGIC_STACK_DEPTH;
    }
iSenninha picture iSenninha on 6 Jul 2020
👍1

翻到3.18的代码Debug了一波，症结应该是这里了，一开始我说的那里是修复后代码，囧。

3.18版本 Thread#getThreadStack()代码如下：

    public static String getThreadStack(Thread currentThread) {
        StackTraceElement[] stackTraceElementArray = currentThread.getStackTrace();

        StackTraceElement locationStackTraceElement = stackTraceElementArray[10];
        String locationString = String.format("    @%s.%s()", locationStackTraceElement.getClassName(),
                locationStackTraceElement.getMethodName());

        StringBuilder builder = new StringBuilder();
        builder.append(getThreadTitle(currentThread)).append("\n").append(locationString).append("\n");

        int skip = 11;
        for (int index = skip; index < stackTraceElementArray.length; index++) {
            StackTraceElement ste = stackTraceElementArray[index];
            builder.append("        at ")
                    .append(ste.getClassName())
                    .append(".")
                    .append(ste.getMethodName())
                    .append("(")
                    .append(ste.getFileName())
                    .append(":")
                    .append(ste.getLineNumber())
                    .append(")\n");
        }

        return builder.toString();
    }

问题出在这一行：

        StackTraceElement[] stackTraceElementArray = currentThread.getStackTrace();

这里返回的数组长度在多次调用后会不一样，下面是Jdk11 NativeMethodAccessorImpl的代码：

    public Object invoke(Object obj, Object[] args)
        throws IllegalArgumentException, InvocationTargetException
    {
        // We can't inflate methods belonging to vm-anonymous classes because
        // that kind of class can't be referred to by name, hence can't be
        // found from the generated bytecode.
        if (++numInvocations > ReflectionFactory.inflationThreshold()
                && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            MethodAccessorImpl acc = (MethodAccessorImpl)
                new MethodAccessorGenerator().
                    generateMethod(method.getDeclaringClass(),
                                   method.getName(),
                                   method.getParameterTypes(),
                                   method.getReturnType(),
                                   method.getExceptionTypes(),
                                   method.getModifiers());
            parent.setDelegate(acc);
        }

        return invoke0(method, obj, args);
    }

超过inflationThreshold会通过生成MethodAccessorGenerator替代NativeMethodAccessorImpl。这个时候stackTraceElementArray的长度就变小了，直接这样截取就出问题：

 int skip = 11;
        for (int index = skip; index < stackTraceElementArray.length; index++) {
            StackTraceElement ste = stackTraceElementArray[index];
            builder.append("        at ")
                    .append(ste.getClassName())
                    .append(".")
                    .append(ste.getMethodName())
                    .append("(")
                    .append(ste.getFileName())
                    .append(":")
                    .append(ste.getLineNumber())
                    .append(")\n");
        }

修复的方式是动态找到Arthas 栈帧开始的深度：

    private static int findTheSpyAPIDepth(StackTraceElement[] stackTraceElementArray) {
        if (MAGIC_STACK_DEPTH > 0) {
            return MAGIC_STACK_DEPTH;
        }
        if (MAGIC_STACK_DEPTH > stackTraceElementArray.length) {
            return 0;
        }
        for (int i = 0; i < stackTraceElementArray.length; ++i) {
            if (SpyAPI.class.getName().equals(stackTraceElementArray[i].getClassName())) {
                MAGIC_STACK_DEPTH = i + 1;
                break;
            }
        }
        return MAGIC_STACK_DEPTH;
    }

的确是这个原因，一般人注意不到。新版本去掉了反射，所以栈深度是固定的，并且只计算一次就可以了。

hengyunabc picture hengyunabc on 6 Jul 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

joey-happy picture joey-happy  ·  3Comments
hengyunabc picture hengyunabc  ·  4Comments
x334085347 picture x334085347  ·  5Comments
Feixu2015 picture Feixu2015  ·  4Comments
liugddx picture liugddx  ·  3Comments