Arthas中使用watch观测方法执行前后,基本类型参数的值不一致问题

一、背景

某日晚,需要协助女朋友排查一个线上问题,其请求调用比较复杂,单次请求过来会多次通过不同路径调用存在问题的方法,并且还有很多重载的方法,排查过程中需要结合stack和各种条件判断,极其麻烦;期间也遇到了 Arthas中使用watch观测方法执行前后,基本类型参数的值不一致的问题。

此问题的结论和原因虽然都比较简单,但其排查过程也可供学习记录。
只想看结论的同学也可以直接看 第四点 !

1.代码

由于真实情况涉及公司业务,而且有很多无关紧要的逻辑,所以写了个超级简化版。

package com.company;

import java.util.concurrent.ConcurrentHashMap;

public class TmpTest {

    public static void main(String[] args) throws InterruptedException {
        for (int i = 0; i < 1000; i++) {
            //睡眠10s,一是避免程序退出,二是可以持续观测
            Thread.sleep(10*1000);

            //这里使用了两个请求意在贴近实际场景,使用Arthas时,能够筛选出自己想要观测的请求是一个非常重要的能力

            //第一个请求进入,该请求是我们想要观测的请求,该flow1是固定或者可控的
            int flow1 = 1234;
            new Thread(new Runnable() {
                @Override
                public void run() {
                    runRequest(flow1);
                }
            }).start();
            //第二个请求进入,该请求是其他用户发起的请求,是干扰项
            int flow2 = 6789;
            new Thread(new Runnable() {
                @Override
                public void run() {
                    runRequest(flow2);
                }
            }).start();

        }

    }

    /**
     * 假设该方法为请求的处理方法
     */
    private static void runRequest(int flow){
        //设置流水
        setFlow(flow);
        //判断是否支持 https
        boolean supportHttps = condition1() && condition2() == 2 && "https".equals(condition3());
        //获取前缀,getPrefix的参数是我们的观测目标,看它是true还是false
        String prefix = getPrefix(supportHttps);
        //输出前缀
        System.out.println(prefix);
    }

    private static String getPrefix(boolean supportHttps) {
        supportHttps = subCondition();
        return supportHttps ? "https" : "http";
    }

    private static boolean condition1() {
        //复杂逻辑
        return true;
    }

    public static int condition2() {
        //复杂逻辑
        return 2;
    }

    public static String condition3() {
        //复杂逻辑
        return "https";
    }

    private static boolean subCondition() {
        //复杂逻辑
        return false;
    }

    /**
     * 存储线程流水映射
     */
    private static final ConcurrentHashMap<Long,Integer> flowMap = new ConcurrentHashMap<>(10);

    /**
     * 根据当前线程id获取流水
     * @return flow 流水值
     */
    private static int getFlow(){
        return flowMap.getOrDefault(Thread.currentThread().getId(),0);
    }

    /**
     * 为当前线程id设置流水值
     * @param flow 流水值
     */
    private static void setFlow(int flow){
        flowMap.put(Thread.currentThread().getId(),flow);
    }
}

2.观测的目标

getPrefix(boolean supportHttps) 方法被调用时,supportHttps 的值,到底是true还是false呢?

二、观测&排查流程

1.直接watch观测 getPrefix() 方法,拿到参数值

如上图,我们拿到了 getPrefix() 方法的入参值supportHttps,是 false 来的!

tips:通过静态方法拿到当前线程的flow并作为筛选条件 @com.company.TmpTest@getFlow()==1234 企业实践中,一般会将一些请求相关的信息放到可静态调用获取的地方,这就是筛选请求的重要利器

2.业务及逻辑分析与观测结果不符

boolean supportHttps = condition1() && condition2() == 2 && "https".equals(condition3()); 当我们从实际的业务和逻辑分析(代码没有呈现)看的时候,我们认为上面的表达值的值应该是 true 才对,为何观测到是false呢???是业务和逻辑分析错了吗?

到底是哪里出了问题呢?为了找到答案,我们需要再进一步的分析!

3.直接获取supportHttps变量的值?不可

getPrefix()方法的入参值其实就是 supportHttps 变量,我们只要获取到该变量的值就能确定逻辑分析推断是否有问题了!
但是,supportHttps 是方法内的临时变量,因此我们无法通过Arthas直接获取到它的值。

相信对很多入门Arthas的人来说,都会这样的疑问:Arthas可以获取到方法内的临时变量吗?
答案:可以,但又不完全可以!
分析:既然不能直接观测,我们一般可以通过观测使用到该临时变量的方法来间接观测它的值,就像第1点做的那样,只是本次我们对这个值有所怀疑。另外,一般定义变量,都是为了接收方法的返回值,或者是作为方法的参数,因此,这部分的变量值还是有机会拿到滴!

4.侧面求证,利用好短路机制

boolean supportHttps = condition1() && condition2() == 2 && "https".equals(condition3()); 从上边的代码看,supportHttps 变量就是通过表达式求出来的,因此我们可以观测表达式的执行情况呀!

