LooperStatsService的使用与功能实现分析

本文所有代码基于Android 12

今天我们来认识一下这个比较不为人所知的framework层的系统服务,LooperStatsService

创作不易,请求一个一键三连,关注、点赞、觉得有用或者有趣好玩的话可以转发给朋友看看😋

未经同意不得转载(防止卖课的洗文)

LooperStatsService是一个系统服务,在SystemServer初始化的时候会同时初始化这个服务,并可以监测SystemServer中Looper的消息调度,下面简单介绍下这个服务有什么功能。

  1. 统计msg被执行时的消耗的时间、消耗的cpu时间、执行延迟的时间。
  2. 统计msg被执行的次数、执行中错误的次数、执行延迟的次数。
  3. 提供adb shell dump服务,把记录的数据打印出来。

LooperStatsService的使用

通过执行命令来手动打开或者关闭SystemServer中Looper的消息调度的数据统计

adb shell setprop debug.sys.looper_stats_enabled true // 打开
adb shell setprop debug.sys.looper_stats_enabled false // 关闭

adb shell looper_stats enable // 打开
adb shell looper_stats disable // 关闭

执行下面的命令可以打印出统计的数据

adb shell dumpsys looper_stats

# 打印出来的数据长这样
Start time: 2022-04-09 02:53:46
On battery time (ms): 29576717
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,ActivityManager,com.android.server.am.BroadcastQueue$BroadcastHandler,0xc8,false,196,1,537,537,511,511,1,0,0,0
-1,OomAdjuster,android.os.Handler,0x0,false,72,1,7872,7872,7704,7704,1,0,0,0
-1,PowerManagerService,android.os.Handler,0x2,false,559,2,381,307,370,297,2,1,1,0
-1,PowerManagerService,android.os.Handler,android.app.LoadedApk$ReceiverDispatcher$Args$$ExternalSyntheticLambda0,false,62,1,117,117,113,113,1,0,0,0
-1,PowerManagerService,android.os.Handler,com.android.server.display.DisplayPowerState$4,false,1032,1,105,105,102,102,1,0,0,0
-1,PowerManagerService,android.view.Choreographer$FrameHandler,android.view.Choreographer$FrameDisplayEventReceiver,false,1086,2,9769,5866,4412,2248,2,0,0,0
-1,android.anim,android.os.Handler,com.android.server.wm.InputMonitor$UpdateInputWindows,false,764,2,682,523,449,292,2,1,1,0
-1,android.anim,android.os.Handler,com.android.server.wm.WindowSurfacePlacer$Traverser,false,274,1,673,673,599,599,1,1,1,0
-1,android.anim,android.view.Choreographer$FrameHandler,android.view.Choreographer$FrameDisplayEventReceiver,false,3694,7,1964,590,1417,447,7,6,2,0
-1,android.anim.lf,android.view.Choreographer$FrameHandler,android.view.Choreographer$FrameDisplayEventReceiver,false,1896,2,693,444,435,271,2,1,1,0
com.android.systemui/u0a87,main,android.os.Handler,0x425,false,576,1,29,29,29,29,1,0,0,0
com.android.systemui/u0a87,main,com.android.server.notification.NotificationManagerService$WorkerHandler,com.android.server.notification.NotificationManagerService$CancelNotificationRunnable,false,237,2,236,158,197,122,2,0,0,0
com.android.cellbroadcastreceiver.module/u0a93,android.ui,com.android.server.am.ActivityManagerService$UiHandler,com.android.server.am.UidObserverController$$ExternalSyntheticLambda0,false,17,1,308,308,309,309,1,0,0,0
com.wandoujia.phoenix2/u0a97,PowerManagerService,android.os.Handler,0x2,false,29,1,19,19,18,18,1,0,0,0
com.wandoujia.phoenix2/u0a97,batterystats-handler,android.os.Handler,com.android.server.am.BatteryStatsService$$ExternalSyntheticLambda11,false,48,1,191,191,191,191,1,0,0,0
com.wandoujia.phoenix2/u0a97,main,com.android.server.notification.NotificationManagerService$WorkerHandler,com.android.server.notification.NotificationManagerService$NotificationListeners$$ExternalSyntheticLambda5,false,6,2,407,213,405,213,2,1,1,0
com.tencent.qqmusic/u0a98,AudioService,com.android.server.audio.AudioService$AudioHandler,0x1d,false,8,1,119,119,117,117,1,0,0,0
com.tencent.qqmusic/u0a98,android.ui,com.android.server.am.ActivityManagerService$UiHandler,0x1f,false,225,1,32,32,32,32,1,0,0,0

一般关注以下这几个值就可以:total_latency_micros,max_latency_micros,total_cpu_micros,max_cpu_micros,后面会分析到这几个值是怎么计算出来的。

执行下面的命令可以重置统计的数据

