【问答集】主线程任务队列耗时如何分析?

【问答集】主线程任务队列耗时如何分析?

可以通过Looper.loop()方法的log进行查看。

在Android中所有的事件(Activity、Fragment生命周期方法,点击事件等)最终都会被转换(封装)成Message,再交给主线程去执行。

任务队列耗时可以理解为处理每个msg的时间。

Looper.loop()方法分析:(Android api 30)

    public static void loop() {
        final Looper me = myLooper();

        me.mInLoop = true;
        final MessageQueue queue = me.mQueue;

        for (;;) {
            Message msg = queue.next(); // might block
            if (msg == null) {
                // No message indicates that the message queue is quitting.
                
                // Q1、这个地方为什么可以return呢?第一个猜测是系统对主线程的message进行了非null验证,保证了到这里的msg不会为null,不然主线程的loop方法都退出了。第二个猜测是系统有什么方法可以把loop方法再调用一下,保证循环可用。这个需要再做研究。
                return;
            }

            // here1:关键就在这里,开始的时候,会去打印一条日志
            
            // This must be in a local variable, in case a UI event sets the logger
            final Printer logging = me.mLogging;
            if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }
                // here2:msg分发给对应的target(也就是handler)进行处理
                msg.target.dispatchMessage(msg);

            // here3:关键就在这里,结束的时候,也会去打印一条日志,通过计算两条日志的时间差,就可以得到每条消息的处理时间
            if (logging != null) {
                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            }
        }
    }

分析:

1、主要的方法就是靠注释:here1-here3

2、分析源码的时候新发现了一个问题(注释:Q1),要去思考一下。

验证1——生命周期耗时

public class MainActivity extends AppCompatActivity {
    private static final String TAG = "MainActivity";
    private long lastTime;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        long startTime = System.currentTimeMillis();
        Log.i(TAG, "onCreate:" + startTime);

        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        mockSpendTimeOperate();
        
