Chromium 渲染性能分析案例

Published: by Creative Commons Licence

  • Categories:

项目中发现，在浏览器中的 Canvas 上书写的延迟 (lag) 很高，这里的延迟指的是手指到屏幕上笔迹的最末端的延迟，下面调查问题的原因，期望找到一种通用的解决方案。

问题可能出在以下几个地方：

  1. 浏览器本身的事件传递和渲染流水线；
  2. 浏览器使用的 Skia 图形库；
  3. 浏览器和 Android 渲染的对接方式；
  4. 设备的 GPU 硬件。
  5. 操作系统本身；

因此，写了一个 Demo（demo_android_skia） 来模拟浏览器在 Android 上的渲染，用于加深对 Chromium 渲染的理解，也方便后续的调试。为了能够定量的分析程序的性能，在 Demo 中添加了 Trace 机制，然后抓到性能数据如下：

Trace

局部放大：

Trace2

有以下发现：

  1. 主线程（23118，对应 Andorid 中的 UI 线程）中的 Looper.dispatch: android.view.Choreographer$FrameHandler(android.view.Choreographer$FrameDisplayEventReceiver 占用了大量的时间，由于他负责 Touch 事件的分发，因此这可能影响 Touch 事件的分发速度；
  2. Looper.dispatch:... 的 Wall Duration 是 27.9ms, 而 CPU Duration 只有 6.8ms, 说明有大量的时间都不是消耗在 CPU 上；
  3. 由于没有足够的 Touch 事件，因此负责我们程序渲染的RenderThread很空闲（这个是自定义的线程，后来发现命名和 Android 原本的渲染线程重名了，因此后续这个线程被重命名为了 DemoRender)；

所以要研究 Looper.dispatch: android.view.Choreographer$FrameHandler(android.view.Choreographer$FrameDisplayEventReceiver 这个 Trace 是怎么来的，看能不能添加更详细的 Trace 信息来定位是什么造成了它占用那么多的时间。

Looper.dispatch:* 的来源

Android 系统层的 android.os.Looper 类负责线程的消息循环，它维护了一个消息队列，系统的触摸，渲染等消息等都是在这里分发给到 App，它允许外部注册一个 android.util.Printer 对象，用来打印消息的分发日志：

// frameworks/base/core/java/android/os/Looper.java
public static void loop() {
  // ...
  for (;;) {
      Message msg = queue.next(); // might block
      if (msg == null) {
          // No message indicates that the message queue is quitting.
          return;
      }

      // 这个 logging 用来打印消息分发日志
      final Printer logging = me.mLogging;
      if (logging != null) {
          logging.println(">>>>> Dispatching to " + msg.target + " " +
                  msg.callback + ": " + msg.what);
      }
      // ...
      if (logging != null) {
          logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
      }
      // ...
  }
}

当开启我们程序的 TraceEvent 的时候，会向 Android 的主消息循环 Looper 中注册一个 android.util.Printer 对象，这个 Printer 负责将 Looper 的日志输出对接到 TraceEvent 机制：

// base/android/java/src/org/chromium/base/TraceEvent.java
@CalledByNative
public static void setEnabled(boolean enabled) {
  // ...
  ThreadUtils.getUiThreadLooper().setMessageLogging(
          enabled ? LooperMonitorHolder.sInstance : null);
}

private static final class LooperMonitorHolder {
    private static final BasicLooperMonitor sInstance =
            CommandLine.getInstance().hasSwitch(BaseSwitches.ENABLE_IDLE_TRACING)
            ? new IdleTracingLooperMonitor() : new BasicLooperMonitor();
}

所以这就解释了 Looper.dispatch: android.view.Choreographer$FrameHandler(android.view.Choreographer$FrameDisplayEventReceiver 的来源。但是还没有解释为什么他存在大量的时间处于非活跃状态，然后开始研究 Android 的 Choreographer 机制，简单来说它在 Android 系统中负责渲染/交互/事件等的调度，熟悉了它的机制之后了解到上面这条信息表示Choreographer收到了 vsync 信号在进行 vsync 的调度，经过追踪代码发现它通过 FrameDisplayEventReceicer 最终触发了 Frame 的重绘：

// frameworks/base/core/java/android/view/Choreographer.java
 void doFrame(long frameTimeNanos, int frame) {
        final long startNanos;
        synchronized (mLock) {
        // ...
        try {
            Trace.traceBegin(Trace.TRACE_TAG_VIEW, "Choreographer#doFrame");
            AnimationUtils.lockAnimationClock(frameTimeNanos / TimeUtils.NANOS_PER_MS);

            mFrameInfo.markInputHandlingStart();
            doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos);

            mFrameInfo.markAnimationsStart();
            doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos);
            doCallbacks(Choreographer.CALLBACK_INSETS_ANIMATION, frameTimeNanos);

            mFrameInfo.markPerformTraversalsStart();
            doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);

            doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos);
        } finally {
            AnimationUtils.unlockAnimationClock();
            Trace.traceEnd(Trace.TRACE_TAG_VIEW);
        }
      // ...
    }
 }

