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