Documentation/admin-guide/dynamic-debug-howto.rst

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