adb shell looper_stats reset

执行下面的命令可以设置采样间隔,默认是1000,采样间隔越低,采样越频繁

adb shell looper_stats sampling_interval 2000 // 设置采样间隔为2000

通过执行下面的命令可以控制采样间隔、是否忽略电池状态(电池正在充电的时候会停止进行统计)、打开或者关闭SystemServer中Looper的消息调度的数据统计。(键值对顺序没有要求,只需要设置自己需要改变的键值对即可,不改变的可忽略)

adb shell settings put global looper_stats enabled=true,ignore_battery_status=false,track_screen_state=false,sampling_interval=2000

LooperStatsService在Looper中的作用

通过LooperStatsService这个名字可以看出,它是一个和Looper中的数据统计有关,而它会统计哪些Looper呢?我们带着疑问继续分析。下面代码只显示一些与LooperStatsService有关的代码,其他无关代码将会被省略。

在Looper中搜LooperStatsService字段,并不能直接搜到数据,但如果读过Looper源码的同学可能会知道,Looper中比较重要的方法是Looper#loopOnce方法,这个方法的功能是从MessageQueue中取出一条Message,然后分发到Message指定的target handler执行,我们从这个方法入手,看看能不能找到什么数据被收集到LooperStatsService中。

frameworks/base/core/java/android/os/Looper.java

private static boolean loopOnce(final Looper me, final long ident, final int thresholdOverride) {
    // ...
    // 1
    final Observer observer = sObserver;

    // ...
    if (observer != null) {
        token = observer.messageDispatchStarting();
    }
    // ...
    try {
        // ...
        // 2
        msg.target.dispatchMessage(msg);
        if (observer != null) {
            observer.messageDispatched(token, msg);
        }
        // ...
    } catch (Exception exception) {
        if (observer != null) {
            observer.dispatchingThrewException(token, msg, exception);
        }
        throw exception;
    } finally {
        // ...
    }
    // ...

    return true;
}

注释2作为Looper#loopOnce中最重要的调用,它的前后分别被observer调用messageDispatchStartingmessageDispatched包围起来了,如果dispatchMessage发生异常还会在catch中通过dispatchingThrewException调用反馈给observer,从1处可以看到这里有一个全局静态变量sObserver赋值给observer变量,而sObserver作为Looper的全局静态变量,在初始化的时候为null,通过调用Looper#setObserver的静态方法可以给Looper设置一个Observer,但这个是一个@hide方法,但通过反射和绕过hidden api应用也是可以给自己的Looper设置这个Observer。回归正题,通过查看Looper#setObserver方法的调用方,可以看到在系统源码中,LooperStatsService#setEnabled会调用此方法。

frameworks/base/services/core/java/com/android/server/LooperStatsService.java

private void setEnabled(boolean enabled) {
    if (mEnabled != enabled) {
        mEnabled = enabled;
        mStats.reset();
        mStats.setAddDebugEntries(enabled);
        Looper.setObserver(enabled ? mStats : null);
    }
}

这里LooperStatsService把mStats设置到自己的Looper中作为Observer,由此可以看出,Looper数据统计的核心类就是LooperStats mStats,在LooperStatsService创建的时候创建出来

frameworks/base/services/core/java/com/android/server/LooperStatsService.java

public Lifecycle(Context context) {
    super(context);
    // DEFAULT_SAMPLING_INTERVAL = 1000
    // DEFAULT_ENTRIES_SIZE_CAP = 1500
    mStats = new LooperStats(DEFAULT_SAMPLING_INTERVAL, DEFAULT_ENTRIES_SIZE_CAP);
    mService = new LooperStatsService(getContext(), mStats);
    mSettingsObserver = new SettingsObserver(mService);
}

所以这里可以大致总结一下,LooperStatsService在初始化的时候创建出LooperStats mStats,并通过Looper.setObserver设置到SystemServer的Looper中(功能打开的情况下),作为统计消息被分发之前messageDispatchStarting、消息执行之后messageDispatched、消息执行异常dispatchingThrewException的插桩。这里可以看到DEFAULT_ENTRIES_SIZE_CAP的值为1500,而LooperStats中没有其他方法可以更改这个值的函数,所以这里统计的msg的上限就是1500条(也可以说是1500种msg)。

数据统计类LooperStats解析

LooperStats实现了接口Looper.Observer

/** {@hide} */
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);
}

messageDispatchStarting

LooperStats是这样来实现messageDispatchStarting接口函数的:

frameworks/base/core/java/com/android/internal/os/LooperStats.java

@Override
public Object messageDispatchStarting() {
    // 判断是否采样这个msg 不采样则返回DispatchSession.NOT_SAMPLED
    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;
}

private static class DispatchSession {
    static final DispatchSession NOT_SAMPLED = new DispatchSession();
    public long startTimeMicro;
    public long cpuStartMicro;
    public long systemUptimeMillis;
}

