APM_卡顿检测模块

11 阅读16分钟

前言

卡顿检测这块是用的腾讯的一个开源库 matrix,这篇文章说一下原理。

RunLoop

iOS 的应用消息循环是基于 RunLoop 机制:

官方定义的内部逻辑:

  1. 通知 Observer 已经进入了 RunLoop
  2. 通知 Observer 即将处理 Timer
  3. 通知 Observer 即将处理非基于端口的输入源(即将处理 Source0)
  4. 处理那些准备好的非基于端口的输入源(处理 Source0)
  5. 如果基于端口的输入源准备就绪并等待处理,请立刻处理该事件。转到第 9 步(处理 Source1)
  6. 通知 Observer 线程即将休眠
  7. 将线程置于休眠状态,直到发生以下事件之一
    • 事件到达基于端口的输入源(port-based input sources)(也就是 Source1)
    • Timer 到时间执行
    • 外部手动唤醒
    • 为 RunLoop 设定的时间超时
  8. 通知 Observer 线程刚被唤醒(还没处理事件)
  9. 处理待处理事件
    • 如果是 Timer 事件,处理 Timer 并重新启动循环,跳到第 2 步
    • 如果输入源被触发,处理该事件(文档上是 deliver the event)
    • 如果 RunLoop 被手动唤醒但尚未超时,重新启动循环,跳到第 2 步
  10. 本次 RunLoop 运行结束时,通知 Observer 已经退出 RunLoop

主线程的 RunLoop 负责组织主线程上的事件处理,包括用户交互、注册在主线程 RunLoop 上的定时器,以及提交到主队列的任务等。如果其中某段任务处理耗时过长,后续需要主线程执行的工作就可能被延迟,用户就有可能感知到卡顿。

所以,监听卡顿的思路很直接,观察主线程 RunLoop 什么时候开始干活,到它什么时候休息,如果这段时间超过阈值,我们就认为它出现了卡顿。

RunLoop 有 6 个可以通过 Observer 观察到的状态:

  • kCFRunLoopEntry:进入 RunLoop,即将开始事件处理循环
  • kCFRunLoopBeforeTimers:即将处理 Timer
  • kCFRunLoopBeforeSources:即将处理输入源
  • kCFRunLoopBeforeWaiting:准备休眠,等待事件或定时器触发
  • kCFRunLoopAfterWaiting:刚从休眠中醒来,尚未处理这次唤醒对应的事件
  • kCFRunLoopExit:RunLoop 退出

要注意的是 Entry、Exit 对应一次 RunLoop 运行调用的进入和退出,不是每处理一个事件就触发一次。

RunLoop 的原理可以看看 iOS概念攻坚之路(一):RunLoop。

Matrix 的实现

如何判定是卡顿?

Matrix 判断主线程的核心依据是:RunLoop 已经开始处理工作,迟迟没有回到等待状态,而且这段连续忙碌的时间超过了阈值。

  1. RunLoop 被唤醒,进入 AfterWaiting

Matrix 记录当前时间,并把主线程标记为 "忙碌",BeforeTimers、BeforeSources 也会设置这个标记,但如果已经处于忙碌,就不会重新计时

// myRunLoopBeginCallback 中的处理
switch (activity) {
    case kCFRunLoopAfterWaiting:
    case kCFRunLoopBeforeTimers:
    case kCFRunLoopBeforeSources:
        // 只有刚开始忙碌时才记录时间
        if (!g_bRun) {
            gettimeofday(&g_tvRun, NULL);
        }

        g_bRun = YES;
        break;

    default:
        break;
}
  1. 主线程开始执行事件处理代码

这里就是处理各种各样的事件,Source 0、Source 1、定时器这些事件。假如某个回调里有耗时计算,或者一直等待锁,这段处理就会比较耗时,迟迟不能结束,RunLoop 也就走不到 BeforeWaiting。

  1. 如果顺利走到 BeforeWaiting,Matrix 就清除忙碌标记

说明这段忙碌已经结束,接下来的正常休眠时间不参与卡顿判断。

