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

---

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

可以通过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等生命周期方法的执行时间给打印出来，但是结果和预期并不符合。

结果：

失败了。。。

用这种方法是统计不到的 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();
        }
    }
}

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

结果：

这次和预期的完全符合了

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

Dispatching to Handler (android.view.ViewRootImpl$ViewRootHandler)770eec3android.view.View$PerformClick@9ede30f: 0

所以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();
        });

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

那我们再回过去看看

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

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

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

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

是在 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面试题：主线程任务队列耗时情况

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