返回一个DispatchSession对象作为被trace的message的token,而DispatchSessionLooperStats的一个静态内部类,里面包含三个long类型的变量,都是表示消息分发之前的时间,分别是

  • startTimeMicro: 开机到现在包括系统深度睡眠的微秒 SystemClock.elapsedRealtimeNanos() / 1000
  • cpuStartMicro: 当前线程占用cpu的微秒 SystemClock.currentThreadTimeMicro()
  • systemUptimeMillis: 开机到现在不包括深度睡眠的毫秒 SystemClock.uptimeMillis()

接下来的所有数据都是根据以上三个值作为基础值,而进行统计的。

messageDispatched(Object token, Message msg)

当消息被分发之后,把当前的时间和之前存下来的数据进行相减,则是执行这条消息所花费的时间,代码如下:

frameworks/base/core/java/com/android/internal/os/LooperStats.java

@Override
public void messageDispatched(Object token, Message msg) {
    // ...
    DispatchSession session = (DispatchSession) token;
    Entry entry = findEntry(msg, /* allowCreateNew= */session != DispatchSession.NOT_SAMPLED);
    if (entry != null) {
        synchronized (entry) {
            // 自加msg执行的次数
            entry.messageCount++;
            // messageDispatchStarting返回DispatchSession.NOT_SAMPLED则不采样此次的dispatch
            if (session != DispatchSession.NOT_SAMPLED) {
                entry.recordedMessageCount++;
                final long latency = getElapsedRealtimeMicro() - session.startTimeMicro;
                final long cpuUsage = getThreadTimeMicro() - session.cpuStartMicro;
                entry.totalLatencyMicro += latency;
                entry.maxLatencyMicro = Math.max(entry.maxLatencyMicro, latency);
                entry.cpuUsageMicro += cpuUsage;
                entry.maxCpuUsageMicro = Math.max(entry.maxCpuUsageMicro, cpuUsage);
                if (msg.getWhen() > 0) {
                    final long delay = Math.max(0L, session.systemUptimeMillis - msg.getWhen());
                    entry.delayMillis += delay;
                    entry.maxDelayMillis = Math.max(entry.maxDelayMillis, delay);
                    entry.recordedDelayMessageCount++;
                }
            }
        }
    }
    // ...
}

private static class Entry {
    // 标识哪个uid把msg enqueue到MessageQueue 只会在system_server进程使用
    public final int workSourceUid; 
    // msg的target handler
    public final Handler handler;
    // 有callback的handler为callback类名 没有callback则为msg.what的十六进制表示
    public final String messageName;
    // 标识执行这条msg时候的屏幕的亮灭 默认不跟踪这个值 为false
    public final boolean isInteractive;
    // 该msg被执行的次数,如果messageDispatchStarting返回DispatchSession.NOT_SAMPLED
    // messageDispatched会自加messageCount,而不自加recordedMessageCount
    public long messageCount;
    // 该msg被执行且采样到的次数
    public long recordedMessageCount;
    // 执行这个msg翻车的次数(回调dispatchingThrewException)
    public long exceptionCount;
    // 执行这个msg总的消耗的时间
    public long totalLatencyMicro;
    // 执行这个msg最大消耗的时间
    public long maxLatencyMicro;
    // 执行这个msg消耗的总cpu时间
    public long cpuUsageMicro;
    // 执行这个msg消耗的最大的cpu时间
    public long maxCpuUsageMicro;
    // 这个msg被延迟执行的次数
    public long recordedDelayMessageCount;
    // 这个msg被延迟执行的累加毫秒数
    public long delayMillis;
    // 这个msg被延迟执行的最大延迟时间
    public long maxDelayMillis;
}

Entry作为message所有数据记录的类,作为静态内部类声明在LooperStats

dispatchingThrewException(Object token, Message msg, Exception exception)

当消息执行翻车的时候,翻车的次数也会被执行下来

frameworks/base/core/java/com/android/internal/os/LooperStats.java

@Override
public void dispatchingThrewException(Object token, Message msg, Exception exception) {
    // ...
    if (entry != null) {
        synchronized (entry) {
            entry.exceptionCount++;
        }
    }

    // ...
}

几个有趣的地方

有趣一LooperStatsService在初始化读取了配置中这个键track_screen_state的值,并执行自己的setTrackScreenInteractive函数,但是最后并不会设置到所有数据统计的地方LooperStats,所以在配置中配置这个值是没有效果的。

frameworks/base/services/core/java/com/android/server/LooperStatsService.java

private void setTrackScreenInteractive(boolean enabled) {
    if (mTrackScreenInteractive != enabled) {
        // 没有调用
        // mStats.setTrackScreenInteractive(enable);
        mTrackScreenInteractive = enabled;
        mStats.reset();
    }
}