// myRunLoopEndCallback 中的核心处理
if (activity == kCFRunLoopBeforeWaiting) {
    gettimeofday(&g_tvRun, NULL);
    g_bRun = NO;
}

所以,在检查的时候,Matrix 主要看两个条件:

忙碌标记还在,并且「当前时间 - 忙碌开始的时间」 超过阈值

如果满足这个条件,就认为主线程发生了卡顿。

BOOL isBusy = g_bRun;
struct timeval start = g_tvRun;

struct timeval now;
gettimeofday(&now, NULL);

unsigned long long duration =
    [WCBlockMonitorMgr diffTime:&start endTime:&now];

// 简化后的核心条件:省略时间有效性及特殊场景检查
if (isBusy && duration > g_RunLoopTimeOut) {
    return EDumpType_MainThreadBlock;
}

比如醒来时记下 t0,业务回调一直没有结束,忙碌标记就仍然为 YES。检查时发现 now - t0 超过阈值,就判定卡顿,如果早已进入正常休眠,标记就是 NO,时间差再大也不会触发这个判断。

Matrix 的默认阈值是 2 秒。

采集报告

Observer 的回调是在主线程上执行的,负责记录忙碌状态和时间,但是我们不能在主线程去处理关于卡顿检测的这些代码,因为如果主线程长时间停留在某段业务代码里,或者阻塞在锁等待上,就无法及时继续后续的事件处理,依赖主线程执行的监控回调也会被延迟。

所以 Matrix 是有另外一个独立的监控线程来检测这些状态,这个线程在 Matrix 里叫 m_monitorThread,入口是 threadProc,负责超时检查、还有可选的提前采样开关,以及命中卡顿后的过滤和报告处理。

因为光知道有卡顿还不行,得知道为什么发生了卡顿。

它有两条线:

  • 不开启提前采样(默认)
  • 开启提前采样

所谓采样的主要就是采集主线程的调用栈。

不开启提前采样

默认情况下,监控线程每 1 秒检查一次主线程状态,如果主线程被标记为忙碌状态,而且持续时间超过 2 秒,就进入卡顿处理流程。

这个时候监控线程会去抓取主线程的调用栈,然后判断是否需要记录这次报告,因为卡顿可能持续很久,然后并不是每次拿栈都需要落到报告中,如果是一直抓到相同的栈,那就没必要重复的记到报告中,流程是这样的:

抓到的栈是否生成报告下次等多久
A生成,保存 A1 秒
A相同,跳过2 秒
A相同,跳过3 秒
A相同,跳过5 秒
A相同,跳过8 秒
B变了,生成,保存 B重置,1 秒
C又变了,生成,保存 C重置, 1 秒
C相同,跳过2 秒
C相同,跳过3 秒
A与之前保存的 C 不同,生成,保存 A重置,1 秒

可以看到如果时间一样,那么下次抓栈的时间会越来越久,这是一种 退火算法。

退火算法

所谓 "退火",就是 如果连续检查发现主线程仍然卡顿,而且抓到的堆栈没有变化,就跳过重复报告,并逐步延长下一次检查的等待时间。

因为如果程序一直卡住,然后栈又一样,那没有必要每次都生成重复的报告,生成报告需要把完整的线程调用栈、内存状态、上下文信息这些东西格式化,还要写到磁盘,这种操作本身就耗费资源,而且现在又是卡顿的情况,一整个就是火上浇油,主要是重复的报告也没有什么意义。

具体咋退呢?

Matrix 会保存 "上一轮间隔" 和 "当前间隔",初始都设为基础检查间隔,默认是 1 秒。

每次遇到相同栈:

新间隔 = 上一轮间隔 + 当前间隔
上一轮间隔 = 当前间隔
当前间隔 = 新间隔

因此,连续遇到相同栈时,等待时间会变成:

1 秒 → 2 秒 → 3 秒 → 5 秒 → 8 秒 → 13 秒……

同时会让本次检查跳过报告生成。

