WWDC 2019 Session 411译文

该 session 介绍了如何使用 Instruments 来衡量 app 的运行表现,通过它来找到 app 性能瓶颈并进行相应优化,通过 Demo 演示了如何使用 time profilersignposts 这两个工具来观察 app 的详细运行情况。

该 session 主要分为三个部分 :

  • Instument 简介
  • 使用 Time Profiler 分析应用
  • 使用 Signpost

Instrument 简介

Instruments 是一个强大的性能分析和测试工具,它可以帮助开发者分析 app 的运行状况从而优化其性能。它被内置于 Xcode 中,但也可以作为一个独立 app 来使用,并且可以用于多平台(MacOS,iOS,tvOS,watchOS)。

打开 Instruments 面板, 可以看到里面有一系列的模板,本 seesion 着重介绍了 Time Profiler 模板的使用。

Time Profiler 可以用来检测应用的 cpu 使用情况,它会按照一定的时间间隔来追踪每一条线程和每个 cpu 核心的堆栈信息。

屏幕快照 2019-06-16 下午1.51.04

除了Time Profile 外,Instruments 还提供了一系列好用的调试工具,比如 Core Animation 可以用来查看界面的离屏渲染、光栅化等;AllocationsLeaks 可以用来检查应用内存相关问题。网上有很多相关资料,这里就不再赘述了。

界面

左上角高亮区域是 profiling control (录制和暂停键) 以及 target area,通过 profiling control, 可以控制数据收集操作的开始、暂停和停止。通过target area,可以选择运行设备以及想要分析的应用。

屏幕快照 2019-06-16 上午11.00.14

使用 Instrument 会占用系统资源,为了使它对 app 的影响最小化,Instrument 提供了一种名为 最后几秒模式 (Last Few Seconds Mode)也称作 窗口模式(Windowed Mode)的特性。在窗口模式下, Instrument 在记录结束前不会分析或者显示结果,并且它会忽略除最后几秒外所记录的所有事件。这种模式适用于开始记录后,遇到问题时就停止记录的情况。一部分 Instrument 模板默认使用这种模式,因为它们会在极短的时间内记录大量的数据。

屏幕快照 2019-06-16 下午2.21.18

当一次 time profiler 结束后,显示结果类似下图。窗口上方的高亮部分被称为 Track Viewer。其中的每行被称作一个 TrackTrack 显示的是某种事件来源下的追踪数据,例如进程、线程、cpu等。一次 Instrument 记录可能会包含大量的 track

屏幕快照 2019-06-16 上午11.00.31

第二行的Points of interest 显示了 app 中开发者所关注区域的信息。 可以通过一系列的 API,例如 signpost 来标记出那些你想要关注的重点区域。关于这点的具体内容下文还会提到。

窗口的左下部分被称为 Detail View,在这里可以查看选中 Track 的详细记录数据。

屏幕快照 2019-06-16 上午10.59.35

Detail View 的右侧是 Extended Detail View, 它会根据使用的 intrument 模板提供相应地更加丰富的信息,在本例中,使用的是 time profiler,所以这里显示的是Heaviest Stack Trace

屏幕快照 2019-06-16 下午2.59.23

通过鼠标可以选中关注的区域,选中之后,Detail ViewExtended Detail View 也会更新来专注于选中的数据。

屏幕快照 2019-06-16 上午10.59.23

有关 Instrument 界面内容的更详细介绍,可以参见苹果官方文档 Instruments Help

使用 Time Profiler

在 WWDC 2018,苹果展示了一款名为 Solar System 的 Mac 应用。它支持点击、拖拽、缩放等多种手势来查看太阳系行星的运行轨迹,用户反映当他们使用 Command + R 命令刷新 app 数据时,页面会卡死并出现旋转等待图标(我们俗称的小菊花),在本 session 中,苹果工程师把它作为 demo 来演示如何通过 Instrument 来定位并修复该问题。

屏幕快照 2019-06-11 下午8.49.30

打开 Instrument,选择 time profiler 模板并开启录制,在一顿点击、移动、缩放、Command + R 操作之后,instrument 记录了一系列数据。在 cpu 使用率的高峰值区域,出现了一个红色的标签显示着 spinning 。在 Instrument 中出现 spinning 代表主线程被阻塞了。

spinning

查看 Main Thread 的记录数据,可以看到有一段高峰值,选中该区域,窗口下部的 Detail View 会更新并显示该段时间的记录详情。

屏幕快照 2019-06-15 下午4.57.40

