定时器触发日志¶

定时器触发日志是 Gecko 中内置的一项功能，它会为每个触发的定时器打印一行数据。这很有用，因为定时器触发是唤醒的主要原因，而唤醒会导致高功耗。

注意：如果您还没有阅读功耗分析概述，建议您现在阅读。它可能会让您更容易理解本文档的部分内容。

调用¶

定时器触发日志使用 Gecko 自身的日志机制，因此可以在任何构建中使用。设置以下环境变量以启用它。

NSPR_LOG_MODULES=TimerFirings:4

输出¶

启用后，定时器触发将为每个触发的定时器打印一行日志输出。最好将此输出重定向到一个文件。

以下示例展示了此输出的基本内容。

-991946880[7f46c365ba00]: [6775]    fn timer (SLACK      100 ms): LayerActivityTracker
-991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT   250 ms): PresShell::sPaintSuppressionCallback
-991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler
-991946880[7f46c365ba00]: [6775] iface timer (ONE_SHOT   200 ms): 7f46964d7f80
-1340643584[7f46c365ec00]: [6775]   obs timer (SLACK     1000 ms): 7f46a95a0200

每行包含以下信息。

前两个值标识线程。这不太有用。
下一个值是进程 ID (pid)。在多进程场景中这很有用。
接下来是定时器类型，包括 fn（函数）、iface（接口）或 obs（观察者），这是 Gecko 支持的三种定时器。
然后是函数类型，包括 ONE_SHOT（一次性定时器）、SLACK 或 PRECISE（具有不同精度的重复定时器）。
然后是定时器周期，以毫秒为单位。
最后是定时器的识别信息。函数定时器具有信息性标签。接口和观察者定时器仅具有地址，这不太有用，但它们足够罕见，因此通常不会造成太大影响。

以上示例仅显示了 Gecko 中 C++ 的定时器。对于 JavaScript 代码中的 setTimer 或 setInterval 调用，也存在定时器，如下例所示。

-991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT     0 ms): [content] chrome://browser/content/tabbrowser.xml:1816:0
711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT   100 ms): [content] http://edition.cnn.com/:5:7231
711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT   100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423

这些 JS 定时器用 [content] 进行注释，并显示创建它们的 JavaScript 源代码位置。它们可以来自 Firefox 中的 chrome 代码，也可以来自 Web 内容。

信息性标签仅存在于其创建站点已添加注释的函数定时器上。对于未添加注释的函数定时器，有三种可能的行为。

首先，在 Mac 上，代码使用 dladdr 立即获取名称，输出如下所示。

2082435840[100445640]: [81190] fn timer (ONE_SHOT 8000 ms): [from dladdr] gfxFontInfoLoader::DelayedStartCallback(nsITimer*, void*)

其次，在 Linux 上，代码使用 dladdr 获取符号库和地址，可以使用 tools/rb/fix_stacks.py 对其进行后处理。以下两行显示了在使用该脚本进行后处理之前和之后的输出。

2088737280[7f606bf68140]: [30710]    fn timer (ONE_SHOT    16 ms): [from dladdr] #0: ???[/home/njn/moz/mi1/o64/dist/bin/libxul.so +0x2144f94]
2088737280[7f606bf68140]: [30710]    fn timer (ONE_SHOT    16 ms): [from dladdr] #0: mozilla::RefreshDriverTimer::TimerTick(nsITimer*, void*) (/home/njn/moz/mi1/o64/layout/b

第三，在其他平台上，dladdr 未实现或无法正常工作，输出如下所示。

711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT    16 ms): ???[dladdr is unimplemented or doesn't work well on this OS]

??? 表示函数定时器缺少显式名称，方括号内的注释解释了为什么未使用回退机制.

如果未添加注释的定时器函数频繁出现，则值得明确对其添加注释，以便在其他平台上对其进行有效识别。（显然需要在 Mac 或 Linux 上运行以了解定时器函数的名称。）这可以通过使用 initWithNamedFuncCallback 或 initWithNameableFuncCallback 而不是 initWithNameCallback 初始化它来完成。

后处理¶

定时器触发日志会快速生成数千行输出。此输出需要后处理才能使其有用。如果输出重定向到名为 out 的文件，则以下命令将提取与定时器相关的行，计算每条唯一行出现的次数，然后按最常见的行优先打印。

cat out | grep timer | sort | uniq -c | sort -r -n

以下是此命令的示例输出。

801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT    50 ms): [content] http://widgets.outbrain.com/outbrain.js:20:330
-495057024[7f74e105ba00]: [7108]    fn timer (ONE_SHOT     4 ms): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT   100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423
801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT    50 ms): [content] http://static.dynamicyield.com/scripts/12086/dy-min.js?v=12086:3:3389
801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT    50 ms): [content] https://ad.double-click.net/ddm/adi/N7921.1283839CADREON.COM.AU/B9038144.122190976;sz=300x600;click=http://pixel.mathtag.com/click/img?mt_aid=2744535504761193354&mt_id=1895890&mt_adid=148611&mt_sid=973379&mt_exid=9&mt_inapp=0&mt_uuid=353d5460-19f6-4400-9bbd-d0fcc3bcf595&mt_3pck=http%3A//beacon-apac-hkg1.rubiconproject.com/beacon/t/d1f9921d-4e47-448f-b6ba-36cae1c31b65/&redirect=;ord=2744535504761193354?:83:0
801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler
-495057024[7f74e105ba00]: [7108]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler

第一列显示特定行出现的次数。

有时在执行此聚合步骤之前，通过在命令管道中插入一个或多个以下命令，通过去除每行中的某些部分来预处理输出会很有用。

sed 's/^[^:]\+: //'           # strip thread IDs
sed 's/\[[0-9]\+\] //'        # strip process IDs
sed 's/ \+[0-9]\+ ms//'       # strip timer periods

以下是添加了所有这三个命令到管道中的先前示例输出。

  fn timer (ONE_SHOT): [content] http://widgets.outbrain.com/outbrain.js:20:330
  fn timer (ONE_SHOT): nsBrowserStatusFilter::TimeoutHandler
  fn timer (ONE_SHOT): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
  fn timer (ONE_SHOT): [content] http://a.visualrevenue.com/vrs.js:6:9423
  fn timer (SLACK): LayerActivityTracker
  fn timer (SLACK): nsIDocument::SelectorCache
  fn timer (SLACK): CCTimerFired