检查时刻检查结果本次处理等多久再检查
第 0 秒第一次取得栈 A保存比较栈,生成报告1 秒
第 1 秒仍然超时,还是栈 A跳过重复报告2 秒
第 3 秒仍然超时,还是栈 A跳过重复报告3 秒
第 6 秒仍然超时,还是栈 A跳过重复报告5 秒
第 11 秒仍然超时,还是栈 A跳过重复报告8 秒

等待下次检查取得有效但不同的栈的时候,即使主线程仍然超时,也恢复基础间隔,并把新栈保存为比较依据,也就是结束本次退火策略。

开启提前采样

提前采样,也就是提前采调用栈,开了之后,每 50ms 就会采集一次调用栈,不管你这那的,管你忙不忙,闲也给你采。

采了之后,会进到一个队列,队列的容量的计算方式是:

检查间隔 / 采样间隔 = 1000ms / 50ms = 20

然后后面的栈会覆盖前面的。

当确定发生了卡顿,就会从记录的栈队列中,挑出最合适的一条完整的调用栈,Matrix 会选 栈顶地址连续重复,计数最大的那个采样,如果并列的话,就选更新的那份 。因为如果连续多次采样都落在同一个位置,这个位置值得优先排查。

过程是这样的:

1. 每次采集到一条栈,先看它的栈顶地址

比如有两次采样:

上一次:[地址 A, 地址 X, 地址 Y]
这一次:[地址 A, 地址 M, 地址 N]

这里比较的是第一个地址 A,即使后面的调用链不同,这一步仍然认为栈顶相同。

2. 记连续重复的计数

本次栈顶 == 上次栈顶 → 本次计数 = 上次计数 + 1
本次栈顶 != 上次栈顶 → 本次计数 = 0

这里只根据栈顶地址累计连续重复次数,并不要求整条调用链相同。

3. 从缓存里取计数最大的样本

假设缓存中有以下的样本,A、B 是不同的栈顶地址:

采样顺序: 1  2  3  4  5  6  7  8  9
栈顶地址: A  A  A  B  A  B  B  B  A
重复计数: 0  1  2  0  0  0  1  2  0

第 3 次和第 8 次的计数都是 2,并列最大。Matrix 从最新样本开始查,所以选中第 8 次才到的完整调用栈,把它作为代表栈交到报告。

所以这里即使 A 出现了 5 次,B 出现了 4 次,但最终选的还是 B,因为看的是连续重复计数,不是出现的总次数。

最终的报告

前面我一直在强调主线程,但其实实际的报告中不仅仅只会有主线程的调用栈,因为在生成报告的时候,其实 Matrix 会去采集当前进程的所有线程的调用栈,然后都写进报告中:

未开启提前采样:

检测到主线程超时
    ↓
即时抓取主线程栈,用于过滤和退火判断
    ↓
通过过滤
    ↓
调用 dumpFileWithType,进入 KSCrash 报告流程
    ↓
采集主线程和其他线程的现场栈
    ↓
写入报告:
主线程现场栈 + 其他线程现场栈

开启提前采样:

尚未超时,就按采样间隔采集主线程栈,保存到队列
    ↓
检测到主线程超时
    ↓
取队列中【最近一次主线程栈】,用于过滤和退火判断
    ↓
通过过滤
    ↓
从队列中选出【主线程代表栈】
    ↓
调用 dumpFileWithType,进入 KSCrash 报告流程
    ↓
采集主线程和其他线程的现场栈
    ↓
写入报告:
主线程代表栈 + 主线程现场栈 + 其他线程现场栈

开启提前采样会多出来一个主线程的代表栈,然后落报告的时候,都会采集当前进程的所有线程的当前的调用栈,主要还是看主线程,但是其他线程的调用栈可以作为辅助信息。

而且,在未开启提前采样时,超时阶段即时采集的主线程调用栈,仅用于过滤,通过过滤后,进入写报告流程,才会在这个位置,重新去采集主线程的调用栈和其他线程的调用栈,这个才是最终报告中的内容。

