I am trying to test a kernel module that uses usb, and so from the module I am writing the ftrace message using trace_printk ; and then I wanted to check when after that it appears in the URB Submit USB USB drive.
The problem is that on my Ubuntu Lucid 11.04 (kernel 2.6.38-16) there is only a local and global clock in ftrace - and although their resolution is the same (microseconds) as timestamps by usbmon, their values vary significantly.
So, knowing nothing better (since I could not find anywhere else about this), I made an 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
... and then when I read from /sys/kernel/debug/tracing/trace , I get a log with problematic timestamps (see below). So I would like to know:
- Is there a way to make
usbmon so that messages appear directly in /debug/tracing/trace and not in /debug/usb/usbmon/2u ? (not what I can see, but I would like it to be confirmed) - If not, is there a better way to "redirect" output directly
/sys/kernel/debug/usb/usbmon/2u without any possible problems with excess resources / cat buffering and / or shell redirection? - If not, is there any algorithm in which I could use an additional
usbmon to somehow "fix" the position of these events in the kernel timestamp domain? (see example below)
Here is a brief snippet of the log example /sys/kernel/debug/tracing/trace that I received:
<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
Therefore, when the kernel timestamp is 44989.404202, the usbmon timestamp is 3237.249791 (= 3237249791 / 1e6); neither a second nor part of a microsecond match. To make it a little easier before our eyes, here is the same fragment with the remaining time information:
(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
Thus, judging by the kernel timestamps, 32 μs expired between events (3) and event (4), but judging by the usbmon marks, 348 μs expired between the same events! Who to trust now ?!
Now, if we assume that the usbmon more correct for these messages, since they got a “printout” before they finished working with the ftrace buffer to begin with, we could assume that the first usb (3) message might have been scheduled right after execution (1), but uploaded something - and therefore the second USB message (4) caused a “printout” (or rather, “write”) of both (3) and (4) in the ftrace buffer (therefore do their core timestamps stick together like that?)
So, if I assume that (4) is more correct, I can try pushing (3) back to 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 this view looks better (also USB now launches 282 μs, 316 μs and 44 μs after MYF) - for the first and second MYF / USB pairs (if this is really the way they behave); but then the third step actually does not match, and so on ... I can’t remember the algorithm that will help me adjust the position of the USB events according to the data in usbmon timestamp ...