由于Detail View 展示的信息太多,很难定位问题。我们可以查看右侧的 Expended Detail View 所显示的 Heaviest Stack TraceHeaviest Stack Trace 会展示这段时间内被频繁调用的函数。在这里,显示灰色的是系统框架提供的函数,白色的是进程的函数。

屏幕快照 2019-06-15 下午5.04.15

可以看到一个名为 scheduleParsingTask 的函数, 这个函数在主线程上执行了一些数据解析的操作,导致了主线程的阻塞。

屏幕快照 2019-06-15 下午5.06.52

为了修复这个bug,需要创建一个parsingQueue,并把数据解析操作放入该 queue, 如下图所示

屏幕快照 2019-06-19 下午10.30.22

再次运行 Instrument,在 app 上执行相同的操作后不会再发生卡死的现象。通过查看主线程上的记录数据,可以发现主线程上的 cpu 使用率维持在一个稳定且较低的状态,该bug已经被解决了。

屏幕快照 2019-06-15 下午5.10.55

Profiling 的技巧

  • Time profiler 是一个查看 app 耗时细节的优秀工具

    当 app 发生响应问题,或者当你想要加快 app 启动时间时,使用 time profiler 会是一个很好的选择。

  • 当程序卡死时,优先检查主线程

    主线程只能被用于更新 UI 或者响应用户的输入事件, 比如 Mac 上的鼠标点击或者 iOS 设备上的触摸。如果 app 长时间没有响应,很有可能就是主线程阻塞了。

  • release 配置下进行 profile

    Xcode 编译器支持不同的优化水平,在 debug 模式下会使用低优化水平,而我们通过 App Store 下载到的应用则使用高优化水平。确保在 profile 应用的时候使用的是 release 配置。

  • 在高负荷情况以及老设备上进行 profile

    在这个案例中,苹果工程师在开发过程中并没有遇到这个 bug,但是用户在他们自己的设备上遇到了。 所以如果可能的话,使用老机型来进行 profile。

  • 在模拟器上使用 Instrument要特别注意

    由于模拟器是在 mac 上运行的,这意味着它有着和 mac 相同的资源竞争管理、cpu 和内存性能、文件管理能力和硬件能力、发热限制等,这和其他设备上的表现会大不相同,需要特别注意。

尽管已经解决了 app 的响应问题,但是 cpu 的过高使用率仍旧没有改善,而过高的CPU使用率会导致

  • 电量消耗过快
  • 设备发热
  • mac 上的风扇转速过快

接下来,需要通过 signpost 来更深入的了解 app 运行情况,并解决 cpu 使用率过高的问题。

使用 Signposts

Time profiler 通过观察一段时间内应用的线程和调用栈的相互关系来对代码进行静态分析。但它无法精确测算代码是怎样执行的。如下图所示,一段代码可能会在一段时间内执行多次,也可能只执行几次, 甚至某些函数可以一直不断地执行来跑满 cpu。为了区分出不同代码的执行模式,需要精确的代码日志。那么如何才能获取这些代码日志呢? 答案就是使用 signpost

屏幕快照 2019-06-11 下午9.57.33

SignpostOSLog 家族的新成员,在 WWDC2018 的 session 405 中被提及,具体可以参考Measuring performance using logging

signpost的特点

  • 和print相比更为简单且高效
  • 内置有计时功能
  • 可通过 Instruments 进行追踪

举个例子