这段代码中可以发现其中有添加 Trace，因此研究如何开启Android系统的 Trace，确认在 Choreographer#doFrame 中都进行了哪些操作。

经过研究，发现以上代码是一种 systrace 机制。

system trace

它是一种基于 Linux 内核的 ftrace 实现的流程追踪机制，可以收集系统全局的性能数据，可以使用 systrace.py 脚本开启，或者从系统中直接启动，获取到的数据可以生成类似 chrome://tracing 那样的分析结果。可以使用 android.os.Trace 在自己的程序中添加新的追踪点。它的好处是不依赖 Android Studio，而且可以收集到系统级的信息。

adb 连接以后，直接使用以下命令来获取指定应用的 system trace, 结果文件会被保存在当前目录下，使用浏览器打开生成的 html 文件即可进行调试。

python systrace.py -a com.example.myapp -b 16384 -o my_systrace_report.html sched freq idle am wm gfx view binder_driver hal dalvik camera input res

systrace 命令的使用见： https://developer.android.com/topic/performance/tracing/command-line#app-trace

但是它只能抓到系统埋好的 Trace 点，如果要抓到自己代码的数据，需要给自己的代码添加追踪点，可以按照这里介绍的方法给自己的程序添加埋点：Define custom events

添加好后，使用它抓到的结果如下图：

systrace

这里可以找到我们之前关注的 Choreographer#doFrame:

systrace2

可以看到大量的时间都处于等待状态，而且等待主要位于 draw 调用中， draw 主要进行以下动作：

// frameworks/base/core/java/android/view/ViewRootImpl.java
private void performDraw() {
  // ...
  Trace.traceBegin(Trace.TRACE_TAG_VIEW, "draw");

  try {
      boolean canUseAsync = draw(fullRedrawNeeded);
      if (usingAsyncReport && !canUseAsync) {
          mAttachInfo.mThreadedRenderer.setFrameCompleteCallback(null);
          usingAsyncReport = false;
      }
  } finally {
      mIsDrawing = false;
      Trace.traceEnd(Trace.TRACE_TAG_VIEW);
  }
  // ...
}

根据名字，大概猜测 draw 要进行绘制操作，而绘制就会涉及 GPU 调用，如果是这样就可以解释为什么Choreographer#doFrame会有大量的 CPU 等待，这似乎是合理的，但是为什么更新一下 SufaceView 会导致 UI 线程大量的绘制呢？根据之前对 Android 渲染的了解以及对渲染架构设计的理解，SurfaceView 的绘制应该是独立于 UI 之外进行的，否则 SurfaceView 的设计就失去了它的初衷，根据我的理解，SurfaceView 设计本意就是要允许用户自己控制绘制，允许它脱离 UI 线程，从而提供给用户较低级别 UI 控制手段，而且我的程序是在独立的DemoRender线程中进行绘制的，就更不应该占用大量的 UI 线程的。程序中唯一更新 UI 的地方就是帧率的显示了，于是把他去掉，再次抓取 systrace，得到以下结果：

systrace3

