Documentation/dynamic-debug-howto.txt

   1
   2 Introduction
   3 ============
   4
   5 This document describes how to use the dynamic debug (dyndbg) feature.
   6
   7 Dynamic debug is designed to allow you to dynamically enable/disable
   8 kernel code to obtain additional kernel information.  Currently, if
   9 CONFIG_DYNAMIC_DEBUG is set, then all pr_debug()/dev_dbg() calls can
  10 be dynamically enabled per-callsite.
  11
  12 Dynamic debug has even more useful features:
  13
  14  * Simple query language allows turning on and off debugging
  15    statements by matching any combination of 0 or 1 of:
  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
  24    which can be read to display the complete list of known debug
  25    statements, to help guide you
  26
  27 Controlling dynamic debug Behaviour
  28 ===================================
  29
  30 The behaviour of pr_debug()/dev_dbg()s are controlled via writing to a
  31 control file in the 'debugfs' filesystem. Thus, you must first mount
  32 the debugfs filesystem, in order to make use of this feature.
  33 Subsequently, we refer to the control file as:
  34 <debugfs>/dynamic_debug/control. For example, if you want to enable
  35 printing from source file 'svcsock.c', line 1603 you simply do:
  36
  37 nullarbor:~ # echo 'file svcsock.c line 1603 +p' >
  38                                 <debugfs>/dynamic_debug/control
  39
  40 If you make a mistake with the syntax, the write will fail thus:
  41
  42 nullarbor:~ # echo 'file svcsock.c wtf 1 +p' >
  43                                 <debugfs>/dynamic_debug/control
  44 -bash: echo: write error: Invalid argument
  45
  46 Viewing Dynamic Debug Behaviour
  47 ===========================
  48
  49 You can view the currently configured behaviour of all the debug
  50 statements via:
  51
  52 nullarbor:~ # cat <debugfs>/dynamic_debug/control
  53 # filename:lineno [module]function flags format
  54 /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"
  55 /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init =_ "\011max_inline       : %d\012"
  56 /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init =_ "\011sq_depth         : %d\012"
  57 /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init =_ "\011max_requests     : %d\012"
  58 ...
  59
  60
  61 You can also apply standard Unix text manipulation filters to this
  62 data, e.g.
  63
  64 nullarbor:~ # grep -i rdma <debugfs>/dynamic_debug/control  | wc -l
  65 62
  66
  67 nullarbor:~ # grep -i tcp <debugfs>/dynamic_debug/control | wc -l
  68 42
  69
  70 The third column shows the currently enabled flags for each debug
  71 statement callsite (see below for definitions of the flags).  The
  72 default value, with no flags enabled, is "=_".  So you can view all
  73 the debug statement callsites with any non-default flags:
  74
  75 nullarbor:~ # awk '$3 != "=_"' <debugfs>/dynamic_debug/control
  76 # filename:lineno [module]function flags format
  77 /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"
  78
  79
  80 Command Language Reference
  81 ==========================
  82
  83 At the lexical level, a command comprises a sequence of words separated
  84 by spaces or tabs.  So these are all equivalent:
  85
  86 nullarbor:~ # echo -c 'file svcsock.c line 1603 +p' >
  87                                 <debugfs>/dynamic_debug/control
  88 nullarbor:~ # echo -c '  file   svcsock.c     line  1603 +p  ' >
  89                                 <debugfs>/dynamic_debug/control
  90 nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
  91                                 <debugfs>/dynamic_debug/control
  92
  93 Command submissions are bounded by a write() system call.
  94 Multiple commands can be written together, separated by ';' or '\n'.
  95
  96   ~# echo "func pnpacpi_get_resources +p; func pnp_assign_mem +p" \
  97      > <debugfs>/dynamic_debug/control
  98
  99 If your query set is big, you can batch them too:
 100
 101   ~# cat query-batch-file > <debugfs>/dynamic_debug/control
 102
 103 At the syntactical level, a command comprises a sequence of match
 104 specifications, followed by a flags change specification.
 105
 106 command ::= match-spec* flags-spec
 107
 108 The match-spec's are used to choose a subset of the known pr_debug()
 109 callsites to which to apply the flags-spec.  Think of them as a query
 110 with implicit ANDs between each pair.  Note that an empty list of
 111 match-specs will select all debug statement callsites.
 112
 113 A match specification comprises a keyword, which controls the
 114 attribute of the callsite to be compared, and a value to compare
 115 against.  Possible keywords are:
 116
 117 match-spec ::= 'func' string |
 118                'file' string |
 119                'module' string |
 120                'format' string |
 121                'line' line-range
 122
 123 line-range ::= lineno |
 124                '-'lineno |
 125                lineno'-' |
 126                lineno'-'lineno
 127 // Note: line-range cannot contain space, e.g.
 128 // "1-30" is valid range but "1 - 30" is not.
 129
 130 lineno ::= unsigned-int
 131
 132 The meanings of each keyword are:
 133
 134 func
 135     The given string is compared against the function name
 136     of each callsite.  Example:
 137
 138     func svc_tcp_accept
 139
 140 file
 141     The given string is compared against either the full pathname, the
 142     src-root relative pathname, or the basename of the source file of
 143     each callsite.  Examples:
 144
 145     file svcsock.c
 146     file kernel/freezer.c
 147     file /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svcsock.c
 148
 149 module
 150     The given string is compared against the module name
 151     of each callsite.  The module name is the string as
 152     seen in "lsmod", i.e. without the directory or the .ko
 153     suffix and with '-' changed to '_'.  Examples:
 154
 155     module sunrpc
 156     module nfsd
 157
 158 format
 159     The given string is searched for in the dynamic debug format
 160     string.  Note that the string does not need to match the
 161     entire format, only some part.  Whitespace and other
 162     special characters can be escaped using C octal character
 163     escape \ooo notation, e.g. the space character is \040.
 164     Alternatively, the string can be enclosed in double quote
 165     characters (") or single quote characters (').
 166     Examples:
 167
 168     format svcrdma:         // many of the NFS/RDMA server pr_debugs
 169     format readahead        // some pr_debugs in the readahead cache
 170     format nfsd:\040SETATTR // one way to match a format with whitespace
 171     format "nfsd: SETATTR"  // a neater way to match a format with whitespace
 172     format 'nfsd: SETATTR'  // yet another way to match a format with whitespace
 173
 174 line
 175     The given line number or range of line numbers is compared
 176     against the line number of each pr_debug() callsite.  A single
 177     line number matches the callsite line number exactly.  A
 178     range of line numbers matches any callsite between the first
 179     and last line number inclusive.  An empty first number means
 180     the first line in the file, an empty line number means the
 181     last number in the file.  Examples:
 182
 183     line 1603       // exactly line 1603
 184     line 1600-1605  // the six lines from line 1600 to line 1605
 185     line -1605      // the 1605 lines from line 1 to line 1605
 186     line 1600-      // all lines from line 1600 to the end of the file
 187
 188 The flags specification comprises a change operation followed
 189 by one or more flag characters.  The change operation is one
 190 of the characters:
 191
 192   -    remove the given flags
 193   +    add the given flags
 194   =    set the flags to the given flags
 195
 196 The flags are:
 197
 198   p    enables the pr_debug() callsite.
 199   f    Include the function name in the printed message
 200   l    Include line number in the printed message
 201   m    Include module name in the printed message
 202   t    Include thread ID in messages not generated from interrupt context
 203   _    No flags are set. (Or'd with others on input)
 204
 205 For display, the flags are preceded by '='
 206 (mnemonic: what the flags are currently equal to).
 207
 208 Note the regexp ^[-+=][flmpt_]+$ matches a flags specification.
 209 To clear all flags at once, use "=_" or "-flmpt".
 210
 211
 212 Debug messages during Boot Process
 213 ==================================
 214
 215 To activate debug messages for core code and built-in modules during
 216 the boot process, even before userspace and debugfs exists, use
 217 dyndbg="QUERY", module.dyndbg="QUERY", or ddebug_query="QUERY"
 218 (ddebug_query is obsoleted by dyndbg, and deprecated).  QUERY follows
 219 the syntax described above, but must not exceed 1023 characters.  Your
 220 bootloader may impose lower limits.
 221
 222 These dyndbg params are processed just after the ddebug tables are
 223 processed, as part of the arch_initcall.  Thus you can enable debug
 224 messages in all code run after this arch_initcall via this boot
 225 parameter.
 226
 227 On an x86 system for example ACPI enablement is a subsys_initcall and
 228    dyndbg="file ec.c +p"
 229 will show early Embedded Controller transactions during ACPI setup if
 230 your machine (typically a laptop) has an Embedded Controller.
 231 PCI (or other devices) initialization also is a hot candidate for using
 232 this boot parameter for debugging purposes.
 233
 234 If foo module is not built-in, foo.dyndbg will still be processed at
 235 boot time, without effect, but will be reprocessed when module is
 236 loaded later.  dyndbg_query= and bare dyndbg= are only processed at
 237 boot.
 238
 239
 240 Debug Messages at Module Initialization Time
 241 ============================================
 242
 243 When "modprobe foo" is called, modprobe scans /proc/cmdline for
 244 foo.params, strips "foo.", and passes them to the kernel along with
 245 params given in modprobe args or /etc/modprob.d/*.conf files,
 246 in the following order:
 247
 248 1. # parameters given via /etc/modprobe.d/*.conf
 249    options foo dyndbg=+pt
 250    options foo dyndbg # defaults to +p
 251
 252 2. # foo.dyndbg as given in boot args, "foo." is stripped and passed
 253    foo.dyndbg=" func bar +p; func buz +mp"
 254
 255 3. # args to modprobe
 256    modprobe foo dyndbg==pmf # override previous settings
 257
 258 These dyndbg queries are applied in order, with last having final say.
 259 This allows boot args to override or modify those from /etc/modprobe.d
 260 (sensible, since 1 is system wide, 2 is kernel or boot specific), and
 261 modprobe args to override both.
 262
 263 In the foo.dyndbg="QUERY" form, the query must exclude "module foo".
 264 "foo" is extracted from the param-name, and applied to each query in
 265 "QUERY", and only 1 match-spec of each type is allowed.
 266
 267 The dyndbg option is a "fake" module parameter, which means:
 268
 269 - modules do not need to define it explicitly
 270 - every module gets it tacitly, whether they use pr_debug or not
 271 - it doesnt appear in /sys/module/$module/parameters/
 272   To see it, grep the control file, or inspect /proc/cmdline.
 273
 274 For CONFIG_DYNAMIC_DEBUG kernels, any settings given at boot-time (or
 275 enabled by -DDEBUG flag during compilation) can be disabled later via
 276 the sysfs interface if the debug messages are no longer needed:
 277
 278    echo "module module_name -p" > <debugfs>/dynamic_debug/control
 279
 280 Examples
 281 ========
 282
 283 // enable the message at line 1603 of file svcsock.c
 284 nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
 285                                 <debugfs>/dynamic_debug/control
 286
 287 // enable all the messages in file svcsock.c
 288 nullarbor:~ # echo -n 'file svcsock.c +p' >
 289                                 <debugfs>/dynamic_debug/control
 290
 291 // enable all the messages in the NFS server module
 292 nullarbor:~ # echo -n 'module nfsd +p' >
 293                                 <debugfs>/dynamic_debug/control
 294
 295 // enable all 12 messages in the function svc_process()
 296 nullarbor:~ # echo -n 'func svc_process +p' >
 297                                 <debugfs>/dynamic_debug/control
 298
 299 // disable all 12 messages in the function svc_process()
 300 nullarbor:~ # echo -n 'func svc_process -p' >
 301                                 <debugfs>/dynamic_debug/control
 302
 303 // enable messages for NFS calls READ, READLINK, READDIR and READDIR+.
 304 nullarbor:~ # echo -n 'format "nfsd: READ" +p' >
 305                                 <debugfs>/dynamic_debug/control
 306
 307 // enable all messages
 308 nullarbor:~ # echo -n '+p' > <debugfs>/dynamic_debug/control
 309
 310 // add module, function to all enabled messages
 311 nullarbor:~ # echo -n '+mf' > <debugfs>/dynamic_debug/control
 312
 313 // boot-args example, with newlines and comments for readability
 314 Kernel command line: ...
 315   // see whats going on in dyndbg=value processing
 316   dynamic_debug.verbose=1
 317   // enable pr_debugs in 2 builtins, #cmt is stripped
 318   dyndbg="module params +p #cmt ; module sys +p"
 319   // enable pr_debugs in 2 functions in a module loaded later
 320   pc87360.dyndbg="func pc87360_init_device +p; func pc87360_find +p"