简介
在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:
1
   | settings put global looper_stats sampling_interval=100,track_screen_state=true,enabled=true
   | 
 
启动流程非常简单,先参数值初始化,然后将Observer设置到Looper。
也可以采用adb命令的方式来控制:
1 2 3 4 5 6
   |  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提供回调接口来实现上述需求:
1 2 3 4 5
   | public interface Observer {         Object messageDispatchStarting();         void messageDispatched(Object token, Message msg);         void dispatchingThrewException(Object token, Message msg, Exception exception);     }
  | 
 
前两个接口分别在一个消息处理前、一个消息完成处理时回调。第三个接口是Message处理过程中抛出了异常时回调。
App主事件循环实际上可以抽象为如下流程:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71
   | public static void loop() {         final Looper me = myLooper();         final MessageQueue queue = me.mQueue;
          boolean slowDeliveryDetected = false;
          for (;;) {             Message msg = queue.next();              if (msg == null) {                                  return;             }
                           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)) {                                                  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,不包括系统休眠)、当前线程消耗的时间。
1 2 3 4 5 6 7 8 9 10 11
   | 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中:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17
   | 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获取性能统计数据。
1 2 3 4 5 6 7
   | 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
   | 
 
如上,当CPU时间、消息处理时间、消息延迟时间等出现异常数值时,即可通过对应的线程、消息来确定耗时的消息、执行缓慢的流程。