ProtoLog

The Android logging system aims for universal accessibility and ease of use, assuming that all log data can be represented as a sequence of characters. This assumption aligns with most use cases, particularly when log readability is crucial without specialized tools. However, in environments demanding high logging performance and restricted log sizes, text-based logging might not be optimal. One such scenario is WindowManager, which necessitates a robust logging system capable of handling real-time window transition logs with minimal system impact.

ProtoLog is the alternative to address the logging needs of WindowManager and similar services. The main benefits of ProtoLog over logcat are:

  • The amount of resources used for logging is smaller.
  • From a developer point of view, it's the same as using the default Android logging framework.
  • Supports log statements to be enabled or disabled at runtime.
  • Can still log to logcat if needed.

To optimize memory usage, ProtoLog employs a string interning mechanism that involves calculating and saving a compiled hash of the message. For improved performance, ProtoLog performs string interning during compilation (for system services), recording only the message identifier and arguments at runtime. Additionally, when generating a ProtoLog trace or obtaining a bug report, ProtoLog automatically incorporates the message dictionary created at compile time, enabling message decoding from any build.

Using ProtoLog, the message is stored in a binary format (proto) within a Perfetto trace. The message decoding happens inside Perfetto's trace_processor. The process consists of decoding the binary proto messages, translating the message identifiers into strings using the embedded message dictionary, and formatting the string using dynamic arguments.

ProtoLog supports the same log levels as android.utils.Log, namely: d, v, i, w, e, wtf.

Client-side ProtoLog

Initially, ProtoLog was intended solely for the server side of the WindowManager, operating within a single process and component. Subsequently, it was expanded to encompass the WindowManager shell code in the System UI process, but ProtoLog use required an intricate boilerplate setup code. Furthermore, Proto logging was restricted to system server and System UI processes, rendering it laborious to incorporate into other processes and necessitating a separate memory buffer setup for each. However, ProtoLog has now been made available for client-side code, eliminating the need for additional boilerplate code.

Unlike system services code, client-side code typically skips compile-time string interning. Instead, string interning occurs dynamically in a background thread. As a result, while ProtoLog on the client-side provides comparable memory use advantages to ProtoLog on system services, it incurs a marginally higher performance overhead and lacks the memory reduction advantage of pinned memory of its server-side counterpart.

ProtoLog groups

ProtoLog messages are organized into groups called ProtoLogGroups, similar to how Logcat messages are organized by TAG. These ProtoLogGroups serve as clusters of messages that can be collectively enabled or disabled at runtime. Additionally, they control whether messages should be stripped during compilation and where they should be logged (proto, logcat, or both). Each ProtoLogGroup comprises the following properties:

  • enabled: When set to false, messages in this group are excluded during compilation and aren't available at runtime.
  • logToProto: Defines if this group logs with binary format.
  • logToLogcat: Defines if this group logs to logcat.
  • tag: Name of the source of the logged message.

Each process using ProtoLog must have a ProtoLogGroup instance configured.

Supported argument types

Internally, ProtoLog formats strings use android.text.TextUtils#formatSimple(String, Object...), so its syntax is the same.

ProtoLog supports the following argument types:

  • %b - boolean
  • %d, %x - integral type (short, integer, or long)
  • %f - floating point type (float or double)
  • %s - string
  • %% - a literal percent character

The width and precision modifiers such as %04d and %10b are supported, but argument_index and flags aren't supported.

Use ProtoLog in a new service

To use ProtoLog in a new process:

  1. Create a ProtoLogGroup definition for this service.

  2. Initialize the definition before its first use (for example, on process creation):

    Protolog.init(ProtologGroup.values());

  3. Use Protolog in the same manner as android.util.Log:

    ProtoLog.v(WM_SHELL_STARTING_WINDOW, "create taskSnapshot surface for task: %d", taskId);

Enable compile-time optimization

To enable compile time ProtoLog in a process, you must change its build rules and invoke the protologtool binary.

ProtoLogTool is a code transformation binary that performs string interning and updates ProtoLog invocation. This binary transforms every ProtoLog logging call as shown in this example:

ProtoLog.x(ProtoLogGroup.GROUP_NAME, "Format string %d %s", value1, value2);

into:

if (ProtoLogImpl.isEnabled(GROUP_NAME)) {
    int protoLogParam0 = value1;
    String protoLogParam1 = String.valueOf(value2);
    ProtoLogImpl.x(ProtoLogGroup.GROUP_NAME, 1234560b0100, protoLogParam0, protoLogParam1);
}

