Android性能监控：主循环性能统计LooperStatsSe

作者：飞起来_飞过来

简介

在Android性能监控和优化领域，一个会影响App性能表现的因素与Handler Message Looper机制有关。当Looper里面的Message处理不及时、或数量太多占用过多处理时间时，可能会出现卡顿感，并且不容易定位到卡顿的Message和慢方法。

Android本身提供了LooperStats机制来统计和监测Message的处理，并且可以通过LooperStatsService来统计和记录，方便调试和分析。

LooperStatsService详解

由SystemServer创建、Settings数据库变更触发启动

LooperStatsService是一个系统服务，由SystemServer在开机阶段启动。按照系统服务的接口要求，它是通过LooperStatsService.Lifecycle这个类被启动的。

启动流程主要是初始化LooperStats、LooperStatsService和SettingsObserver。
SettingsObserver在Settings数据库的值发生变化时回调，回调方法中根据特定格式来解析数据库的内容，根据解析的内容确定是否开始监控、监控频率等。

数据库是Settings.Global.looper_stats，对应的数据库格式如下：使用键值对（key=value）来表示一个参数和它的值，多个键值对之间用逗号分隔。参数包括：sampling_interval控制采样频率（毫秒，默认1000），track_screen_state控制是否跟踪屏幕状态（默认false）。

也就是说，执行如下adb指令，写入Settings数据库，就能让LooperStatsService开始采样监控App的主循环Looper：

settings put global looper_stats sampling_interval=100,track_screen_state=true,enabled=true

启动流程非常简单，先参数值初始化，然后将Observer设置到Looper。

也可以采用adb命令的方式来控制：

# cmd looper_stats
looper_stats commands:
  enable: Enable collecting stats.
  disable: Disable collecting stats.
  sampling_interval: Change the sampling interval.
  reset: Reset stats.

Looper Message Dispatch流程实现监控

我们知道Android的主线程的死循环被Looper封装，在Looper内部取出MessageQueue内排队的Message，根据Message.target和callback，将其派发到对应的处理方法中，实现消息循环。实现监控的流程也很容易，在消息派发前回调到监控者，消息由处理函数处理完成后，回调监控者，即可实现让监控着感知消息处理的进度。

Looper本身提供了内部接口类Observer提供回调接口来实现上述需求：

public interface Observer {
        Object messageDispatchStarting();
        void messageDispatched(Object token, Message msg);
        void dispatchingThrewException(Object token, Message msg, Exception exception);
    }

前两个接口分别在一个消息处理前、一个消息完成处理时回调。第三个接口是Message处理过程中抛出了异常时回调。

App主事件循环实际上可以抽象为如下流程：

public static void loop() {
        final Looper me = myLooper();
        final MessageQueue queue = me.mQueue;

        boolean slowDeliveryDetected = false;

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

            // LooperStatsService打开的情况下，会设置sObserver
            final Observer observer = sObserver;

            long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
            long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
            if (thresholdOverride > 0) {
                slowDispatchThresholdMs = thresholdOverride;
                slowDeliveryThresholdMs = thresholdOverride;
            }
            final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
            final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);

            final boolean needStartTime = logSlowDelivery || logSlowDispatch;
            final boolean needEndTime = logSlowDispatch;
            
            final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
            final long dispatchEnd;
            
            Object token = null;
            if (observer != null) {
                token = observer.messageDispatchStarting();
            }
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    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);
                }
            }
            
            if (logSlowDelivery) {
                if (slowDeliveryDetected) {
                    if ((dispatchStart - msg.when) <= 10) {
                        Slog.w(TAG, "Drained");
                        slowDeliveryDetected = false;
                    }
                } else {
                    if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
                            msg)) {
                        // Once we write a slow delivery log, suppress until the queue drains.
                        slowDeliveryDetected = true;
                    }
                }
            }
            if (logSlowDispatch) {
                showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
            }
    }

简单来说Looper每次处理Message的流程就是，在消息发给App处理之前、之后分别回调Observer的接口，实现记录。其中，慢速的Message处理也会在这里检查并打印日志。

LooperStatsService实际上利用了Looper提供的Observer机制，打开后它设置了sObserver，接受Message Loop的回调，在回调中记录数据并做统计。

LoopStats实现性能数据记录

