LWN：让ftrace的ring buffer里的时间戳更精确！

关注了就能看到更多这么棒的文章哦～

Accurate timestamps for the ftrace ring buffer

September 22, 2020
This article was contributed by Steven Rostedt
https://lwn.net/Articles/831207/

ftrace（function tracer）已经成为了 kernel 里调查问题的最主要工具。ftrace 同 kernel 里许多其他机制一样，都利用了 ring buffer 来跟 user space 快速告知所发生的 event（事件）。这些 event 包括了记录事件发生时间的 timestamp（时间戳）。一直以来，这种 ring buffer 设计方案导致在中断处理函数（interrupt handler）里创建的 event 所附带的时间戳会不准确。这个问题终于得到了解决，请继续深入阅读来了解这个问题的起因以及解决方案。

The ftrace ring buffer

ftrace ring buffer 是在 2008 年引入的。当时过了大半年之后，ftrace 就彻底实现了 lockless 机制，这是把 ring buffer 是分割成多个 per-CPU buffer 来实现的，每个 per-CPU buffer 都有一系列的 sub-buffers，每个 sub-buffer 的大小都是按照所运行的体系架构的 page size 来定的。设计中本来没有规定必须要按照这个 size 来，不过使用 page size 的话，调用 splice()系统调用会很方便。每个 sub-buffer 都在开头的地方包含一个 header 信息，其中包括了这个 sub-buffer 里所存放的第一个 event 的时间戳。对 per-CPU buffer 的写入操作，只能由这个 CPU 来进行。这样就保证了所有的写入冲突都是按照 stack order 来进行的。也就是说：在 normal context 进行的某次 write 操作，只有可能被 interrupt context 中发生的 write 操作所打断来产生竞争，并且 interrupt context 中发起的这个 write 操作一定会彻底完成之后才会返回 normal context。并不需要担心其他 CPU 上同时在进行的 event write 操作。上述被中断的这个 write 看起来就是下面这个样子：

 

[Interrupted write timing diagram]

这种设计中，要求这些会打断其他 event write 过程的 event 写入者都必须要先彻底完成写入，然后才会返回给被打断者来继续进行。这样整体的 lockless 实现就比较容易。尽管这种方案简化了多个 write 操作之间的协调过程，但是在记录时间方面却带来了一些额外问题。

在具体谈到时间戳管理部分之前，需要先来了解一下 ring buffer 是如何预留空间的。需要有一个索引（index）用来记录 sub-buffer 里最后一次 event write 操作的位置。然后会把这个索引加上每个 event 的长度（使用 local_add_return()函数来进行，因为这是一个 per-CPU index，所以可以使用这个函数），这样就可以简单求得新的 event 的位置，也就是用返回值再减掉 event length 即可。

 

[Reserving space for an event in the ring buffer]

当然，如果返回值超过了 sub-buffer 的 size，那么就意味着这个 sub-buffer 没有空间容纳这个 event 了，接下来就可以去下一个 page 寻找空间了。

Timestamps

64 位的 timestamp 需要有 8 个 byte 的空间来存放。event 的 length 越长，就需要越多的写入空间，这样 ring buffer 中能容纳的 event 数量就越少。为了让 event header 的 size 尽量小，ring buffer 的代码里尽量避免保存完整的时间戳。ring buffer 里面的某个 event 是这样定义的：

struct ring_buffer_event {
  u32 type_len:5, time_delta:27;
  u32 array[];
}

