08fe268f18ca9e163fad99e5b3cc1830
WWDC 2018:使用日志框架测量性能

本文是 WWDC 2018 Session 405 的观后感,原视频和 pdf 可以在这里看到。

众所周知,应用交互的流畅度决定了用户对这款用户的喜爱度,所以对于每个 iOS 工程师而言,应用的流畅程度是非常重要的。而这里所说的流畅度在工程师层面来理解就是应用的性能是否处于一个比较优的状态。那我们在发现页面卡顿时,如何去检测卡顿是哪一段代码引起的呢?目前业界的卡顿检测已经非常多了,比如 Instrument 的 Time Profile,各种基于 runloop 的卡顿率检测开源库。但是今天主要来说一说 iOS12 苹果为我们带来的一个新的检测方案,也就是基于 OSLog 的一套新 API。

好了,题外话讲完,我们正式进入正题。该 Seesion 主要有下面几部分组成:

  • 集成 signposts
    • 异步并行操作
    • 添加原数据
    • 控制 signposts 的启用和禁用
  • 使用 Instruments 分析

首先先简单回顾一下 OSLog,苹果在2016年推出这个现代化的日志记录框架,用来获取系统调试信息,这个框架主要是为效率而生。可以看一个简单实例

let logHandle = OSLog(subsystem: "com.example.widget", category: "Setup")
os_log(.info, log: logHandle, "Hello, %{public}s!", world)

PS: 更多内容可以参看 WWDC 2016 Session 721 Unified Logging and Activity Tracing

这里要介绍的 SignpostOSLog 进行了一些扩展,新增了一些用于衡量性能的 API。首先我们来看看如何在代码中集成 Signpost

集成 Signpost

使用 signpost 计算耗时

想象一下我们有这样一个应用,包含了一组图片的 feed 流,滑动过程中,我们会去加载 feed 流的封面,页面如下图所示。
-w200

-w200

我们想要获取每张封面的加载耗时,如果使用 Signpost 相关 API 我们需要如何做呢?
使用 Signpost 我们可以标记每个任务的开始和结束,然后将他们关联起来,调用的相关 API 也比较简单,我们只需要做一个简单的打点,通过两个关联的打点,我们就可以记录这个任务的具体耗时,如下图所示。

伪代码如下

// 引入 os 框架
import os.signpost

// 使用自定义标识和分类创建一个 log,subsystem 建议使用 bundle id,category 主要用于对相关联的操作进行分类
let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")
for element in panel.elements {
    // 任务开始前打点
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
    fetchAsset(for: element)
    // 任务结束打点,注意  log 和 name 要和开始前的匹配,这样才会自动关联
    os_signpost(.end, log: refreshLog, name: "Fetch Asset")
}

如果想要统计所有任务的耗时,也非常简单,只需要在 for 循环前后埋点即可,不过需要注意的一点是 name 的值,如上所述因为想要计算的所有任务的耗时,所以新起了一个值,来进行关联。代码如下

let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")
os_signpost(.begin, log: refreshLog, name: "Refresh Panel")
for element in panel.elements {
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
    fetchAsset(for: element)
    os_signpost(.end, log: refreshLog, name: "Fetch Asset")
}
os_signpost(.end, log: refreshLog, name: "Refresh Panel")

整个时间轴看起来如下图所示

异步任务耗时的计算

如果我们的任务是一步步循序渐进的,上面的方式是没问题的,但是实际应用场景中,大部分任务是异步同时进行的。因此上面的 name 唯一标识在异步并行的场景下,不再能满足我们的需求,因为各任务的起始时间是一样的,但是结束时间肯定不一样,如果都用相同的 name 来做唯一标识,时间轴肯定会存在重叠的情况,因此无法区分各个任务的耗时时间。

因此为了解决上述问题,我们可以使用另一个 Signpost 的 API,叫做 signpost ID。通过 signpost ID,可以区分同种类型操作中的不同任务。所以即使两个任务时间轴有重叠,但是由于 signpost ID 的存在,系统就可以区分出这是两个不同的时间间隔,所以只要 .begin.end 打点时传入的 ID 一致,系统就会把二者自动关联起来,计算耗时。代码如下:

let refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")
let spidForRefresh = OSSignpostID(log: refreshLog)
os_signpost(.begin, log: refreshLog, name: "Refresh Panel", signpostID: spidForRefresh)
for element in panel.elements {
    let spid = OSSignpostID(log: refreshLog, object: element)
    os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID: spid)
    fetchAssetAsync(for: element) {
        os_signpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)
    }
}
notifyWhenDone {
    os_signpost(.end, log: refreshLog, name: "Refresh Panel", signpostID: spidForRefresh)
}

signpost ID 可以通过 OSSignpostID 构建函数传入一个 log handler,以及任意一个对象(可选)。后面的 object 参数非常有用,因为只要传入的 object 是一样的,那么生成的 ID 也是一样的(当然前提是 log handler 也要一致)。

从上面示例我们可以得知,只要 .begin.end 的其它参数是一致的,系统就会自动将其匹配,这样就可以在任何地方去进行“打点”。

所以整个 API 总结一下,大概是下面这样一个层级。

| 参数 | 示例 | 含义 |
| :-: | :-: | :-: |
| Log category | "RefreshOperations" | 相关操作 |
| Signpost name | "Fetch Asset" | 想要计算的某类操作 |
| Signpost ID | spid | 同一类操作下的某个任务 |

添加自定义 Metadata

看完上面部分,你可能会有个疑问:是否可以在 signpost 中携带一些额外信息呢?答案是肯定的。os_signpost 函数为我们提供了一些可选参数,用于传递上下文。传入的参数得是 os_log 格式的字符串,可以传入不同类型的参数以及动态字符串,最终这些字符串都会显示在 Instrument 中。

top Created with Sketch.