分析:由于3个 condition方法 是通过 && 串起来的,又由于java中是有短路机制的,因此可以判定 condition1()==truecondition2()==true ,因为只有这样才会执行 condition3();

5.condition3()返回了啥?是它导致了 supportHttps 为false吗?

验证这个也非常简单,直接watch一下即可!

可以看到,condition3() 的返回值是 https,由此 "https".equals("https") == true

6.出现了!出现了!矛盾的 supportHttps

通过上边的排查, 我们知道表达式 condition1() && condition2() == 2 && "https".equals(condition3())的值是true,那么 supportHttps 应该就是 true 才对啊!!为什么在 getPrefix() 方法的参数观测的时候,它是false来的呢???
难道Arthas有什么隐藏的Bug?

7.重新审视 watch 的使用

我们都知道,watch是可以指定观测的时间点的,方法执行前和方法执行后的参数是有可能不一致的,但是这种不一致的情况一般是指对象类型中的内容被修改了。而我们观测 getPrefix() 方法时,虽然观测的是方法执行之后参数值,但是,按理说,getPrefix() 方法的入参是一个 boolean 类型啊,它不是对象类型,即使方法执行过程中有对参数进行重新赋值,但方法结束后它的值也不应该会变啊?

private static String getPrefix(boolean supportHttps) {
    //改变了supportHttps的值
    supportHttps = subCondition();
    return supportHttps ? "https" : "http";
}

8.没办法了,试一下吧,反正也没什么损失

本来在排查过程中,女朋友也提出了会不会是因为在方法执行后观测,所以看到的结果为false,但是我第一反应就是这不可能,值传递和地址传递我可熟了,值传递在方法执行完之后怎么会变呢!!所以排查重点还是放在方法定位(多次调用和有重载)和condition的确认上,顺手还给她讲了一下地址传递的例子,对象啊,JsonObj啊啥的才会变。

一直到最后(晚上12点多了),当时实在没有办法了,想着只能第二天开新实例开debug导流量了,最后抱着试一试的心态对watch加了-b参数,卧槽!!!还真是true,纳尼??卧槽?什么东西?

三、引出问题

问题:使用watch来观测方法参数(boolean类型),在方法中对该参数进行重新赋值的时候,执行前观测和执行后观测的参数结果不一致!

四、求证

1.毋庸置疑的值传递

参数是 boolean 是值传递,这肯定是没错的。

上图可见,执行完方法后,supportHttps的值是true。所以问题一定是出在Arthas观测的使用上。

2.Arthas中watch命令的实现

想要找到答案,那就必须了解arthas对watch命令的实现了,好在arthas提供了jad命令,并且允许逆编译增强过的类,让我们可以很方便地看到增强的情况。
被观测的方法(getPrefix())逆编译结果:

方法被调用时外层方法(runRequest())逆编译结果:

3.恍然大明白

方法结束之后 进行信息收集的两种做法:

a.方法内部收集代码示例

private static void runRequest(int flow){
    ...
    /************************* 调用处不做处理 ***************************/
    String prefix = getPrefix(supportHttps);
}

private static String getPrefix(boolean supportHttps) {
    /************************* 方法内部收集参数信息 ***************************/
    try {
        //改变了supportHttps的值
        supportHttps = subCondition();
        return supportHttps ? "https" : "http";
    }finally {
        //方法内记录,其值会以方法内最后值为准,也就是方法内对该值进行变更会影响到记录的值
        recordParams(supportHttps);
    }
}

b.调用处收集代码示例

private static void runRequest(int flow){
    ...
    /************************* 调用处收集参数信息 ***************************/
    try{
        String prefix = getPrefix(supportHttps);
    }finally {
        //调用处记录,此时 supportHttps 是值传递,因此方法内部值改变不会影响到此处记录的值
        recordParams(supportHttps);
    }

}

private static String getPrefix(boolean supportHttps) {
    /************************* 方法内部不做处理 ***************************/
    //改变了supportHttps的值
    supportHttps = subCondition();
    return supportHttps ? "https" : "http";
}

结果显而易见,在 方法结束之后 收集参数值的两种方法中,采用 方法内部收集 的时候,拿到的是方法内更改过的值,这也是Arthas采用的方式。

五、写在最后

当我们看到 方法结束之后的参数值的变化 时,很自然而然地想起考试和面试都出现较多的 值传递和地址传递 问题 ,也会很理所当然地认为,这个参数是不会变的;但是我们忽略了Arthas是怎么实现这个功能的,它的原理大致如何,进而导致一些误解的出现。

作者:wingli
链接:https://juejin.cn/post/7024408089302433822

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 216,470评论 6 501
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,393评论 3 392
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 162,577评论 0 353
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,176评论 1 292
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,189评论 6 388
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,155评论 1 299
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,041评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,903评论 0 274
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,319评论 1 310
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,539评论 2 332
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,703评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,417评论 5 343
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,013评论 3 325
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,664评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,818评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,711评论 2 368
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,601评论 2 353

推荐阅读更多精彩内容