使用os_signpost(_ type: OSSignpostType, dso: UnsafeRawPointer = #dsohandle, log: OSLog, name: StaticString, signpostID: OSSignpostID = .exclusive) API,可以在代码中标记你想关注的事件 ,进而可以在 Instrument 中的 point of interest 中显示出来。要使用 signpost, 需要导入 os.signpost

WeChatd4284fb1e956e564adc970d3be01beb1

viewDidLoad 中添加 signpost 相关代码后,再次运行 time profiler,就可以在 point of interest 中查看到 viewDidLoad 的相关统计了,如下图

屏幕快照 2019-06-18 下午11.14.20

使用 Signpost with Point of Interest

在苹果工程师演示的 demo 中,他找到了一处可能导致 cpu 使用率上升的函数 setupScene(),通过使用 signpost 来查看该函数的具体运行情况

屏幕快照 2019-06-19 下午10.41.10

运行 Instrument,可以看到Point of Interest 中已经有了 setupScene() 的信息。在 Detail View 中可以看到setupScene() 函数一共被调用了8次,每次大约耗费大约 200 ms。

屏幕快照 2019-06-15 下午11.54.11

查找到 setupScene() 的调用者是 updateWithPlanet(),这个函数的作用是在 app 从服务器获取到数据后,更新那些有新数据的行星的 model。这里如果返回数据中包含有多个行星的新数据,就会多次调用 prepareScene(),而 prepareScene() 又调用了setupScene(),从而导致 cpu 使用率快速上升。正确的做法应该是批量更新数据后再执行一次 setupScene() 来绘制页面。

屏幕快照 2019-06-16 上午9.46.52

在我们的日常工作中,这种问题很容易在某次添加新功能或者修复其他 bug 的时候悄悄混入我们的代码中。为了防止这样的情况,可以使用单元测试。

屏幕快照 2019-06-16 上午9.53.13

measure(_:) 函数可以用来计算代码块中函数的执行时间,常用于单元测试中。

上图是一个测试 solar system app 加载数据功能的 XC Test。在 Instrument 下构建并运行该测试。

屏幕快照 2019-06-16 上午10.18.24

三击上图中的 XCTestPerformance 可以快速选中其中的一段。 在 Detail View 中看到 setupScene() 现在仅会被调用一次。至此,我们通过使用 signpost 收集到的信息减少了 cpu 的使用率。

屏幕快照 2019-06-16 上午10.23.51

小结

  • 静态分析 (Time profiler)显示了哪些代码会经常执行
  • 精准测量 (signpost)显示为什么代码会被执行,以及它是如何被执行的
  • XCTests 可以在 profile 中可靠地重现 app 的工作状况

除了上述功能外, Instrument 还提供了其他模板来帮助了解 app 的资源使用状况

屏幕快照 2019-06-11 下午10.03.31

File Activity 模板可以记录并分析文件系统以及磁盘读写活动。

Network 模板用来分析程序如何使用TCP/IP和UDP/IP链接。

System Trace 模板可以显示系统的综合表现,可以查看线程调度情况、虚拟内存等

Instrument 还有一些高级特性。如果你是一个框架的开发者,想让你的用户提供他们在使用你的framework 时所遇到的性能问题, 那么你可以提供自定义的 Instrument 模板组合。关于如何创建自定义的 Instrument,可以参考Creating Custom Instruments

屏幕快照 2019-06-11 下午10.03.41

Instrument 的变化

在使用新版 Instrument 过程中,发现了如下几点变化

  1. 增加了App LaunchSwiftUI 模板。

1560877030729

使用测试工程尝试了一下 App Launch 模板。在开启 Instrument 录制后, app 会启动并在启动完成后一小段时间后直接退出,同时 Instrument 界面会提示正在分析中,一段时间后,呈现如下界面

屏幕快照 2019-06-18 下午9.43.07

在界面上显示出了 App life Cycle, 具体到每一色块的信息是:

  • Initializing (1.10s)
  • Launching - UIKit Initialization (155.47ms)
  • Launching - UIKit Scene Creation (52.12ms)
  • Launching - didFinishLaunchingWithOptions (90.24ms)
  • Lauching - initial Frame Rendering (175.72ms)
  • Foreground - Active (3.46s)

可以双击感兴趣的区域,在Detail View 中查看具体的堆栈信息,相信这个功能可以为 app 启动优化工作带来不少便利。(后来发现其实运行其他模板,比如 Time Profiler,在 Track 列表中也会直接显示 app 生命周期信息)

屏幕快照 2019-06-18 下午10.15.24

  1. Track 列表中增加了一个 Thermal State 用来反应设备发热状况,不过这个温度反应的其实是 Xcode 11 新增的对设备温度的模拟功能,而不是真实的设备温度。关于这一点的详细信息可以查阅专栏中的文章Debugging in Xcode 11

  2. 新版 Instrument 的 Track 列表中的线程相关信息被整合到了单独的 app 进程信息中,点击可以展开查看线程详情。

    屏幕快照 2019-06-19 上午1.22.14

总结

平时在工作中遇到 bug,我一般会尝试通过断点调试来查找问题所在。其实 Instrument 已经为我们提供了一系列强大的模板工具,结合一些测量的 API ,就可以很清晰的呈现出代码的运行情况从而来定位 bug。所以下次遇到没有头绪的 bug 时,不妨使用 Instrument 来进行调试。

而且正如苹果工程师在 session 开头讲的那样,无论你的app UI 多么吸引人,一旦发生崩溃或者长时间的无响应,那么用户对你 app 的好感就会荡然无存。所以一定要尽早并且经常性地使用 Instrument 对应用进行性能分析,及早发现并把 bug 扼杀在摇篮里。

参考资料

Using Time Profiler in Instruments

Measuring performance using logging

Creating Custom Instruments

Instruments Help