使用 usbmon 和 ftrace 的可靠 Linux 内核时间戳（或其调整）？答案

【问题标题】：Reliable Linux kernel timestamps (or adjustment thereof) with both usbmon and ftrace?使用 usbmon 和 ftrace 的可靠 Linux 内核时间戳（或其调整）？
【发布时间】：2013-12-06 06:55:10
【问题描述】：

我正在尝试检查一个使用 USB 的内核模块，因此从模块本身我正在使用 trace_printk 向 ftrace 写一条消息；然后我想检查一下USB Bulk Out URB Submit什么时候出现在系统中。

问题在于，在我的 Ubuntu Lucid 11.04（内核 2.6.38-16）上，ftrace 中只有 local 和 global 时钟 - 尽管它们的分辨率与时间戳相同（微秒）通过 usbmon，它们的值有很大的不同。

所以不知道更好（因为我找不到其他地方谈论这个），我所做的是尝试使用cat 将usbmon 重定向到trace_marker：

# ... activate ftrace here ...
usbpid=$(sudo bash -c 'cat /sys/kernel/debug/usb/usbmon/2u > /sys/kernel/debug/tracing/trace_marker & echo $!')
sleep 3 # do test, etc.
sudo kill $usbpid
# ... deactivate ftrace here...

...然后，当我从/sys/kernel/debug/tracing/trace 读取时，我得到一个时间戳有问题的日志（见下文）。所以我想知道的是：

有没有办法让usbmon 的消息直接出现在/debug/tracing/trace 中，而不是/debug/usb/usbmon/2u 中？（我看不到，但我想确认一下）
如果没有，有没有更好的方法来“直接”重定向/sys/kernel/debug/usb/usbmon/2u 的输出，而不会出现cat 和/或shell 重定向的任何可能的开销/缓冲问题？
如果没有，是否有某种算法，我可以使用额外的usbmon 时间戳，以某种方式“纠正”这些事件在内核时间戳域中的位置？（见下面的例子）

这是我得到的/sys/kernel/debug/tracing/trace 日志的一个简短示例 sn-p：

      <idle>-0     [000] 44989.403572: my_kernel_function: 1 00 00 64 1 64 5
       <...>-29765 [000] 44989.403918: my_kernel_function: 1 00 00 64 2 128 2
       <...>-29787 [000] 44989.404202: 0: f1f47280 3237249791 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
       <...>-29787 [000] 44989.404234: 0: f1f47080 3237250139 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
      <idle>-0     [000] 44989.404358: my_kernel_function: 1 00 00 64 3 192 4
       <...>-29787 [000] 44989.404402: 0: f1f47c00 3237250515 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

所以当内核时间戳为 44989.404202 时，usbmon 时间戳为 3237.249791 (= 3237249791/1e6)；秒和微秒部分都不匹配。为了让眼睛更容易看，这里是相同的 sn-p，只剩下时间信息：

(1) 44989.403572 MYF  0
(2) 44989.403918 MYF  0.000346
(3) 44989.404202 USB  |           0          3237.249791  0
(4) 44989.404234 USB  |           0.000032   3237.250139  0.000348
(5) 44989.404358 MYF  0.000440    |                       |
(6) 44989.404402 USB              0.000168   3237.250515  0.000376

因此，从内核时间戳来看，事件 (3) 和事件 (4) 之间过期了 32 μs - 但根据 usbmon 时间戳判断，相同事件之间过期了 348 μs！现在该相信谁？！

现在，如果我们假设 usbmon 时间戳对于这些消息更正确，因为它们在结束于 ftrace 缓冲区之前已被“打印” - 我们可以假设第一条 usb 消息 ( 3) 可能已在 (1) 执行后立即安排，但有东西抢占了它 - 因此第二条 USB 消息 (4) 触发了 (3) 和 (4) 的“打印输出”（或者更确切地说，“输入”） ftrace 缓冲区（这就是为什么它们的内核时间戳如此接近的原因？）

所以，如果我假设 (4) 是更正确的，我可以尝试将 (3) 推回 348 μs：

(1) 44989.403572 MYF  0
(3) 44989.403854 USB  |           0          3237.249791  0
(2) 44989.403918 MYF  0.000346    |                       |
(4) 44989.404234 USB  |           0.000380   3237.250139  0.000348
(5) 44989.404358 MYF  0.000440    |                       |
(6) 44989.404402 USB              0.000168   3237.250515  0.000376

...而且那种看起来更好（USB 现在在 MYF 之后触发 282 μs、316 μs 和 44 μs） - 对于第一和第二个 MYF/USB 对（如果这确实是它们的行为方式）；但是第三步并没有真正匹配，依此类推……实在想不出一个算法来帮助我根据usbmon时间戳中的数据调整USB事件的位置……

【问题讨论】：

标签： debugging linux-kernel timestamp

【解决方案1】：

虽然将 usbmon 输出重定向到 ftrace 的最佳方法仍然是一个悬而未决的问题，但我从这个线程中得到了一个关于关联它们的时间戳的答案：

Using both usbmon and ftrace? [linux-usb mailing list]

你可以调用以下子程序来获取 usbmon 样式的时间戳值，然后可以添加到 ftrace 消息或简单地打印在内核日志中：
#include <linux/time.h>

static unsigned usbmon_timestamp(void)
{
  struct timeval tval;
  unsigned stamp;

  do_gettimeofday(&tval);
  stamp = tval.tv_sec & 0xFFF;
  stamp = stamp * 1000000 + tval.tv_usec;
  return stamp;
}
例如，
pr_info("The usbmon time is: %u\n", usbmon_timestamp());

【讨论】：