In this example, ProtoLog, ProtoLogImpl, and ProtoLogGroup are the classes provided as arguments (can be imported, static imported, or full path, wildcard imports aren't allowed) and, x is the logging method.

The transformation is done at the source level. A hash is generated from the format string, log level, and log group name, and inserted after the ProtoLogGroup argument. The real generated code is inlined and a number of new line characters is added as to preserve line numbering in file.

Example:

genrule {
    name: "wm_shell_protolog_src",
    srcs: [
        ":protolog-impl", // protolog lib
        ":wm_shell_protolog-groups", // protolog groups declaration
        ":wm_shell-sources", // source code
    ],
    tools: ["protologtool"],
    cmd: "$(location protologtool) transform-protolog-calls " +
        "--protolog-class com.android.internal.protolog.ProtoLog " +
        "--loggroups-class com.android.wm.shell.protolog.ShellProtoLogGroup " +
        "--loggroups-jar $(location :wm_shell_protolog-groups) " +
        "--viewer-config-file-path /system_ext/etc/wmshell.protolog.pb " +
        "--legacy-viewer-config-file-path /system_ext/etc/wmshell.protolog.json.gz " +
        "--legacy-output-file-path /data/misc/wmtrace/shell_log.winscope " +
        "--output-srcjar $(out) " +
        "$(locations :wm_shell-sources)",
    out: ["wm_shell_protolog.srcjar"],
}

Command line options

One of the main advantages of ProtoLog is that you can enable or disable it at runtime. For example, you can have more verbose logging in a build, disabled by default, and enabled it during local development, for debugging a specific issue. This pattern is used, for example, in WindowManager with the groups WM_DEBUG_WINDOW_TRANSITIONS and WM_DEBUG_WINDOW_TRANSITIONS_MIN enabling different types of transition logging, with the former being enabled by default.

You can configure ProtoLog using Perfetto, when starting a trace. You can also configure ProtoLog locally using the adb command line.

The command adb shell cmd protolog_configuration supports the following arguments:

help
  Print this help text.

groups (list | status)
  list - lists all ProtoLog groups registered with ProtoLog service"
  status <group> - print the status of a ProtoLog group"

logcat (enable | disable) <group>"
  enable or disable ProtoLog to logcat

Tips for effective usage

ProtoLog uses string interning for both the message and any string arguments passed. This means that, to gain more benefit from ProtoLog, the messages should isolate repeated values into variables.

For example, consider the following statement:

Protolog.v(MY_GROUP, "%s", "The argument value is " + argument);

When optimized at compile time, it translates to this:

ProtologImpl.v(MY_GROUP, 0x123, "The argument value is " + argument);

If ProtoLog is used in the code with arguments A,B,C:

Protolog.v(MY_GROUP, "%s", "The argument value is A");
Protolog.v(MY_GROUP, "%s", "The argument value is B");
Protolog.v(MY_GROUP, "%s", "The argument value is C");
Protolog.v(MY_GROUP, "%s", "The argument value is A");

It results in the following messages in memory:

Dict:
  0x123: "%s"
  0x111: "The argument value is A"
  0x222: "The argument value is B"
  0x333: "The argument value is C"

Message1 (Hash: 0x123, Arg1: 0x111)
Message2 (Hash: 0x123, Arg2: 0x222)
Message3 (Hash: 0x123, Arg3: 0x333)
Message4 (Hash: 0x123, Arg1: 0x111)

If, instead, the ProtoLog statement was written as:

Protolog.v(MY_GROUP, "The argument value is %s", argument);

The in memory buffer would end up as:

Dict:
  0x123: "The argument value is %s" (24 b)
  0x111: "A" (1 b)
  0x222: "B" (1 b)
  0x333: "C" (1 b)

Message1 (Hash: 0x123, Arg1: 0x111)
Message2 (Hash: 0x123, Arg2: 0x222)
Message3 (Hash: 0x123, Arg3: 0x333)
Message4 (Hash: 0x123, Arg1: 0x111)

This sequence results in a memory footprint that is 35% smaller.

Winscope viewer

Winscope's ProtoLog viewer tab shows ProtoLog traces organized in a tabular format. You can filter traces by log level, tag, source file (where the ProtoLog statement is present), and message content. All columns are filterable. Clicking the timestamp in the first column transports the timeline to the message timestamp. Additionally, clicking Go to Current Time scrolls the ProtoLog table back to the timestamp selected in the timeline:

ProtoLog viewer

Figure 1. ProtoLog viewer