3

I have been analysing how a Linux USB driver works using two disparate methods:

  1. examining the output of usbmon, which is a hex dump-ish view of what's being sent "on the wire".
  2. adding printk() statements to the kernel driver module source and reloading it into the kernel.

The output of these methods is available to me through cat /sys/kernel/debug/usb/usbmon/1u and cat /var/log/kern.log respectively.

What I would now like to now do is merge these two files in real-time, so I can see the printk() logging messages I have inserted into the kernel driver interleaved with the lines of hex being sent across the wire. For example, I might put a printk() statement at the beginning and end of a piece of driver code that I know sends USB data, and I want to be able to view the hex (from usbmon that got sent in between, e.g.

Entering function sendImportantUSBData() // from driver code printk()
0a ff bbbb ac 0993 b3332 // from usbmon log
Exiting function sendImportantUSBData() // from driver code printk()

I know tail can show the last n lines of a single file. I also know that the tool multitail can do some merging, though I didn't see any relevant details regarding timing sensitivity and what effect it has on merge line order accuracy. Is there an appropriate tool for what I have described that either a) does accurate merging of time-sensitive logs or b) allows one to specify a relatively small time interval for when merging should be done? In the latter case, I can probably insert sleep statements into the driver code at critical points to make sure the merging tool has time to read my printk() output before the driver moves onto the next USB transaction which would generate further hex from usbmon.

Bryce Thomas
  • 151
  • multitail has few relevant flags: --mergeall, and -ts As for enforcing time coherence, I've done it once, but it had to be done by every log line having a timestamp, and then wrote an awk script to rearrange the entries to be sorted by time. That's nowhere near real-time. The lesson learned on that one was that the timestamps had to be generated by the program generating them, and not the logger program, as they tend to be heavily buffered, which demolishes any notion of decent timestamping. – Marcin Sep 06 '12 at 13:59

3 Answers3

4

How about tail -F /sys/kernel/debug/usb/usbmon/1u /var/log/kern.log ? That will 'follow' the output of both files and print a short header when output of every other file is shown.

jippie
  • 14,086
  • does this deal with the timing issue or will tail be doing "batch" reads of each file (e.g. once a second) and hence the temporal order of individual lines could end up broken? – Bryce Thomas Aug 05 '12 at 13:34
  • It is line buffered, meaning that it will always print until the next end of line. It triggers on file changes. – jippie Nov 05 '12 at 20:51
2

Too easy if you don't want extensive programming,

Suppose you're mixing from log1 and log2, resulting in log:

Monitor log1 in background, and append changes to log tail -f log1 >> log &

Start another process monitoring on log2 tail -f log2 >> log &

To testify, try

echo ok1 >> log1; echo ok2 >> log2

Now if you check log, you will get

ok1

ok2

Community
  • 1
daisy
  • 54,555
0

even i was looking for this example.. I'v used this in a different purpose and happy with the result. I have redirected the output to a file like this: tail -F /sys/kernel/debug/usb/usbmon/1u /var/log/kern.log >> tail.output and thrice a second i'm getting merged output of two different real-time logs. thnx a lot jippie :-)

Maniv
  • 1