可以看到，UI 线程闲下来了，而且在每一个 vsync 信号中都非常稳定的触发Choreographer#doFrame，而且没有了大量的 Off-CPU 时间。

局部放大：

systrace4

此时，每个doFrame中也没有了draw调用，这证实了我们之前的理解是正确的，draw调用是在更新 TextView 中的 fps 显示，虽然结果已经是这样了，但是之前真没想到简单的 TextView 的内容更新就可以让 UI 线程繁忙到这种程度。

再来看一下统计数据：

systrace5

可以看到 doFrame 执行了 43 次，OnRenderOnRenderThread 执行了 37 次，由于在demo中 doFrame 在每个 vsync 的时候都触发了，因此它的速度是 60fps，37/43*60=51.6fps，因此，demo中 SurfaceView 的刷新速度只有 51fps，虽然有了很大的提升，但是离 60fps 还是有一定的差距，注意到DemoRender线程还有一定的空闲时间，如果把这些时间都用起来是否能达到 60fps 呢？这是可能的，但是实际项目中这样做的意义不大，因为可以注意到，图中很多帧的生成已经超过了 1 个 VSYNC，即使平均帧率能够达到 60fps，画面也不会很流畅。因为根本问题是要保证每一个 VSYNC 时间内都有新的一帧生成，而要保证这个只能通过优化 GPU 调用或者升级 GPU 硬件。我们显然无法控制硬件的升级，所以只能尝试优化 GPU（GL）调用部分。

要优化 GL 调用，就要知道当前就进行了哪些调用，因为 demo 中使用了 Skia 绘图（为了和 chromium 保持一致），所以需要研究在绘制的时候 Skia 生成了怎样的 GL 调用。

所以后续有几种策略，一是使用 GL 进行绘制，不使用 Skia；二是研究 Skia 生成 GL 调用的逻辑，给 Skia 添加日志记录生成 GL 调用（实际上Skia已经添加了这样的Trace）；三是集成 command buffer, 然后开启 command buffer 的追踪；四是找到一种可以追踪 GL 调用的工具；最后一种看起来比较简单，业界应该有现成的解决方案。

GPU Trace

不像以上介绍的 CPU 调试工具那么丰富，对于 GPU 的调试可以使用的工具比较少，目前主要有系统自带的 gpu-rendering 柱状图，这对于问题的精确定位是不够的。在很早以前有一个 Android OpenGLES Tracer 的工具可以用来追踪 GL 函数的调用，但目前已经用不了了。

后来，在网上搜索发现 google/gapid: Graphics API Debugger 比较强大，它不仅可以追踪 GL 的执行甚至可以进行调用回放，不过他已经停止发布新版本了。被一个更新的工具 google/agi: Android GPU Inspector 取代，不过这个工具目前处于非常早期，现在只支持 Vulkan。

看起来只有 gapid 还能用，尝试使用 gapid 抓取 GPU 调用的结果如下：

gapid

从图中可以看到画一条笔迹后每一帧的 GL 调用，这些调用并不复杂。所以可能性能瓶颈并不在这些调用上。

为了验证以上猜想，尝试不使用 Skia 绘图库，直接调用 OpenGLES 进行绘制，而且在每一帧中只进行只进行简单的处理，验证这样帧率是否能达到 60fps。

测试得到以下结果：

single-gl

可以看到，在我们选定的那一段中，doFrame的数量和OnRenderOnRenderThread的数量已经相等了，这表示确实达到了 60fps! 说实话，当时确实有 5 秒钟的兴奋，似乎发现了实现 60fps 的一种可能的方法，但其实事情并没有这么简单，从实际的体验上来说，手指和画出来的笔迹之间依然有明显的延迟，这是为什么呢？既然程序都实现了 60fps 为什么还会有明显的延迟呢？其实根据对 Android 渲染的理解，这里是比较好解释的，因为程序绘制的结果要交给 SurfaceFlinger 去合成，之后才会最终显示在屏幕上，所以我们查一下 SurfaceFlinger 的合成情况，如下图：

surfaceflinger

图中 doComposition 操作即为 SurfaceFlinger 在进行合成（其实后续还有 HWC 合成，这不是重点，先忽略这个），可以看到每次调用几乎消耗了 33ms，这直接导致最终的显示只能有大概 30fps 的刷新率！