已开启提前采样时,一直在取的主线程调用栈,在通过过滤后,取出了一个代表的栈,然后进入报告流程,会再采集主线程的当前调用栈 + 其他线程的调用栈,也就是会有两条主线程的调用栈落入到报告中。

一份真实报告

{
  "report": {
    "id": "D4D3E0A4-0DCB-4B34-99D4-D78851E43E27",
    "timestamp": 1792729529,
    "type": "standard",
    "process_name": "HTAPMKitDemo"
  },

  "crash": {
    "threads": [
      {
        "backtrace": {
          "contents": [
            {
              "instruction_addr": 9622005768,
              "symbol_name": "__semwait_signal"
            },
            {
              "instruction_addr": 6875891756,
              "symbol_name": "nanosleep"
            },
            {
              "instruction_addr": 6634837256,
              "symbol_name": "+[NSThread sleepForTimeInterval:]"
            },
            {
              "instruction_addr": 4324661340,
              "symbol_name": "static HTHangValidationModel.blockMainThreadForFourSeconds()",
              "source_file": "HTHangValidation.swift",
              "source_line": 379
            },
            {
              "instruction_addr": 4324651328,
              "symbol_name": "closure #1 in HTHangValidationModel.triggerForegroundHang()",
              "source_file": "HTHangValidation.swift",
              "source_line": 240
            },
            {
              "instruction_addr": 6646869856,
              "symbol_name": "swift::runJobInEstablishedExecutorContext(swift::Job*)"
            }
          ]
        }
      }
      // 省略另外 11 个线程
    ]
  },

  "htapm": {
    "module": "hang",
    "detector": "matrix",
    "block_duration_us": 2105855,
    "runloop_threshold_us": 2000000,

    "collection": {
      "scene_threads": {
        "enumerated_thread_count": 12,
        "items": [
          {
            "thread_identifier": 3120216,
            "is_main_thread": true,
            "status": "captured",
            "frame_count": 6,
            "report_array_index": 0
          }
          // 省略其他线程的元数据
        ]
      },
      "main_thread": {
        "state": "not_requested",
        "reason": "disabled"
      }
    }
  }
}

这是抽取了 Matrix 的逻辑,放到 APM 的 Hang 模块后,采集的一份真实的报告,省略了部分的内容,只保留了关键的信息,并且为了方便阅读已经做了符号化了。

  • module: "hang":hang 模块
  • runloop_threshold_us: 2000000:卡顿阈值是 2 秒
  • block_duration_us: 2105855:检测时已经持续约 2.106 秒

报告里包含了 12 个线程的现场信息,主要是关注主线程,在 htapm.collection.scene_threads.items 中:

is_main_thread = true
report_array_index = 0

说明本次报告的主线程位于 crash.threads[0]。report_array_index 是两个位置之间的对应关系。

另外,collection.main_thread.reason 为 disabled,表示这次没有开启提前采样。因此,这里分析的是生成报告时采集到的 主线程现场栈。

__semwait_signal
nanosleep
+[NSThread sleepForTimeInterval:]
HTHangValidationModel.blockMainThreadForFourSeconds()
HTHangValidationModel.triggerForegroundHang()

可以看到,主线程当时停在等待操作中,这个等待是由 sleepForTimeInterval: 引起的。然后再往前,就定位到了业务方法 blockMainThreadForFourSeconds()。

对应的源码是:

@inline(never)
private static func blockMainThreadForFourSeconds() {
    Thread.sleep(forTimeInterval: 4)
}

再往下走,是 triggerForegroundHang() 中的闭包,因此,这次卡顿的调用路径是:

triggerForegroundHang 中的闭包
    ↓
blockMainThreadForFourSeconds()
    ↓
Thread.sleep(forTimeInterval: 4)
    ↓
主线程同步等待,无法继续处理后续事件
    ↓
超过 2 秒阈值,触发卡顿报告

所以这份报告最终指向,是 Demo 在主线程执行了同步休眠。

其他方式

CADisplayLink