        Looper.myLooper().setMessageLogging(new Printer() {
            @Override
            public void println(String x) {
                Log.i(TAG, x);
                if (lastTime != 0L) {
                    long spendTime = System.currentTimeMillis() - lastTime;
                    lastTime = 0L;
                    Log.i(TAG, "println: " + spendTime);
                } else {
                    lastTime = System.currentTimeMillis();
                }
            }
        });
        Log.i(TAG, "onCreate:" + (System.currentTimeMillis() - startTime));
    }

    private void mockSpendTimeOperate() {
        try {
            Thread.sleep(1000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

这里我预期的是:能够把onCreate等生命周期方法的执行时间给打印出来,但是结果和预期并不符合。

结果:
image-20210802204749204.png

失败了。。。

用这种方法是统计不到的 Activity 的生命周期方法。

Q2:为什么会统计不到呢?

是我我这种方法不对?还是原理就没理解好呢?

看来还是要对Activity的生命周期方法调用过程再做一个分析。

Q3:那统计耗时的方法有哪些呢?

1、手动加日志,再计算

2、字节码插入日志代码进行统计(忘了叫啥了,这个得再学一下)

3、还有啥呢?

那既然不能统计生命周期的方法,就再看看它能不能统计到我们自己发的msg耗时:

验证2:统计我们自己写的代码、发的msg

public class MainActivity extends AppCompatActivity {
    private static final String TAG = "MainActivity";
    private long lastTime;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        long startTime = System.currentTimeMillis();
        Log.i(TAG, "onCreate:" + startTime);

        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        // here:就用一个点击事件来测一下
        Button btnTestMsg = findViewById(R.id.btn_testMsg);
        btnTestMsg.setOnClickListener(v -> mockSpendTimeOperate());

        mockSpendTimeOperate();

        // 首先拿到 主线程的 looper,把Printer对象设置进去。
        // 这里的目的就是统计耗时
        Looper.myLooper().setMessageLogging(new Printer() {
            @Override
            public void println(String x) {
                Log.i(TAG, x);
                if (lastTime != 0L) {
                    long spendTime = System.currentTimeMillis() - lastTime;
                    lastTime = 0L;
                    Log.i(TAG, "msg spendTime: " + spendTime);
                } else {
                    lastTime = System.currentTimeMillis();
                }
            }
        });
        Log.i(TAG, "onCreate:" + (System.currentTimeMillis() - startTime));
    }

    private void mockSpendTimeOperate() {
        try {
            Thread.sleep(1000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

这里用点击事件来测一下,能不能打印出时间来呢?

结果:
image-20210802215027114.png

这次和预期的完全符合了

然后再来看看系统给的日志:

Dispatching to Handler (android.view.ViewRootImplViewRootHandler) {770eec3} android.view.ViewPerformClick@9ede30f: 0

image-20210802215316683.png

因此Button点击事件的msg信息为:

target:ViewRootImpl$ViewRootHandler,处理msg的handler。也是发送这条msg的Handler。

callback:android.view.View$PerformClick,msg的callback实际就是一个Runnable,就是一坨可执行的代码。

Message.java

/*package*/ Runnable callback;

callback和handlerMessage方法的关系如下:

Handler.java

public void dispatchMessage(@NonNull Message msg) {
    if (msg.callback != null) {
        handleCallback(msg);
    } else {
        if (mCallback != null) {
            if (mCallback.handleMessage(msg)) {
                return;
            }
        }
        handleMessage(msg);
    }
}

    private static void handleCallback(Message message) {
        message.callback.run();
    }

msg.what:找到具体的事件,一般都是通过Switch去匹配。

因此,Button的点击就执行了callback的run方法,如下:
private final class PerformClick implements Runnable {
    @Override
    public void run() {
        recordGestureClassification(TOUCH_GESTURE_CLASSIFIED__CLASSIFICATION__SINGLE_TAP);
        performClickInternal();
    }
}

    private boolean performClickInternal() {
        // Must notify autofill manager before performing the click actions to avoid scenarios where
        // the app has a click listener that changes the state of views the autofill service might
        // be interested on.
        notifyAutofillManagerOnClick();

        return performClick();
    }

    public boolean performClick() {
        // We still need to call this method to handle the cases where performClick() was called
        // externally, instead of through performClickInternal()
        notifyAutofillManagerOnClick();

        final boolean result;
        final ListenerInfo li = mListenerInfo;
        if (li != null && li.mOnClickListener != null) {
            playSoundEffect(SoundEffectConstants.CLICK);
            
            // here1:执行了我们的onClick事件
            li.mOnClickListener.onClick(this);
            result = true;
        } else {
            result = false;
        }

        sendAccessibilityEvent(AccessibilityEvent.TYPE_VIEW_CLICKED);

        notifyEnterOrExitForAutoFillIfNeeded(true);

        return result;
    }

看注释here1处,最终执行了我们的onClick方法。

那还有一个问题?msg是在哪里发送的呢?

首先我们知道发送msg的Handler是android.view.ViewRootImpl$ViewRootHandler,但一个Handler是可以在多处使用的,我们试试这样找:

在点击事件里把调用栈打印出来:

        Button btnTestMsg = findViewById(R.id.btn_testMsg);
        btnTestMsg.setOnClickListener(v -> {
            mockSpendTimeOperate();
            Exception dumpStack = new Exception("dumpStack");
            dumpStack.printStackTrace();
        });
image-20210802222659171.png
image-20210802223357490.png

很可惜,毫无收获,思路不对。

那我们再回过去看看

private final class PerformClick implements Runnable {
    @Override
    public void run() {
        recordGestureClassification(TOUCH_GESTURE_CLASSIFIED__CLASSIFICATION__SINGLE_TAP);
        performClickInternal();
    }
}

前面说了,最终会调用这坨代码,那看看它在哪调用的就好了(即这个callback是在哪设置给msg的)。

好在幸运的是,这个 PerformClick 是private的。

直接搜素 new PerformClick()找到唯一使用地方:

image-20210802223357490.png

是在 onTouchEvent()中的。看到这肯定就知道是走的事件分发了,一切都串联了起来。正着分析,反着分析,都是一样的。

也就是从 Activity 传到 view 的那套东西(事件方法:Activity-Window-DecorView-ViewGroup)了。

但到这里还是没有回答:msg是从哪里发出来的呢???

Q4:问题又来了,点击事件的msg是从哪里发出来的呢?

还没搞懂,再朝着这个方向学一下。

思考:这个就沿着找——调用 Activity#dispatchTouchEvent()方法的地方。然后再往上找。

Q5:事件又是如何传递到Activity的呢?

这个代码我还没看,又有新任务了。

然后其实看Looper.loop()方法时,还发现了个东西:

Looper.java

    private static Observer sObserver;

    public static void setObserver(@Nullable Observer observer) {
        sObserver = observer;
    }

    public static void loop() {
        final Looper me = myLooper();

        me.mInLoop = true;
        final MessageQueue queue = me.mQueue;

        for (;;) {
            Message msg = queue.next(); // might block
            if (msg == null) {
                // No message indicates that the message queue is quitting.
                return;
            }

            // Make sure the observer won't change while processing a transaction.
            final Observer observer = sObserver;

            final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
            final long dispatchEnd;
            Object token = null;
            if (observer != null) {
                // here1:
                token = observer.messageDispatchStarting();
            }
            long origWorkSource = ThreadLocalWorkSource.setUid(msg.workSourceUid);
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    // here2:
                    observer.messageDispatched(token, msg);
                }
                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
            } catch (Exception exception) {
                if (observer != null) {
                    observer.dispatchingThrewException(token, msg, exception);
                }
                throw exception;
            } finally {
                ThreadLocalWorkSource.restore(origWorkSource);
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }
           
        }
    }

我们可以设一个observe对象进去,那么在dispatch msg 的时候就会回调我们。

observe接口提供了3个方法,根据上面的代码,我们可以在注释here1处,返回一个当前时间,再在结束的时候here2处,算一下耗时,也可以计算时间,算是一个简单的运用。

public interface Observer {
    /**
     * Called right before a message is dispatched.
     *
     * <p> The token type is not specified to allow the implementation to specify its own type.
     *
     * @return a token used for collecting telemetry when dispatching a single message.
     *         The token token must be passed back exactly once to either
     *         {@link Observer#messageDispatched} or {@link Observer#dispatchingThrewException}
     *         and must not be reused again.
     *
     */
    Object messageDispatchStarting();

    /**
     * Called when a message was processed by a Handler.
     *
     * @param token Token obtained by previously calling
     *              {@link Observer#messageDispatchStarting} on the same Observer instance.
     * @param msg The message that was dispatched.
     */
    void messageDispatched(Object token, Message msg);

    /**
     * Called when an exception was thrown while processing a message.
     *
     * @param token Token obtained by previously calling
     *              {@link Observer#messageDispatchStarting} on the same Observer instance.
     * @param msg The message that was dispatched and caused an exception.
     * @param exception The exception that was thrown.
     */
    void dispatchingThrewException(Object token, Message msg, Exception exception);
}

知识点:

Handler机制、Looper#loop()、点击事件分发

待解决问题汇总:

Q1、下面注释here1处为什么可以return呢?第一个猜测是系统对主线程的message进行了非null验证,保证了到这里的msg不会为null,不然主线程的loop方法都退出了。第二个猜测是系统有什么方法可以把loop方法再调用一下,保证循环可用。这个需要再做研究。

public static void loop() {
    final Looper me = myLooper();

    me.mInLoop = true;
    final MessageQueue queue = me.mQueue;

    for (;;) {
        Message msg = queue.next(); // might block
        if (msg == null) {
            // No message indicates that the message queue is quitting.
            
            // here1
            return;
        }

Q2:为什么会统计不到呢?

是我我这种方法不对?还是原理就没理解好呢?

看来还是要对Activity的生命周期方法调用过程再做一个分析。

Q3:那统计耗时的方法有哪些呢?

1、手动加日志,再计算

2、字节码插入日志代码进行统计(忘了叫啥了,这个得再学一下)

3、还有啥呢?

Q4:问题又来了,点击事件的msg是从哪里发出来的呢?

还没搞懂,再朝着这个方向学一下。

思考:这个就沿着找——调用 Activity#dispatchTouchEvent()方法的地方。然后再往上找。

Q5:事件又是如何传递到Activity的呢?

这个代码我还没看,又有新任务了。

参考:

1、阿里盒马Android面试题:主线程任务队列耗时情况

他讲的也没有很清楚,比如要如何实践也没讲,算是给了个方向。

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

推荐阅读更多精彩内容