结论

到这里，问题已经比较明朗了，受限于系统的合成速度，无法在不绕过系统合成的情况下实现 60fps 的渲染速度。而要绕过系统的合成层，可以通过直接使用系统的 FrameBuffer 来实现，但这种方式是不通用的，只能在开放了直接操作 FrameBuffer 的设备上或者将应用集成到系统中。所以，要想彻底解决此类问题，最好的办法就是对系统进行优化。现阶段可以使用直接操作 FrameBuffer 的方法来绕过这个问题。

参考链接：

以下是走过的一些弯路，权当是花絮了。

弯路

实际中没有上面那么顺利，下面是走过的一些弯路。

当时不认为是自己程序中的 fps 统计导致doFrame的大量延时，因为不太相信一个简单的文本更新会导致帧率降低一半，因此虽然把程序中的 fps 刷新给去掉了，但是并没有再次抓 systrace，这就导致走了弯路。

所以，后面又有两方面的尝试，一个是想是否有办法让 SurfaceView 独立进行绘制，不要影响 view 的布局及重绘制，经过搜索没有找到相关信息，如果要回答这个问题需要对 Android UI 的绘制原理有足够的了解，而这可能需要花费一地的时间，因此先放下，留个 TODO。

因为之前还注意到一个 CPU Profiler 的调试工具，而起看起来更加强大一点，因此打算再试一下这个工具。

CPU Profiler (Trace logs)

可以在 Android Studio 中直接使用 CPU Profiler 实时查看程序的运行情况（要求程序 debugable=true）。也可以在程序中使用 android.os.Debug 类启动追踪，它会生成一个 .trace 文件，这个文件可以被 CPU Profiler 加载（或者使用 dmtracedump 工具将 .trace 文件生成一个调用堆栈图）。在开发调试期 CPU Prefiler 比较好用，除了有 systrace 的功能之外，也支持其他比如内存，耗电等的追踪。

详细的使用方法见： https://developer.android.com/studio/profile/cpu-profiler#configurations

在实际中，打开这个工具后，遇到无法检测到 demo 程序的问题，尝试了升级 AndroidStudio，升级 SDK，给程序的AndroidManifest.xml文件添加android:debuggable="true", 重启 AndroidStudio 之后，终于能够成功检测到 demo 程序了，下图是使用 CPU Profiler 抓到的程序运行情况：

以上问题是因为 demo 程序没有使用 AndroidStudio 以及 gradle 进行开发，而是使用了 chromium 的 Android Apk 编译工具链，如果使用 AndroidStudio 进行开发可能就会轻松一点，当然使用 chromium 工具链的好处就是可以方便的使用 chromium 套件，而且可以不用打开庞大的 IDE 🐶.

tracelog

这里可以发现，在Choreographer#doFrame中只有 input 的处理，没有 traversal/draw 的相关调用，此时终于恍然大悟，回到了正轨，原来真是 TextView 的更新导致的延时。

另外，CPU Profiler 也可以提供一些 systrace 没有提供的信息，比如在 draw 之后它会告诉你是在等待 GPU。

后来又发现 simpleperf 工具，但是他对我们的问题分析帮助不大，所以在了解后没有进一步的尝试。

simpleperf

它类似 linux 上的 perf 工具，可以收集 Java/C++层程序执行的热点函数及调用堆栈，配合 FlameGraph 生成火焰图。

关于它的详细信息可以参考：Android application profiling

关于性能调试的更多信息，可以参考以下文档：

dumpsys

dumpsys 是一个内置在系统内的工具，它可以获取系统service的状态信息，具体用法见 dumpsys.

使用 dumpsys 获取渲染信息：

$ adb shell dumpsys gfxinfo org.demo.demo_android_skia
Applications Graphics Acceleration Info:
Uptime: 193498680 Realtime: 193498680

** Graphics info for pid 9163 [org.demo.demo_android_skia] **