最开始 5 位记录了 event 类型和 size，比如值为 29 的话就是一个 padding event，30 就代表 time-extend event，31 表示是绝对时间戳。如果取值在 1 到 28 之间，就表示这是一个带有 data payload 的 event，内容记录在 array 这部分，并且 event 的总 size 就是 type_len 再乘以 4。如果 event 的总 size 超过了 112（也就是 4*28）字节，那么 type_len 就被设置为 0，而是用这个 32 位的 array 区域来存放 event 的 length，而 data payload 就紧挨着其后存放在 array 区域中。大多数 event 的长度都不会超过 112 字节。这种设计使得 event 存放很紧凑。注意这里所有的 event 都是按照 4 字节对齐的。接下来的 27 位就是存放 time_delta。它表示从上一个 event 之后过去了多少时间，也就是时间间隔（time delta）。如果这是此 sub-buffer 中的第一个 event 的话，就填 0，而在 header 里面完整记录 8 字节的时间戳。如果时间戳的单位是纳秒的话，那么最大可表示的时间间隔就是 134.217728 毫秒（2^27 纳秒）。如果下一个 event 是在超过了 134.217728 毫秒之后才来的话，就需要增加一个 time-extend event，这里即利用 time_delta 域，也利用 array 里最开始的 32 位来确保可以最大表示 18 年的时间间隔（2^59 纳秒）。

Tom zanussi 需要提取出每个 event 的完整时间戳，从而展示 histogram（参看https://lwn.net/Articles/635522/ ）图示。由于这些 event 里面只记录了时间间隔，所以需要创建一个新的 event 来记录 59 位完整时间戳，这样 histogram 才能精确记录某个 event 的时间戳。上面提到过的 type 值为 31 就代表这种新的 event 类型，它和 time-extend 的存放方式类似，只是存放的不是时间间隔，而是存放自从启动以来的所过去的时间。实际上这个新的时间戳可以取代 time-extend 时间戳，因为只有 18 年不重启的机器上这两种类型才有区别。

The problem with nested writes

现在这种设计（记录上一个 event 到现在的时间差）用下来已经证明容易导致出错的。它需要把上一个记录的 event 的时间戳保存在 ring buffer 里，用来计算下一个 event 的时间差。这导致下面这些步骤需要是原子操作（但是无法实现这个要求）：

1. 读取目前 event 的时间戳。

2. 在 ring buffer 里面分配空间来保存当前的 event。

3. 计算当前 event 和上一个 event 的时间戳之间的时间差。

4. 把当前 event 的时间戳保存下来，用来计算下一个 event 的时间差。

上面的这些步骤中任何一个都可能被打断并导致上下文切换（比如发生了中断，或者 NMI——non-maskable interrupt）。这样我们就很难确认目前记录的当前 event 的时间差是否仍然是同上一个 event 的时间差。等到获取到上次的时间戳用来计算时间差时，有可能又发生一个中断，导致在我们还没分配到存储空间之前，ring buffer 里面就已经插入了多个 event：

 

[Interrupt during event storage allocation]

新的 event 的时间戳必须是在分配空间之前获取的，这样才能在万一刚分配好之后就发生中断时，供 event 用来计算时间差。哪怕在 interrupt event 里面记录的是一个完整时间戳，如果这个被打断的 event 所用的时间戳是在分配空间之后才采集的时间，那么就会比这个 interrupt event 的时间戳更加晚了，尽管这个 event 其实是先发生的，图示如下：

 

[Timestamps taken after storage allocation]

无论采集时间的动作是在分配空间之前还是之后，上面描述的 interrupt 场景都会导致 ring buffer 里的时间看起来有往回走的现象。这是不应该发生的，因为它会导致在把 per-CPU buffer 的内容合并成一个统一输出 buffer 时的合并动作出错。

人们用来避免这个问题的方法很简单，就是对这些打断了别的 event 的 event，干脆都把时间差这里填成 0。不过这样的话看起来就好像时间停止了一样。这种方案最明显的问题就是会丢失这两个 event 之间的时间差。输出内容看起来就好像这些 event 都是同时发生的。这种方案在过去 12 年里基本满足了大家的需求，不过仍然是一个设计缺陷。

想要看一下真实的例子的话，可以执行下面的命令：

trace-cmd record -p function

等一段时间之后再对这个输出文件来执行下列命令：

trace-cmd report --debug -l -t --ts-diff --cpu 4

