带有usbmon和ftrace的可靠Linux内核时间戳(或其调整)? [英] Reliable Linux kernel timestamps (or adjustment thereof) with both usbmon and ftrace?
问题描述
我正在尝试检查一个利用usb的内核模块，因此我正在使用 trace_printk 从模块本身向 ftrace 写入一条消息.然后我想检查一下之后什么时候USB Bulk Out URB Submit在系统中出现.
I'm trying to inspect a kernel module that utilizes usb, and so from the module itself I'm writing a message to ftrace using trace_printk; and then I wanted to inspect when does a USB Bulk Out URB Submit appear in the system after that.
问题是，在我的Ubuntu Lucid 11.04(内核2.6.38-16)上， ftrace local 和 global 个时钟>-尽管它们的分辨率与usbmon的时间戳相同(微秒)，但是它们的值却有很大差异.
The problem is that on my Ubuntu Lucid 11.04 (kernel 2.6.38-16), there are only local and global clocks in ftrace - and although their resolution is the same (microseconds) as the timestamps by usbmon, their values differ significantly.
所以不知道更好(因为我在其他地方找不到这个话题)，我所做的就是尝试使用 usbmon 将 usbmon 重定向到 trace_marker >猫:
So not knowing any better (as I couldn't find anywhere else talking about this), what I did was attempt to redirect usbmon to trace_marker, using cat:
# ... 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 读取时，我得到了带有问题时间戳的日志(请参见下文).所以我想知道的是:
... and then, when I read from /sys/kernel/debug/tracing/trace, I get a log with problematic timestamps (see below). So what I'd like to know is:
- 是否可以使
usbmon的消息直接显示在/debug/tracing/trace中，而不是在/debug/usb/usbmon/中显示2u?(不是我能看到的，但我想确认这一点) - 如果没有，是否有更好的方法直接"重定向
/sys/kernel/debug/usb/usbmon/2u的输出，而没有cat <的任何可能的开销/缓冲问题/code>和/或shell重定向? - 如果没有，是否存在某种算法，可以在其中使用额外的
usbmon时间戳，以某种方式纠正"这些事件在内核时间戳域中的位置?(请参见下面的示例)
- Is there a way to make
usbmonhave it's messages appear directly in/debug/tracing/trace, instead of in/debug/usb/usbmon/2u? (not that I can see, but I'd like to have this confirmed) - If not, is there a better way to "directly" redirect output of
/sys/kernel/debug/usb/usbmon/2uwithout any possible overhead/buffering issues ofcatand/or shell redirection? - If not, is there some sort of an algorithm, where I could use the extra
usbmontimestamp, to somehow "correct" the position of these events in the kernel timestamp domain? (see example below)
这是我得到的/sys/kernel/debug/tracing/trace 日志的简短示例片段:
Here is a brief example snippet of a /sys/kernel/debug/tracing/trace log I got:
<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)；秒和微秒部分都不匹配.为了让您更容易理解，以下是相同的代码段，仅保留了时间信息:
So when the kernel timestamp is 44989.404202, the usbmon timestamp is 3237.249791 (= 3237249791/1e6); neither the seconds nor the microseconds part match. To make it a bit easier on the eyes, here's the same snippet with only time information remaining:
(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！现在信任谁?！
So judging by the kernel timestamps, 32 μs expired between event (3) and event (4) - but judging by the usbmon timestamps, 348 μs expired between the same events! Whom to trust now?!
现在，如果我们假设 usbmon 时间戳对于这些消息更正确，假设它们在结束进入 ftrace 缓冲区之前被打印"开始-我们可以假设第一个USB消息(3)可能是在执行(1)之后立即安排的，但是有先于之作-因此第二个USB消息(4)触发了打印输出"(或更确切地说，是进入")(3)和(4)都在 ftrace 缓冲区中(这就是为什么它们的内核时间戳如此紧凑的原因?)
Now, if we assume that the usbmon timestamps are more correct for those messages, given they got "printed" before they ended up in the ftrace buffer to begin with - we could assume that the first usb message (3) may have been scheduled right after (1) executed, but something preempted it - and so the second USB message (4) triggered the "printout" (or rather, "entry") of both (3) and (4) in the ftrace buffer (which is why their kernel timestamps are so clcse together?)
因此，如果我假设(4)是更正确的，我可以尝试将(3)推回348μs:
So, if I assume (4) is the more correct one, I can try push (3) back for 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事件的位置...
... and that sort of looks better (also USB now fires 282 μs, 316 μs, and 44 μs after MYF) - for first and second MYF/USB pairs (if that is indeed how they behave); but then the third step doesn't really match, and so on... Cannot really think of an algorithm to help me adjust the USB events position according to the data in the usbmon timestamp...
推荐答案
虽然将 usbmon 输出重定向到 ftrace 的最佳方法仍然是一个悬而未决的问题，但我从这个线程中得到了关于关联它们的时间戳的答案:
While the best approach for redirecting usbmon output to ftrace is still an open question, I got an answer about correlating their timestamps from this thread:
同时使用usbmon和ftrace吗?[linux-usb邮件列表]
您可以拨打以下电话子例程以获取usbmon样式的时间戳记值，然后可以将其设置为添加到ftrace消息中或简单地打印在内核日志中:
You can call the following subroutine to get a usbmon-style timestamp value, which can then be added to an ftrace message or simply printed in the kernel log:
#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());
这篇关于带有usbmon和ftrace的可靠Linux内核时间戳(或其调整)?的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
