Reliable Linux kernel timestamps (or adjustment th

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 clcse 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...

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:

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

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;
}
For example,
pr_info("The usbmon time is: %u\n", usbmon_timestamp());