11:12 am
Thursday, 7 July 2022 (GMT+8)
Time in Guangdong Province, China

概述

本文是对ProtoLog的基本说明，包括对ProtoLog的使用、Group的定制，以及ProtoLog框架的结构。

ProtoLog是Android R(Android 11)开始引入的全新的日志框架，它在性能、开销和灵活程度上有明显的提升，是一套全新流程的日志框架，它主要在WindowManager体系中使用，并有可能推广到Android系统层的其他部分。

它的一大特点是能够根据Group分类来动态启停指定类别的日志打印，这使系统层初步具备了动态日志的能力（动态日志的另一大能力是打印没有预埋的日志、动态执行没有预置的调试代码）。另外还有精妙绝伦的日志数据量压缩机制（虽然并不是什么新技术）。利用对日志字符串的哈希引用减少了App内字符串数量和大小，给应用和Framework大小、内存占用带来一定的减少ProtoLog会将二进制日志以Protocol Buffer的形式存储，这是ProtoLog命名的由来。Protocol Buffer的使用也使序列化数据更加紧凑，是Protocol Buffer在Android日志框架中的落地（在此之前，一些窗口系统、Surface系统已经在使用Protocol Buffer来存储Trace、日志了）。

ProtoLog不仅像android.util.Log一样能够输出日志到logcat，还能够根据配置以二进制的形式（Protocol Buffer格式）将日志输出到DB中（同步地提供了一个将二进制日志转换为常规日志的工具）。

ProtoLog带来了全新的三大Feature，这些Features为系统日志带来了实用的动态能力，减少了日志的开销（包括包大小、内存占用、日志打印的开销）：

  • 动态启停(Tunable in runtime)、支持分类
  • 暴露的接口简洁、从android.util.Log几乎0成本迁移
  • 数据量压缩

ProtoLog提供了简洁的、类似android.util.Log的接口，它是一个空实现的Stub，实际上通过ProtoLogTool实现其功能，在编译期间做出大量工作（涉及词法分析及代码生成）。参考《Android动态日志ProtoLog原理与架构：How ProtoLogTool works》。

ProtoLog框架具有三大子模块：实现日志功能的运行时模块、解析和阅读二进制日志的工具、在编译期工作的负责处理和转换的工具。参考《Android动态日志ProtoLog原理与架构：How ProtoLogTool works》。

使用

本节介绍ProtoLog的使用。说明一下，ProtoLog是为WindowManager设计的（至少Android 11是这样。WindowManager太复杂了，没有强劲的调试手段和日志会让原本困难的WMS开发雪上加霜）。如果想要将ProtoLog用在其他地方，需要根据实际情况做配套工作，如编译、实现和插桩等。

ProtoLog的基本用法分三步走。

  1. 新增自己定义的Group，或者使用已有的Group，在代码中通过ProtoLog.i()等方法打印日志
  2. 打开Group对应的动态日志
  3. 解析、阅读日志

下面首先介绍如何找到系统内一些预定义的Groups，以及如何定义Groups。然后展示adb shell如何动态打开日志，以及专门用于阅读二进制Protocol Buffer格式的日志的工具。

定义(TAG/Group)

Group是新引入的概念，它用于对ProtoLog进行分类。常规的日志通常会带有TAG，TAG可以用于过滤日志，像是日志的标签。而Group在ProtoLog中用于分类日志，**动态启停的的控制范围正是一个个的Group**。动态日志的启停、以及对应的启停命令，都是以Group作为颗粒度的。

从ProtocolLog提供的方法的签名来看，日志方法已经不再要求提供TAG了，而仅要求提供Group（实际上是另一个位置将TAG和Group绑定起来了，每个Group都能确定对应的TAG）。下面是方法签名，可以看到它像普通日志方法一样接收日志格式串，但是不接受TAG而要求传递Group。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
package com.android.server.protolog.common;

public class ProtoLog {
    public static void d(IProtoLogGroup group, String messageString, Object... args) {
        // Stub, replaced by the ProtoLogTool.
        throw new UnsupportedOperationException("ProtoLog calls MUST be processed with ProtoLogTool");
    }
    ...
}

    // 对比android.util.Log:
    public static int d(@Nullable String tag, @NonNull String msg) {
        ...
    }