我们的本地调试工具里会有一个检测当前 FPS 的功能,就是用 CADisplayLink 来实现的。

CADisplayLink 是直接跟屏幕的刷新率绑定的,硬件会发出一个帧同步(VSync)信号,CADisplayLink 通过监听这个信号来触发一个回调,所以它的节奏和屏幕刷新是一致的。

那就可以在记录这个回调次数,比如 1 秒中回调了多少次,假设 60Hz 的屏幕,一秒内只收到了 35 次回调,我们就可以判定出现了严重掉帧。

但是它的问题是,如果要判断主线程卡顿,它就需要注册到主线程的 RunLoop,如果注册到主线程,那主线程卡,它也会被延迟执行。

假设主线程执行一次图片解码,持续占用主线程 3 秒:


CADisplayLink 正常回调
        ↓
主线程开始执行 decodeImage
        ↓
持续执行 3 秒
这期间 CADisplayLink 回调也无法执行
        ↓
decodeImage 返回
        ↓
CADisplayLink 再次回调,发现与上次间隔很长

根据主 RunLoop 的执行机制,在这个过程中,即使把超过 xxx 秒就抓栈的判断写进 CADisplayLink 回调,这段判断本身也没有机会执行。

这就导致一个问题,等它发现异常的时候,导致卡顿的调用栈可能已经消失了,等它过了 3 秒后再去抓主线程的栈,抓到的是现在正在执行的回调现场,未必还能看到之前耗时的那段调用链。

所以它的局限就在于,它可以在恢复后发现回调曾经延迟,但是没法可靠的定位现场。

还有就是,FPS 即使低于 60 次/秒,也不一定就是卡顿,CADisplayLink 的回调频率还会收到配置、设备刷新率以及低电量等系统策略影响,而且就算回调是正常的,也不能证明每一帧都及时显示了,一帧还需要经过渲染和 GPU 那些阶段,Apple 明确区分了应用提交阶段的延迟与渲染阶段的延迟。只统计回调次数,也没法覆盖整条显示流程。

所以一般 CADisplayLink 可以作为一个辅助指标,开发调试的时候弄成一个小组件来用,不适合用来作为 APM 的卡顿检测。

子线程 Ping

子线程 Ping 就是子线程定时向主线程发个很轻的任务,让主线程回个消息。

子线程发任务的时候,会开始计时,主线程执行到这个任务时,就会回复子线程,如果子线程超过阈值时间还没有收到回复,就会判定本次的响应超时,然后采集主线程的堆栈。

探测任务必须等主线程执行,但判断超时、触发抓栈这些不需要等。

这种方式的局限在于:

  • 计时起点不同

Ping 测量的是 "探测任务从提交到执行,等了多久",如果主线程已经忙了 800ms 才发出 Ping,Ping 不会把之前的 800ms 算进去。

  • 等待时间可能由多个任务累积而成

如果 Ping 前面排着很多任务,也可能导致它迟迟不能执行。因此,超时不能直接证明某一个函数执行过久,只能说明这个探测任务没有及时得到处理。

综合来说还是 RunLoop 的方式更合适。

收尾

其实卡顿监控主要是回答两个问题:

  • 主线程有没有长时间无法响应
  • 以及当时为什么无法响应

本文介绍的方案,也就是 Matrix 中的方案,通过 RunLoop Observer 记录主线程的忙碌状态和开始时间,再由独立的监控线程检查是否超时,把异常发现和主线程的执行分开。

发现超时后,还需要考虑现场怎么保留、重复报告怎么处理。Matrix 是通过即时获取主线程栈,然后做重复的过滤,以及有退火策略。如果开启提前采样,会记录主线程的调用栈并入队列,最终选出一个主线程的代表栈。

进入报告采集流程后,会记录主线程和其他线程的现场,开启提前采样会多出一个主线程代表栈。

也给出了一个真实的报告,说明如何解读一份卡顿的报告,确认最终卡顿的原因。

另外,还比较了 CADisplayLink 和子线程 Ping 这两种方案。

好像没啥好说的了。