Hi all, Apologies for somewhat of a cross-post; I have already tried to ask about this here: Reliable Linux kernel timestamps (or adjustment thereof) with both usbmon and ftrace? http://stackoverflow.com/questions/20417897/reliable-linux-kernel-timestamps-or-adjustment-thereof-with-both-usbmon-and-ft ... but that question doesn't seem to attract much attention, so hope it's OK to try my luck here. I'll just copy paste that question verbatim below: /// 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. 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. 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... ... 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: * Is there a way to make `usbmon` have 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/2u` without any possible overhead/buffering issues of `cat` and/or shell redirection? * If not, is there some sort of an algorithm, where I could use the extra `usbmon` timestamp, to somehow "correct" the position of these events in the kernel timestamp domain? (see example below) ----- 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 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 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?! 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 close together?) 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 ... 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... /// That was the original posting - would anyone have answers to the questions above, or any suggestions on how I should proceed? Many thanks in advance, Cheers! -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
