Back to home page

OSCL-LXR

 
 

    


0001 Dynamic debug
0002 +++++++++++++
0003 
0004 
0005 Introduction
0006 ============
0007 
0008 This document describes how to use the dynamic debug (dyndbg) feature.
0009 
0010 Dynamic debug is designed to allow you to dynamically enable/disable
0011 kernel code to obtain additional kernel information.  Currently, if
0012 ``CONFIG_DYNAMIC_DEBUG`` is set, then all ``pr_debug()``/``dev_dbg()`` and
0013 ``print_hex_dump_debug()``/``print_hex_dump_bytes()`` calls can be dynamically
0014 enabled per-callsite.
0015 
0016 If you do not want to enable dynamic debug globally (i.e. in some embedded
0017 system), you may set ``CONFIG_DYNAMIC_DEBUG_CORE`` as basic support of dynamic
0018 debug and add ``ccflags := -DDYNAMIC_DEBUG_MODULE`` into the Makefile of any
0019 modules which you'd like to dynamically debug later.
0020 
0021 If ``CONFIG_DYNAMIC_DEBUG`` is not set, ``print_hex_dump_debug()`` is just
0022 shortcut for ``print_hex_dump(KERN_DEBUG)``.
0023 
0024 For ``print_hex_dump_debug()``/``print_hex_dump_bytes()``, format string is
0025 its ``prefix_str`` argument, if it is constant string; or ``hexdump``
0026 in case ``prefix_str`` is built dynamically.
0027 
0028 Dynamic debug has even more useful features:
0029 
0030  * Simple query language allows turning on and off debugging
0031    statements by matching any combination of 0 or 1 of:
0032 
0033    - source filename
0034    - function name
0035    - line number (including ranges of line numbers)
0036    - module name
0037    - format string
0038 
0039  * Provides a debugfs control file: ``<debugfs>/dynamic_debug/control``
0040    which can be read to display the complete list of known debug
0041    statements, to help guide you
0042 
0043 Controlling dynamic debug Behaviour
0044 ===================================
0045 
0046 The behaviour of ``pr_debug()``/``dev_dbg()`` are controlled via writing to a
0047 control file in the 'debugfs' filesystem. Thus, you must first mount
0048 the debugfs filesystem, in order to make use of this feature.
0049 Subsequently, we refer to the control file as:
0050 ``<debugfs>/dynamic_debug/control``. For example, if you want to enable
0051 printing from source file ``svcsock.c``, line 1603 you simply do::
0052 
0053   nullarbor:~ # echo 'file svcsock.c line 1603 +p' >
0054                                 <debugfs>/dynamic_debug/control
0055 
0056 If you make a mistake with the syntax, the write will fail thus::
0057 
0058   nullarbor:~ # echo 'file svcsock.c wtf 1 +p' >
0059                                 <debugfs>/dynamic_debug/control
0060   -bash: echo: write error: Invalid argument
0061 
0062 Note, for systems without 'debugfs' enabled, the control file can be
0063 found in ``/proc/dynamic_debug/control``.
0064 
0065 Viewing Dynamic Debug Behaviour
0066 ===============================
0067 
0068 You can view the currently configured behaviour of all the debug
0069 statements via::
0070 
0071   nullarbor:~ # cat <debugfs>/dynamic_debug/control
0072   # filename:lineno [module]function flags format
0073   net/sunrpc/svc_rdma.c:323 [svcxprt_rdma]svc_rdma_cleanup =_ "SVCRDMA Module Removed, deregister RPC RDMA transport\012"
0074   net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init =_ "\011max_inline       : %d\012"
0075   net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init =_ "\011sq_depth         : %d\012"
0076   net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init =_ "\011max_requests     : %d\012"
0077   ...
0078 
0079 
0080 You can also apply standard Unix text manipulation filters to this
0081 data, e.g.::
0082 
0083   nullarbor:~ # grep -i rdma <debugfs>/dynamic_debug/control  | wc -l
0084   62
0085 
0086   nullarbor:~ # grep -i tcp <debugfs>/dynamic_debug/control | wc -l
0087   42
0088 
0089 The third column shows the currently enabled flags for each debug
0090 statement callsite (see below for definitions of the flags).  The
0091 default value, with no flags enabled, is ``=_``.  So you can view all
0092 the debug statement callsites with any non-default flags::
0093 
0094   nullarbor:~ # awk '$3 != "=_"' <debugfs>/dynamic_debug/control
0095   # filename:lineno [module]function flags format
0096   net/sunrpc/svcsock.c:1603 [sunrpc]svc_send p "svc_process: st_sendto returned %d\012"
0097 
0098 Command Language Reference
0099 ==========================
0100 
0101 At the lexical level, a command comprises a sequence of words separated
0102 by spaces or tabs.  So these are all equivalent::
0103 
0104   nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
0105                                 <debugfs>/dynamic_debug/control
0106   nullarbor:~ # echo -n '  file   svcsock.c     line  1603 +p  ' >
0107                                 <debugfs>/dynamic_debug/control
0108   nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
0109                                 <debugfs>/dynamic_debug/control
0110 
0111 Command submissions are bounded by a write() system call.
0112 Multiple commands can be written together, separated by ``;`` or ``\n``::
0113 
0114   ~# echo "func pnpacpi_get_resources +p; func pnp_assign_mem +p" \
0115      > <debugfs>/dynamic_debug/control
0116 
0117 If your query set is big, you can batch them too::
0118 
0119   ~# cat query-batch-file > <debugfs>/dynamic_debug/control
0120 
0121 Another way is to use wildcards. The match rule supports ``*`` (matches
0122 zero or more characters) and ``?`` (matches exactly one character). For
0123 example, you can match all usb drivers::
0124 
0125   ~# echo "file drivers/usb/* +p" > <debugfs>/dynamic_debug/control
0126 
0127 At the syntactical level, a command comprises a sequence of match
0128 specifications, followed by a flags change specification::
0129 
0130   command ::= match-spec* flags-spec
0131 
0132 The match-spec's are used to choose a subset of the known pr_debug()
0133 callsites to which to apply the flags-spec.  Think of them as a query
0134 with implicit ANDs between each pair.  Note that an empty list of
0135 match-specs will select all debug statement callsites.
0136 
0137 A match specification comprises a keyword, which controls the
0138 attribute of the callsite to be compared, and a value to compare
0139 against.  Possible keywords are:::
0140 
0141   match-spec ::= 'func' string |
0142                  'file' string |
0143                  'module' string |
0144                  'format' string |
0145                  'line' line-range
0146 
0147   line-range ::= lineno |
0148                  '-'lineno |
0149                  lineno'-' |
0150                  lineno'-'lineno
0151 
0152   lineno ::= unsigned-int
0153 
0154 .. note::
0155 
0156   ``line-range`` cannot contain space, e.g.
0157   "1-30" is valid range but "1 - 30" is not.
0158 
0159 
0160 The meanings of each keyword are:
0161 
0162 func
0163     The given string is compared against the function name
0164     of each callsite.  Example::
0165 
0166         func svc_tcp_accept
0167         func *recv*             # in rfcomm, bluetooth, ping, tcp
0168 
0169 file
0170     The given string is compared against either the src-root relative
0171     pathname, or the basename of the source file of each callsite.
0172     Examples::
0173 
0174         file svcsock.c
0175         file kernel/freezer.c   # ie column 1 of control file
0176         file drivers/usb/*      # all callsites under it
0177         file inode.c:start_*    # parse :tail as a func (above)
0178         file inode.c:1-100      # parse :tail as a line-range (above)
0179 
0180 module
0181     The given string is compared against the module name
0182     of each callsite.  The module name is the string as
0183     seen in ``lsmod``, i.e. without the directory or the ``.ko``
0184     suffix and with ``-`` changed to ``_``.  Examples::
0185 
0186         module sunrpc
0187         module nfsd
0188         module drm*     # both drm, drm_kms_helper
0189 
0190 format
0191     The given string is searched for in the dynamic debug format
0192     string.  Note that the string does not need to match the
0193     entire format, only some part.  Whitespace and other
0194     special characters can be escaped using C octal character
0195     escape ``\ooo`` notation, e.g. the space character is ``\040``.
0196     Alternatively, the string can be enclosed in double quote
0197     characters (``"``) or single quote characters (``'``).
0198     Examples::
0199 
0200         format svcrdma:         // many of the NFS/RDMA server pr_debugs
0201         format readahead        // some pr_debugs in the readahead cache
0202         format nfsd:\040SETATTR // one way to match a format with whitespace
0203         format "nfsd: SETATTR"  // a neater way to match a format with whitespace
0204         format 'nfsd: SETATTR'  // yet another way to match a format with whitespace
0205 
0206 line
0207     The given line number or range of line numbers is compared
0208     against the line number of each ``pr_debug()`` callsite.  A single
0209     line number matches the callsite line number exactly.  A
0210     range of line numbers matches any callsite between the first
0211     and last line number inclusive.  An empty first number means
0212     the first line in the file, an empty last line number means the
0213     last line number in the file.  Examples::
0214 
0215         line 1603           // exactly line 1603
0216         line 1600-1605      // the six lines from line 1600 to line 1605
0217         line -1605          // the 1605 lines from line 1 to line 1605
0218         line 1600-          // all lines from line 1600 to the end of the file
0219 
0220 The flags specification comprises a change operation followed
0221 by one or more flag characters.  The change operation is one
0222 of the characters::
0223 
0224   -    remove the given flags
0225   +    add the given flags
0226   =    set the flags to the given flags
0227 
0228 The flags are::
0229 
0230   p    enables the pr_debug() callsite.
0231   f    Include the function name in the printed message
0232   l    Include line number in the printed message
0233   m    Include module name in the printed message
0234   t    Include thread ID in messages not generated from interrupt context
0235   _    No flags are set. (Or'd with others on input)
0236 
0237 For ``print_hex_dump_debug()`` and ``print_hex_dump_bytes()``, only ``p`` flag
0238 have meaning, other flags ignored.
0239 
0240 For display, the flags are preceded by ``=``
0241 (mnemonic: what the flags are currently equal to).
0242 
0243 Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
0244 To clear all flags at once, use ``=_`` or ``-flmpt``.
0245 
0246 
0247 Debug messages during Boot Process
0248 ==================================
0249 
0250 To activate debug messages for core code and built-in modules during
0251 the boot process, even before userspace and debugfs exists, use
0252 ``dyndbg="QUERY"`` or ``module.dyndbg="QUERY"``.  QUERY follows
0253 the syntax described above, but must not exceed 1023 characters.  Your
0254 bootloader may impose lower limits.
0255 
0256 These ``dyndbg`` params are processed just after the ddebug tables are
0257 processed, as part of the early_initcall.  Thus you can enable debug
0258 messages in all code run after this early_initcall via this boot
0259 parameter.
0260 
0261 On an x86 system for example ACPI enablement is a subsys_initcall and::
0262 
0263    dyndbg="file ec.c +p"
0264 
0265 will show early Embedded Controller transactions during ACPI setup if
0266 your machine (typically a laptop) has an Embedded Controller.
0267 PCI (or other devices) initialization also is a hot candidate for using
0268 this boot parameter for debugging purposes.
0269 
0270 If ``foo`` module is not built-in, ``foo.dyndbg`` will still be processed at
0271 boot time, without effect, but will be reprocessed when module is
0272 loaded later. Bare ``dyndbg=`` is only processed at boot.
0273 
0274 
0275 Debug Messages at Module Initialization Time
0276 ============================================
0277 
0278 When ``modprobe foo`` is called, modprobe scans ``/proc/cmdline`` for
0279 ``foo.params``, strips ``foo.``, and passes them to the kernel along with
0280 params given in modprobe args or ``/etc/modprob.d/*.conf`` files,
0281 in the following order:
0282 
0283 1. parameters given via ``/etc/modprobe.d/*.conf``::
0284 
0285         options foo dyndbg=+pt
0286         options foo dyndbg # defaults to +p
0287 
0288 2. ``foo.dyndbg`` as given in boot args, ``foo.`` is stripped and passed::
0289 
0290         foo.dyndbg=" func bar +p; func buz +mp"
0291 
0292 3. args to modprobe::
0293 
0294         modprobe foo dyndbg==pmf # override previous settings
0295 
0296 These ``dyndbg`` queries are applied in order, with last having final say.
0297 This allows boot args to override or modify those from ``/etc/modprobe.d``
0298 (sensible, since 1 is system wide, 2 is kernel or boot specific), and
0299 modprobe args to override both.
0300 
0301 In the ``foo.dyndbg="QUERY"`` form, the query must exclude ``module foo``.
0302 ``foo`` is extracted from the param-name, and applied to each query in
0303 ``QUERY``, and only 1 match-spec of each type is allowed.
0304 
0305 The ``dyndbg`` option is a "fake" module parameter, which means:
0306 
0307 - modules do not need to define it explicitly
0308 - every module gets it tacitly, whether they use pr_debug or not
0309 - it doesn't appear in ``/sys/module/$module/parameters/``
0310   To see it, grep the control file, or inspect ``/proc/cmdline.``
0311 
0312 For ``CONFIG_DYNAMIC_DEBUG`` kernels, any settings given at boot-time (or
0313 enabled by ``-DDEBUG`` flag during compilation) can be disabled later via
0314 the debugfs interface if the debug messages are no longer needed::
0315 
0316    echo "module module_name -p" > <debugfs>/dynamic_debug/control
0317 
0318 Examples
0319 ========
0320 
0321 ::
0322 
0323   // enable the message at line 1603 of file svcsock.c
0324   nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
0325                                 <debugfs>/dynamic_debug/control
0326 
0327   // enable all the messages in file svcsock.c
0328   nullarbor:~ # echo -n 'file svcsock.c +p' >
0329                                 <debugfs>/dynamic_debug/control
0330 
0331   // enable all the messages in the NFS server module
0332   nullarbor:~ # echo -n 'module nfsd +p' >
0333                                 <debugfs>/dynamic_debug/control
0334 
0335   // enable all 12 messages in the function svc_process()
0336   nullarbor:~ # echo -n 'func svc_process +p' >
0337                                 <debugfs>/dynamic_debug/control
0338 
0339   // disable all 12 messages in the function svc_process()
0340   nullarbor:~ # echo -n 'func svc_process -p' >
0341                                 <debugfs>/dynamic_debug/control
0342 
0343   // enable messages for NFS calls READ, READLINK, READDIR and READDIR+.
0344   nullarbor:~ # echo -n 'format "nfsd: READ" +p' >
0345                                 <debugfs>/dynamic_debug/control
0346 
0347   // enable messages in files of which the paths include string "usb"
0348   nullarbor:~ # echo -n 'file *usb* +p' > <debugfs>/dynamic_debug/control
0349 
0350   // enable all messages
0351   nullarbor:~ # echo -n '+p' > <debugfs>/dynamic_debug/control
0352 
0353   // add module, function to all enabled messages
0354   nullarbor:~ # echo -n '+mf' > <debugfs>/dynamic_debug/control
0355 
0356   // boot-args example, with newlines and comments for readability
0357   Kernel command line: ...
0358     // see whats going on in dyndbg=value processing
0359     dynamic_debug.verbose=3
0360     // enable pr_debugs in the btrfs module (can be builtin or loadable)
0361     btrfs.dyndbg="+p"
0362     // enable pr_debugs in all files under init/
0363     // and the function parse_one, #cmt is stripped
0364     dyndbg="file init/* +p #cmt ; func parse_one +p"
0365     // enable pr_debugs in 2 functions in a module loaded later
0366     pc87360.dyndbg="func pc87360_init_device +p; func pc87360_find +p"