不论是LogCat还是ProtoLog打印日志，均会带上TAG。ProtoLog的TAG是在ProtoLogGroup中定义的，而不需要调用者传递的。如下，为WindowManager定义的Groups，以及Groups对应的TAGs。

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
package com.android.server.wm;
public enum ProtoLogGroup implements IProtoLogGroup {
    WM_ERROR(true, true, true, Consts.TAG_WM),
    WM_DEBUG_ORIENTATION(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_FOCUS_LIGHT(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_BOOT(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_RESIZE(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_ADD_REMOVE(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_FOCUS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false, Consts.TAG_WM),
    WM_DEBUG_STARTING_WINDOW(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_SHOW_TRANSACTIONS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_SHOW_SURFACE_ALLOC(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    WM_DEBUG_APP_TRANSITIONS(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
            Consts.TAG_WM),
    ...
    
    ProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag) {
        this.mEnabled = enabled;
        this.mLogToProto = logToProto;
        this.mLogToLogcat = logToLogcat;
        this.mTag = tag;
    }
}

从ProtoLogGroup的定义我们可以看到，**Group实际上是ProtoLogGroup中定义的enum，每个Group在定义时就制定了对应的TAG，并通过两个Boolean控制是否输出到ProtoLog或Logcat**。

总结一下，对比android.util.Log接收TAG，ProtoLog接收Group。Group不像TAG一样想咋写咋写，随便写一个String都行，而是要预先进行定义。**Group在ProtoLogGroup中定义，在定义的时候需要提供一个TAG**。定义完成后，才能在代码中使用该Group打印ProtoLog。

命令/工具

本小节介绍ProtoLog的一些机制及对应的命令。其中，日志输出到DB时（Proto Log）在enable后需要start——start专门用于控制开始写入到数据库。

名称/命令 描述
wm logging start start proto logging 开始Proto log输出，让你enable的Group生效；输出到Logcat时不需要start
wm logging stop stop proto logging
wm logging enable/disable [group…] 按照groups启停ProtoLog，真正启动是start命令，调用start命令之后才输出
wm logging enable-text/disable-text [group…] 启停动态日志，输出到logcat，不需要调用start命令就会开始输出

上面讲到，ProtoLog是为WindowManager设计的，ProtoLog的命令也集成在内。

wm logging与cmd window logging，这两个指令等价。

数据量压缩原理

  • 查看已经定义好的Group以及其对应的日志
  • 以及数据量压缩原理

ProtoLog具有一定的日志数据量压缩能力（以ProtoBuf二进制形式输出时）。它的基本原理是，将原本需要进行存储的日志转换为存储日志对应的哈希，这样原本需要存储一段较长的字符串就转为了仅存储定长的哈希即可。这也是ProtoLog需要专用工具才能解析查看的原因。

举个例子：ProtoLog.i(WM_DEBUG_ORIENTATION, "Performing post-rotate rotation after seamless rotation");这是DisplayRotation内部的动态日志打印，它可能在运行时打印成千上万次，每次都会打印对应的字符串日志——这会让我们的日志文件存储成千上万条冗余的重复的字符串。对于冗余和重复，很容易就能想到归一化管理的方法——仅存储一处，其他位置采用引用即可。**ProtoLog将被引用的源字符串放到一个文件中（可见下文），将其哈希作为引用，并将日志打印过程替换为打印哈希。解析工具解析时再将哈希替换为源字符串即可。**

这个过程是在编译期实现的、源码级实现。也就是说，编译完成后，日志打印的调用会被替换掉。相关的工作在编译配置中实现，涉及Java词法分析、代码生成等——这一块，ProtoLog采用JavaParser实现。

除了可以在源码中查看已经定义好的Group外（ProtoLogGroup.java），还可以在Android设备中直接在线查看/system/etc/protolog.conf.json.gz（实际上ProtoLog就是使用这个东西来进行Group管理和日志数据量压缩的）。

/system/etc/protolog.conf.json.gz是一个打包文件，内部仅包含一个Group配置信息的Json。因为只有一个文件，直接peek它即可，甚至不需要解压。（ADB内可能没有下面这个命令，pull出来再执行）

1
zmore protolog.conf.json.gz

其内容如下，可以看到第一个Group就是我们刚刚上面动态启停指令使用过的。

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
{
  "version": "1.0.0",
  "messages": {
    "-2146181682": {
      "message": "Releasing screen wakelock, obscured by %s",
      "level": "DEBUG",
      "group": "WM_DEBUG_KEEP_SCREEN_ON",
      "at": "com\/android\/server\/wm\/WindowManagerService.java"
    },
    "-2127842445": {
      "message": "Clearing startingData for token=%s",
      "level": "VERBOSE",
      "group": "WM_DEBUG_STARTING_WINDOW",
      "at": "com\/android\/server\/wm\/ActivityRecord.java"
    },
    "-2109936758": {
      "message": "removeAppToken make exiting: %s",
      "level": "VERBOSE",
      "group": "WM_DEBUG_ADD_REMOVE",
      "at": "com\/android\/server\/wm\/ActivityRecord.java"
    },
    "-2109864870": {
      "message": "app-release(): mOuter=%s",
      "level": "DEBUG",
      "group": "WM_DEBUG_REMOTE_ANIMATIONS",
      "at": "com\/android\/server\/wm\/RemoteAnimationController.java"
    },
    ...
  
  "groups": {
    "TEST_GROUP": {
      "tag": "WindowManagetProtoLogTest"
    },
    "WM_DEBUG_ADD_REMOVE": {
      "tag": "WindowManager"
    },
    "WM_DEBUG_APP_TRANSITIONS": {
      "tag": "WindowManager"
    },
    "WM_DEBUG_APP_TRANSITIONS_ANIM": {
      "tag": "WindowManager"
    },
    "WM_DEBUG_BOOT": {
      "tag": "WindowManager"
    },
    "WM_DEBUG_DRAW": {
      "tag": "WindowManager"
    },
    "WM_DEBUG_FOCUS": {
      "tag": "WindowManager"
    },
    ...

可以看到，Group们都在这里，还可以看到日志的源信息（因为日志压缩的原理是将字符串做哈希，打印出来的日志仅包含哈希，日志查看工具根据哈希在这里索引拿到源信息即可。由于避免存储字符串，而仅存储定长哈希，这是ProtoLog数据量压缩的核心原理。）一行日志该有的TAG、Message、日志等级都齐了。

动态启停

  • 启动某个Group，并输出到Logcat:
1
wm logging enable-text WM_DEBUG_SCREEN_ON
  • 启动某个Group，并输出到DB
1
2
3
generic_x86_64:/ # wm logging enable WM_DEBUG_SCREEN_ON
generic_x86_64:/ # wm logging start          
Start logging to /data/misc/wmtrace/wm_log.pb.

如上所述，输出到LogCat不需要start，输出到DB需要start

  • 停止
1
2
3
generic_x86_64:/ # wm logging stop 
Stop logging to /data/misc/wmtrace/wm_log.pb. Waiting for log to flush.
Log written to /data/misc/wmtrace/wm_log.pb.

查看Config

这里Connfig是指Group的集合，以及Group的内容。其中内容是包含了TAG、哈希、日志等级和日志源Message。Config的内容、相关作用和原理在上面“数据量压缩原理”一节介绍过了。

由于ProtoLog的压缩原理是仅存储哈希，避免直接存储字符串的开销。那么最终阅读日志时，当然得用哈希来找到源Message。这个寻找的基础就是Config文件：/system/etc/protolog.conf.json.gz。

Config的主要作用是存储Group、Tag、以及源字符串本身及其哈希。没有这个信息，无法从ProtoLog中解析出真正的日志文件。

查看日志

ProtoLog提供了专门的日志查看工具。如下操作可以在浏览器中查看日志和事件：

如果配置为输出到Logcat，那么直接看Logcat即可。

  • 获取对应的页面并用浏览器打开：
1
curl 'https://android.googlesource.com/platform/prebuilts/misc/+/master/common/winscope/winscope.html?format=TEXT' | base64 -d > winscope.html
  • 打开后导入抓取的文件即可查看日志

首先导入ProtoLog对应的pb文件。在导入时会自动识别其文件类型，也可以手动指定类型为ProtoLog。

接着即可查看日志。

对于日常调试和开发时建议使用更简便的输出到logcat的方案，这样能够直接查看Raw text，而不需要解析ProtoBuf。

  • 使用Winscope.html查看日志有时候也不太方便，还可以使用ProtoLogTool将pb文件解析并直接输出日志。

命令如下，通过ProtoLogTool解析并输出日志。需要通过--viewer-conf指定Config，它提供给ProtoLogTool用于解析数据库。Config是上文介绍过的那个Config，它可以从Android设备的/system/etc/protolog.conf.json.gz解包得到。

1
./out/host/linux-x86/bin/protologtool read-log --viewer-conf /ssd_d/niko/protolog.conf.json /ssd_d/niko/wm_log.pb

注意该命令在PC中执行而非Android设备中执行，目录是以AOSP源码目录为根目录。protolog.conf.json是设备对应的Config，自行获取并传入到命令。

一下是输出示例。可以看到动态日志正常运行，日志文件也正常解析。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
8-> ./host/linux-x86/bin/protologtool read-log --viewer-conf /ssd_d/niko/protolog.conf.json /ssd_d/niko/wm_log.pb                                                                              07-07 16:18:26.361 VERBOSE WindowManager: screenOnEarly=false, awake=true, currentAppOrientation=0, orientationSensorEnabled=true, keyguardDrawComplete=false, windowManagerDrawComplete=false
07-07 16:18:26.370 VERBOSE WindowManager: Disabling listeners                                                                                                                                  07-07 16:18:26.374 VERBOSE WindowManager: Clear freezing of Token{93e49a0 ActivityRecord{bb44959 u0 com.android.launcher3/.uioverrides.QuickstepLauncher t117}}: visible=true freezing=false
07-07 16:18:26.387 VERBOSE WindowManager: setAppVisibility(Token{93e49a0 ActivityRecord{bb44959 u0 com.android.launcher3/.uioverrides.QuickstepLauncher t117}}, visible=false): mNextAppTransit
ion=TRANSIT_UNSET visible=true mVisibleRequested=true Callers=com.android.server.wm.ActivityRecord.setVisibility:4120 com.android.server.wm.ActivityRecord.makeInvisible:4723 com.android.serve
r.wm.EnsureActivitiesVisibleHelper.setActivityVisibilityState:171 com.android.server.wm.EnsureActivitiesVisibleHelper.lambda$Bbb3nMFa3F8er_OBuKA7-SpeSKo:0 com.android.server.wm.-$$Lambda$Ensu
reActivitiesVisibleHelper$Bbb3nMFa3F8er_OBuKA7-SpeSKo.accept:12 com.android.internal.util.function.pooled.PooledLambdaImpl.doInvoke:307                                                        07-07 16:18:26.387 VERBOSE WindowManager: commitVisibility: ActivityRecord{bb44959 u0 com.android.launcher3/.uioverrides.QuickstepLauncher t117}: visible=false mVisibleRequested=false
07-07 16:18:26.387 VERBOSE WindowManager: Looking for focus: Window{196f26a u0 SecondaryHomeHandle0}, flags=562037032, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{e151cc8 u0 EdgeBackGestureHandler0}, flags=25166120, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{bee3810 u0 pip-dismiss-overlay}, flags=280, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{db7dd37 u0 NavigationBar0}, flags=25428072, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{72d19c3 u0 NotificationShade}, flags=-2122055608, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{74b926c u0 StatusBar}, flags=-2122317816, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{d75da1f u0 AssistPreviewPanel}, flags=16777496, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{d0f6ea2 u0 InputMethod}, flags=-2122317560, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{97f4a86 u0 com.android.launcher3/com.android.launcher3.uioverrides.QuickstepLauncher}, flags=-2121203456, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: Looking for focus: Window{dd9f002 u0 com.android.systemui.ImageWallpaper}, flags=82712, canReceive=false
07-07 16:18:26.399 VERBOSE WindowManager: findFocusedWindow: No focusable windows.
07-07 16:18:26.400 INFO WindowManager: setInputMethodTarget null
...

总结

对比android.util.Log，ProtoLog带来了包括动态启停、数据量压缩等方面的优势，总结如下。

Feature 原理
数据量压缩 日志打印时引用字符串的Hash，避免字符串冗余
包体积 同样是字符串Hash带来的，代码中硬编码的日志字符串替换为哈希，减少了代码Code的大小，对包体积有一定的减少
动态启停 内置支持动态启停
允许输出到DB 由于LogCat本身不支持ProtoBuf，因此ProtoLog输出到二进制文件中，这实际上避免了频繁调用LogCat带来的开销（一些系统服务日志全开的情况下日志量是很大的，大量的Log会显著影响性能）
相似的接口 提供了与android.util.Log非常相似的接口。该接口在编译期会通过Transform工具真正生成动态日志的代码

参考

  1. 查看ProtoLog的工具
  2. ProtoLogTool