ProtoLog

The Android logging system aims to achieve universal accessibility and ease of use, assuming 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 is not optimal. One such scenario is WindowManager, which requires a robust logging system that handles real-time window transition logs with minimal system impact.

ProtoLog is the alternative to address the logging needs of WindowManager and similar services. ProtoLog offers the following benefits over logcat:

  • Uses fewer resources for logging.
  • From a developer's perspective, it works the same as the default Android logging framework.
  • Lets you enable or disable log statements at runtime.
  • Can also log to logcat.

To optimize memory usage, ProtoLog uses a string interning mechanism. This mechanism calculates and saves a compiled hash of the message. To improve performance, ProtoLog performs string interning during compilation for system services. It records only the message identifier and arguments at runtime. When you generate a ProtoLog trace or obtain a bug report, ProtoLog automatically incorporates the message dictionary created at compile time. This enables message decoding from any build.

ProtoLog stores messages in a binary format (proto) within a Perfetto trace. Message decoding occurs within Perfetto's trace_processor. The process decodes the binary proto messages, translates message identifiers into strings using the embedded message dictionary, and formats the string using dynamic arguments.

ProtoLog supports the same log levels as android.utils.Log, which are d, v, i, w, e, and wtf.

Client-side ProtoLog

Initially, ProtoLog was intended only for the server side of the WindowManager, operating within a single process and component. Later, it was expanded to encompass the WindowManager shell code in the System UI process. However, using ProtoLog required intricate boilerplate setup code. Additionally, Proto logging was restricted to system server and System UI processes. This made it difficult to incorporate into other processes and required a separate memory buffer setup for each. ProtoLog is now available for client-side code, eliminating the need for additional boilerplate code.

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

ProtoLog groups

ProtoLog messages are organized into groups called ProtoLogGroups, similar to how Logcat messages are organized by TAG. These ProtoLogGroups serve as message clusters that you can enable or disable at runtime. They also control whether messages are stripped during compilation and where they are logged (proto, logcat, or both). Each ProtoLogGroup includes 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 that uses ProtoLog must have a ProtoLogGroup instance configured.

Supported argument types

ProtoLog internally formats strings using 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

Width and precision modifiers, such as %04d and %10b, are supported. However, argument_index and flags aren't supported.

Use ProtoLog in a new service

To use ProtoLog in a new service, follow these steps:

  1. Create a ProtoLogGroup definition for this service.
  2. Initialize the definition before its first use. For example, initialize it during process creation:

    ProtoLog.init(ProtoLogGroup.values());
    
  3. Use ProtoLog in the same way you use 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