LooperStatsService借助LoopStats实现数据记录。在Message派发前，记录三个数据：开机后经过的时间（elpased real time，包含系统休眠）、开机后经过的时间（uptime，不包括系统休眠）、当前线程消耗的时间。

public Object messageDispatchStarting() {
        if (deviceStateAllowsCollection() && shouldCollectDetailedData()) {
            DispatchSession session = mSessionPool.poll();
            session = session == null ? new DispatchSession() : session;
            session.startTimeMicro = getElapsedRealtimeMicro();
            session.cpuStartMicro = getThreadTimeMicro();
            session.systemUptimeMillis = getSystemUptimeMillis();
            return session;
        }
        return DispatchSession.NOT_SAMPLED;
    }

其中，deviceStateAllowsCollection()的判断逻辑是“设备未在充电状态”，shouldCollectDetailedData()用于实现上述设置的采样时间间隔。

LooperStatsService区分不同的Message分别进行统计，统计的信息存储于Entry中：

private static class Entry {
        public final int workSourceUid;
        public final Handler handler;
        public final String messageName;
        public final boolean isInteractive;
        public long messageCount;
        public long recordedMessageCount;
        public long exceptionCount;
        public long totalLatencyMicro;
        public long maxLatencyMicro;
        public long cpuUsageMicro;
        public long maxCpuUsageMicro;
        public long recordedDelayMessageCount;
        public long delayMillis;
        public long maxDelayMillis;
        ...
}

其中，主要信息是messageName，messageCount记录消息派发的次数，recordedMessageCount记录消息被LooperStats采样并记录到的次数。

messageCount和recordedMessageCount的差异是：每个消息都让messageCount +1，而满足前述参数设置的采样时间间隔的消息才会被采样、记录，被采样的消息才会让recordedMessageCount +1。
totalLatencyMicro记录该类型的消息花费的总时间，计算方法是消息派发前、处理完成后两者的elpased time（开机后经过的时间，包含系统或进程休眠）时间差。

maxLatencyMicro计算该类型的消息在某一次派发、处理花费的最大时间，同样是elpased time。

cpuUsageMicro和maxCpuUsageMicro，分别计算该类型消息处理时间的总和、最大耗时。计算方法是取得线程运行时间，减去派发前的线程运行时间（即messageDispatchStarting()记录的起始值）即可得到线程处理该消息的耗时（线程实际工作时间，不包含休眠）
App Message Loop还有一个很大的特点，就是其Message可以指定某个时间再出发（如postDelayed()发出的Message）。那么在一些场景下，要求定时处理的Message可能不能准时触发，而是有一定的延时，可能也会存在性能问题或体验问题，甚至是功能异常。delayMills、maxDelayMills就用于记录发生这些延时的总时间、最大延时。计算方法是，计算派发前、处理后两者的uptime时间差（系统或进程休眠时不计时），大于Message的目标时间的值就是delay的大小。对应的，recordedDelayMessageCount记录延时发生的次数。注意这三个delay数据只针对Message.when有值（即指定了触发时间的Message）的情况才会统计。

dumpsys获取性能监控数据
可以在adb shell执行dumpsys looper_stats获取性能统计数据。

dumpsys looper_stats
Start time: 2023-05-05 17:17:08
On battery time (ms): 54297
work_source_uid,thread_name,handler_class,message_name,is_interactive,message_count,recorded_message_count,total_latency_micros,max_latency_micros,total_cpu_micros,max_cpu_micros,recorded_delay_message_count,total_delay_millis,max_delay_millis,exception_count
-1,PowerManagerService,android.os.Handler,0x2,false,5,1,72,72,68,68,1,0,0,0
com.android.systemui/u0a139,WifiHandlerThread,com.android.wifi.x.com.android.internal.util.StateMachine$SmHandler,0x20053,false,9,1,31576,31576,9055,9055,1,1,1,0
com.tencent.android.qqdownloader/u0a164,PowerManagerService,android.os.Handler,0x2,false,4,1,1360,1360,98,98,1,0,0,0
com.tencent.android.qqdownloader/u0a164,SchedPolicyExecutor,com.android.server.performance.PolicyExecutor$1,0x1,false,7,1,22,22,20,20,1,0,0,0

如上，当CPU时间、消息处理时间、消息延迟时间等出现异常数值时，即可通过对应的线程、消息来确定耗时的消息、执行缓慢的流程。