// 正确示范
private void setIgnoreBatteryStatus(boolean ignore) {
    if (mIgnoreBatteryStatus != ignore) {
        // 调用了
        mStats.setIgnoreBatteryStatus(ignore);
        mIgnoreBatteryStatus = ignore;
        mStats.reset();
    }
}

这个值的作用是设置消息执行与亮灭屏的关联,设置关联的话,亮屏和灭屏是两种不一样的统计数据,也就是亮屏下执行这条msg是一个entry,灭屏下执行这条数据是另外一个entry,可能某些msg的耗时对于亮屏或者灭屏下的状态会比较敏感,所以需要分开统计,默认为false。如果真的想消息统计关联亮灭屏可以手动调一下LooperStats#setTrackScreenInteractive,记得调用之后一定要reset一下LooperStats中的数据,即调用LooperStats#reset,重新统计数据。

有趣二LooperStats类中有两个比较特殊的Entry

frameworks/base/core/java/com/android/internal/os/LooperStats.java

private final Entry mOverflowEntry = new Entry("OVERFLOW");
private final Entry mHashCollisionEntry = new Entry("HASH_COLLISION");

mOverflowEntry的作用:当当前存储的entries数量多于初始化时设置的值时(1500种msg),就会把后面所有与前面1500种不同的msg的统计数据存入到这个mOverflowEntry中。

想想其实也是这个道理,前面都出现过1500种msg,那后面的msg的统计的收益也就不大了。其实也可以做成这样:如果某些msg的耗时太大,可以把前面耗时不大的Entry替换,这样的策略,毕竟这个服务存在的意义就是帮开发者把一些耗时的消息从主Looper找出来,放到bg thread进行。

mHashCollisionEntry的作用:当通过msg和isInteractive从mEntries中找到的entry与msg的workSourceUidhandlerthreadisInteractive(亮灭屏)中有任何一项与当前统计msg的不一样的时候表明查找id的时候发生了hash冲突,而这里处理hash冲突的方法就是把数据全统计在这个entry中。hash算法如下:

frameworks/base/core/java/com/android/internal/os/LooperStats.java

static int idFor(Message msg, boolean isInteractive) {
    int result = 7;
    result = 31 * result + msg.workSourceUid;
    result = 31 * result + msg.getTarget().getLooper().getThread().hashCode();
    result = 31 * result + msg.getTarget().getClass().hashCode();
    result = 31 * result + (isInteractive ? 1231 : 1237);
    if (msg.getCallback() != null) {
        return 31 * result + msg.getCallback().getClass().hashCode();
    } else {
        return 31 * result + msg.what;
    }
}

当这两个entry中的messageCount或者exceptionCount大于0的时候则会在dumpsys中显示,反之则不显示这两个entry。

有趣三:dumpsys的时候会添加几个debug的entry,但打印的时候会被过滤

frameworks/base/core/java/com/android/internal/os/LooperStats.java

public List<ExportedEntry> getEntries() {
    // ...
    // Debug entries added to help validate the data.
    if (mAddDebugEntries && mBatteryStopwatch != null) {
        exportedEntries.add(createDebugEntry("start_time_millis", mStartElapsedTime));
        exportedEntries.add(createDebugEntry("end_time_millis", SystemClock.elapsedRealtime()));
        exportedEntries.add(
            createDebugEntry("battery_time_millis", mBatteryStopwatch.getMillis()));
        exportedEntries.add(createDebugEntry("sampling_interval", mSamplingInterval));
    }
    return exportedEntries;
}


// frameworks/base/services/core/java/com/android/server/LooperStatsService.java
@Override
protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
    // ...
    for (LooperStats.ExportedEntry entry : entries) {
        if (entry.messageName.startsWith(LooperStats.DEBUG_ENTRY_PREFIX)) {
            // Do not dump debug entries.
            continue;
        }
        // ...
}
  • "start_time_millis":开始统计Looper中数据的时间,LooperStats#reset会重置这个值
  • "end_time_millis":dumpsys执行的时间
  • "battery_time_millis":开始执行数据统计后经历手机不在充电的时间,mIgnoreBatteryStatus被设置为true时,在充电也会进行Looper的数据统计,但不被累加到battery_time_millisLooperStats#reset会重置这个值
  • "sampling_interval":采样间隔

说在后面

上面这些统计Looper中消息的执行的逻辑,结合字节的ANR分析逻辑,也许你们能复刻字节的Raster工具,帮助自己的App分析Looper中的消息延迟或者主线程消息执行缓慢导致的ANR,下面附上几篇字节的文章链接,方便跳转。

今日头条 ANR 优化实践系列 - 设计原理及影响因素

今日头条 ANR 优化实践系列 - 监控工具与分析思路

今日头条 ANR 优化实践系列分享 - 实例剖析集锦

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

推荐阅读更多精彩内容