这里 –debug 可以显示 sub-buffer 的分割点在哪里，-l 则可以看到 latency 信息（interrupt context），-t 则按纳秒来显示时间戳（否则的话会只保留到微秒），–ts-diff 则显示各个 event 之间的时间差，这里所用的 –cpu 4 是因为我自己的记录里面我是在 CPU 4 上找到的问题（我就是搜索了一下时间差是 0 的情况）。这样就可以给大家看到打断了正在记录的 event 的情况有些什么影响了：

trace-cm-1724    4....   137.210588990: (+84)    function:                      kfree [84:0xf44:24]
trace-cm-1724    4....   137.210589078: (+88)    function:                      wakeup_pipe_writers [88:0xf60:24]
trace-cm-1724    4d.h.   137.210589709: (+631)   function:             __sysvec_apic_timer_interrupt [631:0xf7c:24]
trace-cm-1724    4d.h.   137.210589709: (+0)     function:                hrtimer_interrupt [0:0xf98:24]
trace-cm-1724    4d.h.   137.210589709: (+0)     function:                   _raw_spin_lock_irqsave [0:0xfb4:24]
trace-cm-1724    4d.h.   137.210589709: (+0)     function:                   ktime_get_update_offsets_now [0:0xfd0:24]
CPU:4 [SUBBUFFER START] [137210590461:0x27c53000]
trace-cm-1724    4d.h.   137.210590461: (+752)   function:                   __hrtimer_run_queues [0:0x10:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                      __remove_hrtimer [0:0x2c:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                      _raw_spin_unlock_irqrestore [0:0x48:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                      tick_sched_timer [0:0x64:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                         ktime_get [0:0x80:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                         tick_sched_do_timer [0:0x9c:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                         tick_sched_handle.isra.0 [0:0xb8:24]
trace-cm-1724    4d.h.   137.210590461: (+0)     function:                            update_process_times [0:0xd4:24]
[...]
trace-cm-1724    4d.s.   137.210590461: (+0)     function:                   rcu_segcblist_pend_cbs [0:0x940:24]
trace-cm-1724    4d.s.   137.210590461: (+0)     function:                rcu_disable_urgency_upon_qs [0:0x95c:24]
trace-cm-1724    4d.s.   137.210590461: (+0)     function:                rcu_report_qs_rnp [0:0x978:24]
trace-cm-1724    4d.s.   137.210590461: (+0)     function:                _raw_spin_unlock_irqrestore [0:0x994:24]
trace-cm-1724    4..s.   137.210590461: (+0)     function:                rcu_segcblist_ready_cbs [0:0x9b0:24]
trace-cm-1724    4d.s.   137.210590461: (+0)     function:             irqtime_account_irq [0:0x9cc:24]
trace-cm-1724    4....   137.210590461: (+0)     function:             kill_fasync [0:0x9e8:24]
trace-cm-1724    4....   137.210605019: (+14558) function:             pipe_unlock [14558:0xa04:24]
trace-cm-1724    4....   137.210606026: (+700)   function:             __x64_sys_splice [700:0xa58:24]

从上面的输出中，可以看到调用 __sysvec_apic_timer_interrupt() 来自一个中断的，发生时间就是在 kill_fasync() 这个调用正开始被记录、但是还没有在 ring buffer 里分配到空间的时候。怎么能判断出来的呢？因为 __sysvec_apic_timer_interrupt() 有记录到一个有效的时间差，说明它当时成功地在 kill_fasync() 之前分配到了空间，不过也是在开始处理 kill_fasync() 的 event 之后了。等到 event 开始处理之后，只有第一个进入 ring buffer 的 event 能有有效时间差，后续的 event（包括这个被打断的 event，因为它的存储空间是后面分配的）时间差都是 0。

上面的 –debug 参数是最主要的参数，用来显示额外数据，包括下面这行：

CPU:4 [SUBBUFFER START] [137210590461:0x27c53000]

这行输出说明这里是一个 sub-buffer page 的边界。因为每个 sub-buffer 都会先保存一个绝对时间戳，因此每个 sub-buffer 的第一个 event 就会带有上面这样的时间差。过去多年里，这个问题一直很让我困扰。我花了许多时间来思考怎么能找到一个方法来让这种嵌套情况下的时间戳更加有意义。事实上我们只要关心 stacked write，不需要关心 concurrent write，所以我相信应该有解决方案的。因为这里实际上只有 4 层 stack 需要考虑，我想我可以让每层都变成一个状态（state），利用前后这两个状态来同步时间戳。这四个状态分别为：normal context, software-interrupt (softirq) context, interrupt context, NMI context。理论上说，你可以在 NMI 里面加上 machine check 作为第 5 层，不过 softirq 打断某个 event 、然后在写入 event 时又被 interrupt 打断、在写入 event 的时候又被 NMI 打断并写入 event，这种概率是非常低的，在这一堆条件之上再发生一次 machine check 的概率那就更低了。哪怕是用 function tracing 来跟踪所有 context 的每个函数调用的情况下，我也很难抓到一次嵌套事件，更别说要碰到 4 层嵌套了。我们可以检测出当前的嵌套级别，这样最坏情况也就是我们在检测到之后写个 0 作为时间差而已。后来看下来并不需要担心这一点，因为我的最终方案不需要知道这些状态级别。

Avoiding cmpxchg()

我之前试图解决这个问题的时候，想方设法地避免使用 local_cmpxchg() （也就是 cmpxchg()的 local CPU 版本）。这个 cmpxchg()是一个架构相关的函数，会采用原子操作方式从某个地址读取数值，同一个给定值进行对比，如果两者相等，就会把第三个值写到这个地址去；不等的话则不会更改这个地址。从这个地址读出来的原始值会作为 cmpxchg() 的返回值，可以用来判断 cmpxchg() 是否成功地更改了这个地址。

当我刚开始修改 ring buffer 的时候，只要用了 local_cmpxchange()替换 local_add_return()，我的所有性能测试都会看到有一点性能下降。因此我就设立了这个不使用 cmpxchg() 的目标，取而代之的是对每个嵌套状态都是用一个独立的时间戳记录。最开始尝试过使用一个 4 元素的数组来存放时间戳，我试过各种方案来记录嵌套次数并且保存每个状态的时间戳。在检测到嵌套的时候，我以为一个上下文打断另一个上下文的时候会能够修正被打断的上下文的 timestamp，而不需要使用 local_cmpxchg()。不过最终发现情况更加复杂了，我还得处理类似这种问题：

 

[Three levels of interrupts]

这里处理时间戳数组，实际上是额外又增加了一个变量，需要跟其他的变量解决好同步问题。

上图中展示的情况是第一个 event 的时间戳刚刚采集下来并且分配好空间、但是 event 尚未真正写入的时候，这时候中断发生了。接下来这个 interrupt context 的 event 刚刚采集好时间戳并分配好空间的时候，又发生了 NMI 中断。此时因为 NMI 的空间分配并不是这一系列操作中的第一个 event，其他两个上下文正在被中断着，我很难确认这时候是不是应该更新 interrupt context 中 event 的时间戳，也许那个时间戳早已经更新过了。此外，在 interrupt context 中会在 NMI 添加过一个 event 之后，如果要再记录另一个 event，这时候我的代码就还要处理这种情况（在上一次 interrupt context 的 event 记录完毕之后又插入了来自另一个 context 的 event）了。就因为要记录这四种上下文以及相关的插入 event 就会导致状态机中状态数量大大增加，这看起来并不是一个可行方案了。

The twelve year old puzzle solved

Julia Lawall 报告了一个 bug，在她用 trace-cmd 记录 trace 的时候，发现时间顺序颠倒了。仔细调查之后我发现这是因为 Zanussi 加 histograms 功能时引入的 full timestamp 功能导致的。这个功能会在 event 嵌套场景中导致 time extention 不被 reset 成 0。对这个 issue 进行 fix 的过程启发了我，想到了另一个解决嵌套 timestamp 问题的主意。

我之前总是在尝试着避免使用 cmpxchg()，而在 debug Lawall 报告的问题的时候，我意识到 event 嵌套这种问题是非常罕见的，因为它们可以被检测出来，这样就可以从 fast path 分离出一条 slow path 来。fast path 就是通常的流程，这里每个 event 都不会打断另一个 event，自己也不会被打断。出现例外情况的话就走到 slow path 去。cmpxchg()如果只用在 slow path 的话，性能就不是什么问题了。因此我就不再需要在 slow path 里面限制使用 cmpxchg()了，这样我就有了其他的方案。这带给了我希望，鼓舞我沿着这个方向继续寻找解决办法。

在把 cmpxchg() 加回来的过程中，我发现使用 4 个状态的数组还是带来了太多额外复杂性。我就想办法能继续缩减这个数组，只需要关心被打断的 event 以及打断别人的 event。在发生被打断的情况时，这个 event 实际上“时间被冻结”了。它的时间不会再走，直到中断它的那个 context 退出并返回给它为止。所以，针对被打断的 event 来说，只有两种状态：打断前，和打断后。也就是说，每次被打断之后，只要我自己又可以继续进行处理了，那么也就确定那个打断了我的 context 已经完全运行结束了。这个特性表明，算法中每一步都可以得出一个有限状态集合，只要保留两种不同的时间戳：一个是在 ring buffer 中分配空间之前的时间戳，另一个是在这之后的时间戳。这样一来，解决方案就是利用下面 3 个信息：

• write_tail: 用来在 buffer 中针对这个 event 分配空间的 index。

• before_stamp：每个 event 在进行记录之前保存的时间戳。

• write_stamp：在每个 event 成功分配空间之后更新的时间戳。

下面的代码按顺序执行来确定下一个决策：

w = local_read(write_tail);
before = local_read(before_stamp);
after = local_read(write_stamp);
ts = clock();

一上来先把 write_tail 保存下来备用。这时候我们就可以确定此 event 是不是需要走 slow path 了。如果 before 不等于 after，那么只有两种可能性：要么这个 event 在另一个 event 更新 timestamp 的时候打断了它，要么就是这个 event 在读出 before_stamp 之后但是读取 write_stamp 之前被另一个 context 所打断了。无论是哪种情况，都应该走 slow path：

if (before != after) {
  event_length += RB_LEN_TIME_EXTEND;
  add_timestamp = RB_ADD_STAMP_FORCE | RB_ADD_STAMP_EXTEND;
} else {

这种方案里面需要插入绝对时间，而不是使用时间差。在 slow path 里，event length 需要按照绝对时间戳的 event（size 和 time extend 类型是一样的）的 size 来增加。这里 ADD_STAMP_FORCE 和 ADD_STAMP_EXTEND 两个标记是留给后面的算法用的。

哪怕某个 event 并没有打断其他的 event，也需要检查一下它距离上一个 event 的时间差在 event 的 time_delta 域是否可以放得下。否则的话就需要加一个 time extend。

 delta = ts - after;
 if (delta & ~((1 << 27) - 1)) {
  event_length += RB_LEN_TIME_EXTEND;
  add_timestamp = RB_ADD_STAMP_EXTEND;
 }
}

接下来会写入 before_stamp，并且在 ring buffer 里面分配空间，也就是增加 write_tail。

local_set(before_stamp, ts);
write = local_add_return(event_length, write_tail);
tail = write - event_length;

每个 event 的起始位置可以通过从 write（也就是 event 结尾处的 index）减去 event length 来获得。这个值会存到 tail 里，接下来对算法一开始计算出来并保存好的 write_tail 和 event start 进行比较。相等的话就说明没有其他 event 打断过这个算法（也就是保存 write_tail 和分配空间的过程）。这就是 fast path 了。不过这里还没完。还需要更新 write_stamp。要注意 before_stamp 早已经更新过了，跟 write_stamp 不同了。打断这个 event 的那些嵌套 event 都会走到 slow path 去，从而利用这里的绝对时间。下一步就是更新 write_stamp 了。

local_set(write_stamp, ts);

等一下，如果刚好在写入 write_stamp 之后、但是在 interrupt 写入 event 之前，又发生了一个中断呢？这样会不会导致 write_stamp 值错误呢，因为它并没有包含 ring buffer 里记录的上一次 event 的时间戳？没错，确实会发生这种情况，不过我们不用关心。原因是 write_stamp 只有在跟 before_stamp 相等时才会用在计算中。因为 before_stamp 跟 write_stamp 不相等，那么这些嵌套 event 都不会用它来做计算。这就是我们的算法里如何利用到 stacked interrupting event（也就是每个打断别人的 event 都会在完成执行之后才允许被打断的 event 继续执行）的地方了。before_stamp 总是由所有 event 来更新的，包括打断了这个 event 的嵌套 event 也会更新它，所以 before_stamp 任意时刻存放的 timestamp 就代表了 ring buffer 中所保存的最后一个 event 的时间戳，也就是 write_stamp 也应该设置的值了。更新 write_stamp 的时候还是需要很小心，不过已经很容易能确定这个 event 是否被其他 event 打断了，也就是容易判断出来是否需要使用 slow path，并利用上 cmpxchg() 了：

save_before = local_read(before_stamp);

if (add_timestamp & RB_ADD_STAMP_FORCE)
  delta = ts; // will use the full timestamp
else
  delta = ts - after; // remember, not force means not nested

if (ts != save_before) {
  after = local_read(write_stamp);
  if (save_before > after)
    local_cmpxchg(write_stamp, after, save_before);
 }

上面的代码首先再次读出 before_stamp，这是在 write_stamp 进行更新之后。如果在分配好 buffer 中的空间，到更新 write_stamp 之间，又发生了另一个 event 的话，before_stamp 跟读出的 timestamp（ts）也就不会相等。只要 timestamp 仍然跟 before_stamp 相等，那么 write_stamp 更新的时候就不用担心有其他 event 打断它来导致竞争。event 的时间差也是在 这个时候计算出来的。如果 ADD_STAMP_FORCE flag 置位了，意味着此 event 打断了另一个 event，也就需要一个绝对时间戳了。否则的话，就可以根据 write_stamp 和读出的 clock 值来计算出时间差并写入 delta。如果 before_stamp 同 read clock (ts) 不相等，这就意味着在我这个 event 刚刚分配好空间（更新了 write_tail）之后有另一个 event 插入进来并且更新了 before_stamp 和 write_stamp。由于没什么方法能知道这是什么时候发生的事情，必须假设这是在 write_stamp 更新之前发生的。为了解决这个问题，就需要使用 cmxchg() 来重读一次 write_stamp。假如 write_stamp 比上次读到的 before_stamp 要小，那么我们就得更新一下。如果 write_stamp 大于等于上次读出的 before_stamp，或者 cmxchg() 失败了，那么什么都不需要做了。这是因为这种情况代表此 event 在更新了 write_stamp 之后有另一个 event 发生了，并且它接管了 write_stamp 来确保它正确。

如果在获取时间戳之后、分配 ring buffer 空间之前没有被打断的话，上述算法就够了。不过如果某个 event 在分配空间之前被打断了呢？

The case of the interrupted event before allocating storage

这种情况是指在第一次读取 write_tail 之后、在 ring buffer 中分配空间之前，发生了一个中断事件打断了这个过程。此时没有什么数据是可信的。需要做一些工作来回到已知状态。

after = local_read(write_stamp);
ts = clock();

因为此 event 已经被打断了，并且嵌套调用的 event 也记录到 ring buffer 了，那么之前读出的 clock (ts) 值也就没有用了。此外，因为这个过程中是一个 event 打断了另一个 event 的处理，那么前者就需要确认 write_stamp 就是 ring buffer 中最后一个 event 的时间戳。这样我们就重读一下 clock 和 write_stamp 就能确定出当前具体状态。

if (write == local_read(write_tail) && after < ts) {
  delta = ts - after;
  local_cmpxchg(write_stamp, after, ts);

上面的代码后来发现包含一个小 bug。作者期待有人提出 patch 来正确修复它。首次提交 kernel patch 的开发者可以阅读这里（https://www.kernel.org/doc/html/latest/process/submitting-patches.html ）来了解如何给 kernel 提 patch。

如果 write_tail 同在为这个 event 分配空间时 local_add_return() 返回的值相等，那么就说明在分配空间和重读 write_stamp 之后没有发生嵌套 event。这意味着此 event 就是 ring buffer 里的最后一个 event 了，write_stamp 需要按它来设置。这里只有在 write_stamp 没有变动过的情况下，才会用一个 cmxchg() 来更新它。如果是在读取了 write_stamp 之后才发生的嵌套 event 中断，那么就说明这个 event 就是 ring buffer 里的最后一个 event，这样就不需要更新 write_stamp（cmpxchg()会失败，什么都不需要做）。这里可以很安全的计算出时间差，因为可以确定 write_stamp 就是来自这个 event 分配空间之前保存下来的那个 event。

} else {
    delta = 0;
}

如果 local_add_return 返回值 跟 write_tail 不同，意味着在分配空间和重读 write_tail 之间发生了一次 event。这样一来，此 event　就是在两个发生嵌套 event 的中断之间记录下来的。一次中断是在分配空间之前，另一次是在分配空间之后。因为现在没有方法能知道应该用哪个时间戳来计算时间差了，我们别无选择，只好沿用之前的做法，直接把时间差设置为 0。不过这已经是我们能选择的最好方案了。假如这个 event 是夹在两组 event 之间，那么它的时间戳其实并不重要了，因为已经让人们看到它是在两组嵌套 event 之间发生的了。

 

[An event sandwiched between interrupts]

人们会问，这是不是意味着上面的代码都太多余了，其实可以在这种 event 开始处理之后、分配空间之前发生的其他 event，直接使用 0 作为时间差就好了。我这样做的主要原因是这种情况并不罕见。我在跑 hackbench 采集了几轮 trace 的时候看到这种情况还是发生了几次。用 0 来作为时间差还是有缺点的，如果在中断中记录的 event 碰巧是在 interrupt 的最开始，并且 interrupt 本身在 return 之前运行了一段时间，那么拿 0 作为时间差就会让人们误以为这个中断的处理时间非常短。

不过，这是不是说任何把时间差填为 0 的做法都是不好的呢？确实是这样的。不过在存储之前、之后被两个不同的中断打断的情况是极少发生的。当然这不是说不可能发生，不过我们确实没有什么可以做的了。在对一些 hackbench 进行 trace 之后，我是没有碰到一次这种情况。我对这部分代码进行验证的唯一方式就是人为地在一个"fake" context 下插入 event，看这个算法是否能正常处理。这样一来，这个问题终于被解决了，不过只是在 64 位系统上。针对 32 位系统还有其他一些难题需要解决。希望了解细节的开发者可以读一下这篇额外文章（https://lwn.net/Articles/831892/ ）。

Conclusion

过去几年中我一直担心 ftrace ring-buffer 里的 event 永远没法拥有一个正确的时间戳，担心这会是一个图灵机无法解决的问题。不过在我困扰于这个 0 时间差的现象多年后，我认识到我只有两种方法来让我自己舒服，要么证明这是一个不可能的任务然后夹着尾巴逃走，要么找到一个可行的方案。前者不是一个可以接受的选项，因为我也知道只要施加一些限制条件的话，不可能的任务也会有可能的解决方案。比如说，我们仍然遗留了一个使用 0 作为时间差的分支，不过这个分支非常罕见，并且只影响单个 event，这样就不需要再继续纠结了。我在这个过程中看到最有趣的一点，是这个最终方案是我所有尝试过的方案中最简单的一个。这也并不出意外，不是吗？许多问题一直没有解决就是因为人们总是倾向于把方案复杂化。这个问题在我调试那个相关问题的时候就意识到可以不用考虑的那么极端，这样一切都顺其自然地解决了。

全文完
LWN 文章遵循 CC BY-SA 4.0 许可协议。

欢迎分享、转载及基于现有协议再创作～

长按下面二维码关注，关注 LWN 深度文章以及开源社区的各种新近言论～