Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 1 | |
| 2 | Introduction |
| 3 | ============ |
| 4 | |
| 5 | This document describes how to use the dynamic debug (ddebug) feature. |
| 6 | |
| 7 | Dynamic debug is designed to allow you to dynamically enable/disable kernel |
| 8 | code to obtain additional kernel information. Currently, if |
Jonathan Corbet | 9cad796 | 2011-03-25 10:42:17 -0600 | [diff] [blame] | 9 | CONFIG_DYNAMIC_DEBUG is set, then all pr_debug()/dev_dbg() calls can be |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 10 | dynamically enabled per-callsite. |
| 11 | |
| 12 | Dynamic debug has even more useful features: |
| 13 | |
| 14 | * Simple query language allows turning on and off debugging statements by |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 15 | matching any combination of 0 or 1 of: |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 16 | |
| 17 | - source filename |
| 18 | - function name |
| 19 | - line number (including ranges of line numbers) |
| 20 | - module name |
| 21 | - format string |
| 22 | |
| 23 | * Provides a debugfs control file: <debugfs>/dynamic_debug/control which can be |
| 24 | read to display the complete list of known debug statements, to help guide you |
| 25 | |
| 26 | Controlling dynamic debug Behaviour |
Thomas Renninger | a648ec0 | 2010-08-06 16:11:02 +0200 | [diff] [blame] | 27 | =================================== |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 28 | |
Jonathan Corbet | 9cad796 | 2011-03-25 10:42:17 -0600 | [diff] [blame] | 29 | The behaviour of pr_debug()/dev_dbg()s are controlled via writing to a |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 30 | control file in the 'debugfs' filesystem. Thus, you must first mount the debugfs |
| 31 | filesystem, in order to make use of this feature. Subsequently, we refer to the |
| 32 | control file as: <debugfs>/dynamic_debug/control. For example, if you want to |
| 33 | enable printing from source file 'svcsock.c', line 1603 you simply do: |
| 34 | |
| 35 | nullarbor:~ # echo 'file svcsock.c line 1603 +p' > |
| 36 | <debugfs>/dynamic_debug/control |
| 37 | |
| 38 | If you make a mistake with the syntax, the write will fail thus: |
| 39 | |
| 40 | nullarbor:~ # echo 'file svcsock.c wtf 1 +p' > |
| 41 | <debugfs>/dynamic_debug/control |
| 42 | -bash: echo: write error: Invalid argument |
| 43 | |
| 44 | Viewing Dynamic Debug Behaviour |
| 45 | =========================== |
| 46 | |
| 47 | You can view the currently configured behaviour of all the debug statements |
| 48 | via: |
| 49 | |
| 50 | nullarbor:~ # cat <debugfs>/dynamic_debug/control |
| 51 | # filename:lineno [module]function flags format |
Greg Banks | 9898abb | 2009-02-06 12:54:26 +1100 | [diff] [blame] | 52 | /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:323 [svcxprt_rdma]svc_rdma_cleanup - "SVCRDMA Module Removed, deregister RPC RDMA transport\012" |
| 53 | /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init - "\011max_inline : %d\012" |
| 54 | /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init - "\011sq_depth : %d\012" |
| 55 | /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init - "\011max_requests : %d\012" |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 56 | ... |
| 57 | |
| 58 | |
| 59 | You can also apply standard Unix text manipulation filters to this |
| 60 | data, e.g. |
| 61 | |
| 62 | nullarbor:~ # grep -i rdma <debugfs>/dynamic_debug/control | wc -l |
| 63 | 62 |
| 64 | |
| 65 | nullarbor:~ # grep -i tcp <debugfs>/dynamic_debug/control | wc -l |
| 66 | 42 |
| 67 | |
| 68 | Note in particular that the third column shows the enabled behaviour |
| 69 | flags for each debug statement callsite (see below for definitions of the |
| 70 | flags). The default value, no extra behaviour enabled, is "-". So |
| 71 | you can view all the debug statement callsites with any non-default flags: |
| 72 | |
| 73 | nullarbor:~ # awk '$3 != "-"' <debugfs>/dynamic_debug/control |
| 74 | # filename:lineno [module]function flags format |
Greg Banks | 9898abb | 2009-02-06 12:54:26 +1100 | [diff] [blame] | 75 | /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svcsock.c:1603 [sunrpc]svc_send p "svc_process: st_sendto returned %d\012" |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 76 | |
| 77 | |
| 78 | Command Language Reference |
| 79 | ========================== |
| 80 | |
| 81 | At the lexical level, a command comprises a sequence of words separated |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 82 | by spaces or tabs. So these are all equivalent: |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 83 | |
| 84 | nullarbor:~ # echo -c 'file svcsock.c line 1603 +p' > |
| 85 | <debugfs>/dynamic_debug/control |
| 86 | nullarbor:~ # echo -c ' file svcsock.c line 1603 +p ' > |
| 87 | <debugfs>/dynamic_debug/control |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 88 | nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' > |
| 89 | <debugfs>/dynamic_debug/control |
| 90 | |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 91 | Command submissions are bounded by a write() system call. |
| 92 | Multiple commands can be written together, separated by ';' or '\n'. |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 93 | |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 94 | ~# echo "func pnpacpi_get_resources +p; func pnp_assign_mem +p" \ |
| 95 | > <debugfs>/dynamic_debug/control |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 96 | |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 97 | If your query set is big, you can batch them too: |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 98 | |
Jim Cromie | 85f7f6c | 2011-12-19 17:13:21 -0500 | [diff] [blame] | 99 | ~# cat query-batch-file > <debugfs>/dynamic_debug/control |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 100 | |
| 101 | At the syntactical level, a command comprises a sequence of match |
| 102 | specifications, followed by a flags change specification. |
| 103 | |
| 104 | command ::= match-spec* flags-spec |
| 105 | |
| 106 | The match-spec's are used to choose a subset of the known dprintk() |
| 107 | callsites to which to apply the flags-spec. Think of them as a query |
| 108 | with implicit ANDs between each pair. Note that an empty list of |
| 109 | match-specs is possible, but is not very useful because it will not |
| 110 | match any debug statement callsites. |
| 111 | |
| 112 | A match specification comprises a keyword, which controls the attribute |
| 113 | of the callsite to be compared, and a value to compare against. Possible |
| 114 | keywords are: |
| 115 | |
| 116 | match-spec ::= 'func' string | |
| 117 | 'file' string | |
| 118 | 'module' string | |
| 119 | 'format' string | |
| 120 | 'line' line-range |
| 121 | |
| 122 | line-range ::= lineno | |
| 123 | '-'lineno | |
| 124 | lineno'-' | |
| 125 | lineno'-'lineno |
| 126 | // Note: line-range cannot contain space, e.g. |
| 127 | // "1-30" is valid range but "1 - 30" is not. |
| 128 | |
| 129 | lineno ::= unsigned-int |
| 130 | |
| 131 | The meanings of each keyword are: |
| 132 | |
| 133 | func |
| 134 | The given string is compared against the function name |
| 135 | of each callsite. Example: |
| 136 | |
| 137 | func svc_tcp_accept |
| 138 | |
| 139 | file |
Jim Cromie | 2b67831 | 2011-12-19 17:13:12 -0500 | [diff] [blame] | 140 | The given string is compared against either the full pathname, the |
| 141 | src-root relative pathname, or the basename of the source file of |
| 142 | each callsite. Examples: |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 143 | |
| 144 | file svcsock.c |
Jim Cromie | 2b67831 | 2011-12-19 17:13:12 -0500 | [diff] [blame] | 145 | file kernel/freezer.c |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 146 | file /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svcsock.c |
| 147 | |
| 148 | module |
| 149 | The given string is compared against the module name |
| 150 | of each callsite. The module name is the string as |
| 151 | seen in "lsmod", i.e. without the directory or the .ko |
| 152 | suffix and with '-' changed to '_'. Examples: |
| 153 | |
| 154 | module sunrpc |
| 155 | module nfsd |
| 156 | |
| 157 | format |
| 158 | The given string is searched for in the dynamic debug format |
| 159 | string. Note that the string does not need to match the |
| 160 | entire format, only some part. Whitespace and other |
| 161 | special characters can be escaped using C octal character |
| 162 | escape \ooo notation, e.g. the space character is \040. |
Greg Banks | 9898abb | 2009-02-06 12:54:26 +1100 | [diff] [blame] | 163 | Alternatively, the string can be enclosed in double quote |
| 164 | characters (") or single quote characters ('). |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 165 | Examples: |
| 166 | |
| 167 | format svcrdma: // many of the NFS/RDMA server dprintks |
| 168 | format readahead // some dprintks in the readahead cache |
Greg Banks | 9898abb | 2009-02-06 12:54:26 +1100 | [diff] [blame] | 169 | format nfsd:\040SETATTR // one way to match a format with whitespace |
| 170 | format "nfsd: SETATTR" // a neater way to match a format with whitespace |
| 171 | format 'nfsd: SETATTR' // yet another way to match a format with whitespace |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 172 | |
| 173 | line |
| 174 | The given line number or range of line numbers is compared |
| 175 | against the line number of each dprintk() callsite. A single |
| 176 | line number matches the callsite line number exactly. A |
| 177 | range of line numbers matches any callsite between the first |
| 178 | and last line number inclusive. An empty first number means |
| 179 | the first line in the file, an empty line number means the |
| 180 | last number in the file. Examples: |
| 181 | |
| 182 | line 1603 // exactly line 1603 |
| 183 | line 1600-1605 // the six lines from line 1600 to line 1605 |
| 184 | line -1605 // the 1605 lines from line 1 to line 1605 |
| 185 | line 1600- // all lines from line 1600 to the end of the file |
| 186 | |
| 187 | The flags specification comprises a change operation followed |
| 188 | by one or more flag characters. The change operation is one |
| 189 | of the characters: |
| 190 | |
| 191 | - |
| 192 | remove the given flags |
| 193 | |
| 194 | + |
| 195 | add the given flags |
| 196 | |
| 197 | = |
| 198 | set the flags to the given flags |
| 199 | |
| 200 | The flags are: |
| 201 | |
Bart Van Assche | 8ba6ebf5 | 2011-01-23 17:17:24 +0100 | [diff] [blame] | 202 | f |
| 203 | Include the function name in the printed message |
| 204 | l |
| 205 | Include line number in the printed message |
| 206 | m |
| 207 | Include module name in the printed message |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 208 | p |
| 209 | Causes a printk() message to be emitted to dmesg |
Bart Van Assche | 8ba6ebf5 | 2011-01-23 17:17:24 +0100 | [diff] [blame] | 210 | t |
| 211 | Include thread ID in messages not generated from interrupt context |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 212 | |
Bart Van Assche | 8ba6ebf5 | 2011-01-23 17:17:24 +0100 | [diff] [blame] | 213 | Note the regexp ^[-+=][flmpt]+$ matches a flags specification. |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 214 | Note also that there is no convenient syntax to remove all |
Bart Van Assche | 8ba6ebf5 | 2011-01-23 17:17:24 +0100 | [diff] [blame] | 215 | the flags at once, you need to use "-flmpt". |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 216 | |
Thomas Renninger | a648ec0 | 2010-08-06 16:11:02 +0200 | [diff] [blame] | 217 | |
| 218 | Debug messages during boot process |
| 219 | ================================== |
| 220 | |
| 221 | To be able to activate debug messages during the boot process, |
| 222 | even before userspace and debugfs exists, use the boot parameter: |
| 223 | ddebug_query="QUERY" |
| 224 | |
| 225 | QUERY follows the syntax described above, but must not exceed 1023 |
| 226 | characters. The enablement of debug messages is done as an arch_initcall. |
| 227 | Thus you can enable debug messages in all code processed after this |
| 228 | arch_initcall via this boot parameter. |
| 229 | On an x86 system for example ACPI enablement is a subsys_initcall and |
| 230 | ddebug_query="file ec.c +p" |
| 231 | will show early Embedded Controller transactions during ACPI setup if |
| 232 | your machine (typically a laptop) has an Embedded Controller. |
| 233 | PCI (or other devices) initialization also is a hot candidate for using |
| 234 | this boot parameter for debugging purposes. |
| 235 | |
| 236 | |
Jason Baron | 86151fd | 2009-02-05 11:53:15 -0500 | [diff] [blame] | 237 | Examples |
| 238 | ======== |
| 239 | |
| 240 | // enable the message at line 1603 of file svcsock.c |
| 241 | nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' > |
| 242 | <debugfs>/dynamic_debug/control |
| 243 | |
| 244 | // enable all the messages in file svcsock.c |
| 245 | nullarbor:~ # echo -n 'file svcsock.c +p' > |
| 246 | <debugfs>/dynamic_debug/control |
| 247 | |
| 248 | // enable all the messages in the NFS server module |
| 249 | nullarbor:~ # echo -n 'module nfsd +p' > |
| 250 | <debugfs>/dynamic_debug/control |
| 251 | |
| 252 | // enable all 12 messages in the function svc_process() |
| 253 | nullarbor:~ # echo -n 'func svc_process +p' > |
| 254 | <debugfs>/dynamic_debug/control |
| 255 | |
| 256 | // disable all 12 messages in the function svc_process() |
| 257 | nullarbor:~ # echo -n 'func svc_process -p' > |
| 258 | <debugfs>/dynamic_debug/control |
Greg Banks | 9898abb | 2009-02-06 12:54:26 +1100 | [diff] [blame] | 259 | |
| 260 | // enable messages for NFS calls READ, READLINK, READDIR and READDIR+. |
| 261 | nullarbor:~ # echo -n 'format "nfsd: READ" +p' > |
| 262 | <debugfs>/dynamic_debug/control |