Stats since: 125971681353608ns
Total frames rendered: 25
Janky frames: 7 (28.00%)
50th percentile: 11ms
90th percentile: 73ms
95th percentile: 350ms
99th percentile: 450ms
Number Missed Vsync: 2
Number High input latency: 0
Number Slow UI thread: 7
Number Slow bitmap uploads: 1
Number Slow issue draw commands: 2
HISTOGRAM: 5ms=1 6ms=3 7ms=4 8ms=0 9ms=3 10ms=1 11ms=2 12ms=1 13ms=1 14ms=1 15ms=1 16ms=0 17ms=0 18ms=0 19ms=0 20ms=0 21ms=0 22ms=1 23ms=0 24ms=0 25ms=0 26ms=1 27ms=0 28ms=0 29ms=0 30ms=0 31ms=0 32ms=1 34ms=0 36ms=0 38ms=1 40ms=0 42ms=0 44ms=0 46ms=0 48ms=0 53ms=0 57ms=0 61ms=0 65ms=0 69ms=0 73ms=1 77ms=0 81ms=0 85ms=0 89ms=0 93ms=0 97ms=0 101ms=0 105ms=0 109ms=0 113ms=0 117ms=0 121ms=0 125ms=0 129ms=0 133ms=0 150ms=0 200ms=0 250ms=0 300ms=0 350ms=1 400ms=0 450ms=1 500ms=0 550ms=0 600ms=0 650ms=0 700ms=0 750ms=0 800ms=0 850ms=0 900ms=0 950ms=0 1000ms=0 1050ms=0 1100ms=0 1150ms=0 1200ms=0 1250ms=0 1300ms=0 1350ms=0 1400ms=0 1450ms=0 1500ms=0 1550ms=0 1600ms=0 1650ms=0 1700ms=0 1750ms=0 1800ms=0 1850ms=0 1900ms=0 1950ms=0 2000ms=0 2050ms=0 2100ms=0 2150ms=0 2200ms=0 2250ms=0 2300ms=0 2350ms=0 2400ms=0 2450ms=0 2500ms=0 2550ms=0 2600ms=0 2650ms=0 2700ms=0 2750ms=0 2800ms=0 2850ms=0 2900ms=0 2950ms=0 3000ms=0 3050ms=0 3100ms=0 3150ms=0 3200ms=0 3250ms=0 3300ms=0 3350ms=0 3400ms=0 3450ms=0 3500ms=0 3550ms=0 3600ms=0 3650ms=0 3700ms=0 3750ms=0 3800ms=0 3850ms=0 3900ms=0 3950ms=0 4000ms=0 4050ms=0 4100ms=0 4150ms=0 4200ms=0 4250ms=0 4300ms=0 4350ms=0 4400ms=0 4450ms=0 4500ms=0 4550ms=0 4600ms=0 4650ms=0 4700ms=0 4750ms=0 4800ms=0 4850ms=0 4900ms=0 4950ms=0

Caches:
Current memory usage / total memory usage (bytes):
  TextureCache            28800 / 134217728
  Layers total          0 (numLayers = 0)
  RenderBufferCache           0 /  2097152
  GradientCache               0 /   524288
  PathCache                   0 /  4194304
  TessellationCache           0 /  1048576
  TextDropShadowCache         0 /  2097152
  PatchCache                192 /   131072
  FontRenderer A8         53983 /   524288
    A8   texture 0        53983 /   524288
  FontRenderer RGBA           0 /        0
  FontRenderer total      53983 /   524288
Other:
  FboCache                    0 /        0
Total memory usage:
  553280 bytes, 0.53 MB


Pipeline=FrameBuilder
Profile data in ms:

        org.demo.demo_android_skia/org.demo.demo_android_skia.DemoAndroidSkiaActivity/android.view.ViewRootImpl@cf7a43c (visibility=8)
        Draw    Prepare Process Execute

View hierarchy:

  org.demo.demo_android_skia/org.demo.demo_android_skia.DemoAndroidSkiaActivity/android.view.ViewRootImpl@cf7a43c
  23 views, 23.67 kB of display lists


Total ViewRootImpl: 1
Total Views:        23
Total DisplayList:  23.67 kB