| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 1 | In-kernel memory-mapped I/O tracing | 
|  | 2 |  | 
|  | 3 |  | 
|  | 4 | Home page and links to optional user space tools: | 
|  | 5 |  | 
|  | 6 | http://nouveau.freedesktop.org/wiki/MmioTrace | 
|  | 7 |  | 
|  | 8 | MMIO tracing was originally developed by Intel around 2003 for their Fault | 
|  | 9 | Injection Test Harness. In Dec 2006 - Jan 2007, using the code from Intel, | 
|  | 10 | Jeff Muizelaar created a tool for tracing MMIO accesses with the Nouveau | 
|  | 11 | project in mind. Since then many people have contributed. | 
|  | 12 |  | 
|  | 13 | Mmiotrace was built for reverse engineering any memory-mapped IO device with | 
|  | 14 | the Nouveau project as the first real user. Only x86 and x86_64 architectures | 
|  | 15 | are supported. | 
|  | 16 |  | 
|  | 17 | Out-of-tree mmiotrace was originally modified for mainline inclusion and | 
|  | 18 | ftrace framework by Pekka Paalanen <pq@iki.fi>. | 
|  | 19 |  | 
|  | 20 |  | 
|  | 21 | Preparation | 
|  | 22 | ----------- | 
|  | 23 |  | 
|  | 24 | Mmiotrace feature is compiled in by the CONFIG_MMIOTRACE option. Tracing is | 
|  | 25 | disabled by default, so it is safe to have this set to yes. SMP systems are | 
|  | 26 | supported, but tracing is unreliable and may miss events if more than one CPU | 
|  | 27 | is on-line, therefore mmiotrace takes all but one CPU off-line during run-time | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 28 | activation. You can re-enable CPUs by hand, but you have been warned, there | 
|  | 29 | is no way to automatically detect if you are losing events due to CPUs racing. | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 30 |  | 
|  | 31 |  | 
|  | 32 | Usage Quick Reference | 
|  | 33 | --------------------- | 
|  | 34 |  | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 35 | $ mount -t debugfs debugfs /sys/kernel/debug | 
|  | 36 | $ echo mmiotrace > /sys/kernel/debug/tracing/current_tracer | 
|  | 37 | $ cat /sys/kernel/debug/tracing/trace_pipe > mydump.txt & | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 38 | Start X or whatever. | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 39 | $ echo "X is up" > /sys/kernel/debug/tracing/trace_marker | 
|  | 40 | $ echo nop > /sys/kernel/debug/tracing/current_tracer | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 41 | Check for lost events. | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 42 |  | 
|  | 43 |  | 
|  | 44 | Usage | 
|  | 45 | ----- | 
|  | 46 |  | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 47 | Make sure debugfs is mounted to /sys/kernel/debug. | 
|  | 48 | If not (requires root privileges): | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 49 | $ mount -t debugfs debugfs /sys/kernel/debug | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 50 |  | 
|  | 51 | Check that the driver you are about to trace is not loaded. | 
|  | 52 |  | 
|  | 53 | Activate mmiotrace (requires root privileges): | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 54 | $ echo mmiotrace > /sys/kernel/debug/tracing/current_tracer | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 55 |  | 
|  | 56 | Start storing the trace: | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 57 | $ cat /sys/kernel/debug/tracing/trace_pipe > mydump.txt & | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 58 | The 'cat' process should stay running (sleeping) in the background. | 
|  | 59 |  | 
|  | 60 | Load the driver you want to trace and use it. Mmiotrace will only catch MMIO | 
|  | 61 | accesses to areas that are ioremapped while mmiotrace is active. | 
|  | 62 |  | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 63 | During tracing you can place comments (markers) into the trace by | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 64 | $ echo "X is up" > /sys/kernel/debug/tracing/trace_marker | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 65 | This makes it easier to see which part of the (huge) trace corresponds to | 
|  | 66 | which action. It is recommended to place descriptive markers about what you | 
|  | 67 | do. | 
|  | 68 |  | 
|  | 69 | Shut down mmiotrace (requires root privileges): | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 70 | $ echo nop > /sys/kernel/debug/tracing/current_tracer | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 71 | The 'cat' process exits. If it does not, kill it by issuing 'fg' command and | 
|  | 72 | pressing ctrl+c. | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 73 |  | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 74 | Check that mmiotrace did not lose events due to a buffer filling up. Either | 
|  | 75 | $ grep -i lost mydump.txt | 
|  | 76 | which tells you exactly how many events were lost, or use | 
|  | 77 | $ dmesg | 
|  | 78 | to view your kernel log and look for "mmiotrace has lost events" warning. If | 
|  | 79 | events were lost, the trace is incomplete. You should enlarge the buffers and | 
|  | 80 | try again. Buffers are enlarged by first seeing how large the current buffers | 
|  | 81 | are: | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 82 | $ cat /sys/kernel/debug/tracing/buffer_size_kb | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 83 | gives you a number. Approximately double this number and write it back, for | 
|  | 84 | instance: | 
| GeunSik Lim | 156f5a7 | 2009-06-02 15:01:37 +0900 | [diff] [blame] | 85 | $ echo 128000 > /sys/kernel/debug/tracing/buffer_size_kb | 
| Pekka Paalanen | 6f6f394 | 2008-05-12 21:21:03 +0200 | [diff] [blame] | 86 | Then start again from the top. | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 87 |  | 
|  | 88 | If you are doing a trace for a driver project, e.g. Nouveau, you should also | 
|  | 89 | do the following before sending your results: | 
|  | 90 | $ lspci -vvv > lspci.txt | 
|  | 91 | $ dmesg > dmesg.txt | 
|  | 92 | $ tar zcf pciid-nick-mmiotrace.tar.gz mydump.txt lspci.txt dmesg.txt | 
|  | 93 | and then send the .tar.gz file. The trace compresses considerably. Replace | 
|  | 94 | "pciid" and "nick" with the PCI ID or model name of your piece of hardware | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 95 | under investigation and your nickname. | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 96 |  | 
|  | 97 |  | 
|  | 98 | How Mmiotrace Works | 
|  | 99 | ------------------- | 
|  | 100 |  | 
|  | 101 | Access to hardware IO-memory is gained by mapping addresses from PCI bus by | 
|  | 102 | calling one of the ioremap_*() functions. Mmiotrace is hooked into the | 
|  | 103 | __ioremap() function and gets called whenever a mapping is created. Mapping is | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 104 | an event that is recorded into the trace log. Note that ISA range mappings | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 105 | are not caught, since the mapping always exists and is returned directly. | 
|  | 106 |  | 
|  | 107 | MMIO accesses are recorded via page faults. Just before __ioremap() returns, | 
|  | 108 | the mapped pages are marked as not present. Any access to the pages causes a | 
|  | 109 | fault. The page fault handler calls mmiotrace to handle the fault. Mmiotrace | 
|  | 110 | marks the page present, sets TF flag to achieve single stepping and exits the | 
|  | 111 | fault handler. The instruction that faulted is executed and debug trap is | 
|  | 112 | entered. Here mmiotrace again marks the page as not present. The instruction | 
|  | 113 | is decoded to get the type of operation (read/write), data width and the value | 
|  | 114 | read or written. These are stored to the trace log. | 
|  | 115 |  | 
|  | 116 | Setting the page present in the page fault handler has a race condition on SMP | 
|  | 117 | machines. During the single stepping other CPUs may run freely on that page | 
|  | 118 | and events can be missed without a notice. Re-enabling other CPUs during | 
|  | 119 | tracing is discouraged. | 
|  | 120 |  | 
|  | 121 |  | 
|  | 122 | Trace Log Format | 
|  | 123 | ---------------- | 
|  | 124 |  | 
|  | 125 | The raw log is text and easily filtered with e.g. grep and awk. One record is | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 126 | one line in the log. A record starts with a keyword, followed by keyword- | 
|  | 127 | dependent arguments. Arguments are separated by a space, or continue until the | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 128 | end of line. The format for version 20070824 is as follows: | 
|  | 129 |  | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 130 | Explanation	Keyword	Space-separated arguments | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 131 | --------------------------------------------------------------------------- | 
|  | 132 |  | 
|  | 133 | read event	R	width, timestamp, map id, physical, value, PC, PID | 
|  | 134 | write event	W	width, timestamp, map id, physical, value, PC, PID | 
|  | 135 | ioremap event	MAP	timestamp, map id, physical, virtual, length, PC, PID | 
|  | 136 | iounmap event	UNMAP	timestamp, map id, PC, PID | 
|  | 137 | marker		MARK	timestamp, text | 
|  | 138 | version		VERSION	the string "20070824" | 
|  | 139 | info for reader	LSPCI	one line from lspci -v | 
| Randy Dunlap | 360b6e5 | 2009-12-18 15:16:56 -0800 | [diff] [blame] | 140 | PCI address map	PCIDEV	space-separated /proc/bus/pci/devices data | 
| Pekka Paalanen | c6c67c1 | 2008-05-12 21:20:59 +0200 | [diff] [blame] | 141 | unk. opcode	UNKNOWN	timestamp, map id, physical, data, PC, PID | 
|  | 142 |  | 
|  | 143 | Timestamp is in seconds with decimals. Physical is a PCI bus address, virtual | 
|  | 144 | is a kernel virtual address. Width is the data width in bytes and value is the | 
|  | 145 | data value. Map id is an arbitrary id number identifying the mapping that was | 
|  | 146 | used in an operation. PC is the program counter and PID is process id. PC is | 
|  | 147 | zero if it is not recorded. PID is always zero as tracing MMIO accesses | 
|  | 148 | originating in user space memory is not yet supported. | 
|  | 149 |  | 
|  | 150 | For instance, the following awk filter will pass all 32-bit writes that target | 
|  | 151 | physical addresses in the range [0xfb73ce40, 0xfb800000[ | 
|  | 152 |  | 
|  | 153 | $ awk '/W 4 / { adr=strtonum($5); if (adr >= 0xfb73ce40 && | 
|  | 154 | adr < 0xfb800000) print; }' | 
|  | 155 |  | 
|  | 156 |  | 
|  | 157 | Tools for Developers | 
|  | 158 | -------------------- | 
|  | 159 |  | 
|  | 160 | The user space tools include utilities for: | 
|  | 161 | - replacing numeric addresses and values with hardware register names | 
|  | 162 | - replaying MMIO logs, i.e., re-executing the recorded writes | 
|  | 163 |  | 
|  | 164 |  |