Message-ID: <4E7A66B0.2040103@xenotime.net>
Date:	Wed, 21 Sep 2011 15:35:28 -0700
From:	Randy Dunlap <rdunlap@...otime.net>
To:	jim.cromie@...il.com
CC:	jbaron@...hat.com, joe@...ches.com, bart.vanassche@...il.com,
	greg@...ah.com, linux-kernel@...r.kernel.org
Subject: Re: [PATCH 23/26] dynamic_debug: document pending queries, flags-filter,
 multiple queries

On 09/21/2011 02:55 PM, jim.cromie@...il.com wrote:
> From: Jim Cromie <jim.cromie@...il.com>
> 
> Rework description of flags-spec into 3 parts; flags-filter, flags-change,
> flags-values.  Add section on pending-queries.  Explain flags filtering
> in detail.  Reflow some paragraphs.
> 
> Add example of a command-file which shows commenting,
> multiple queries per line, and describes constraints.
> 
> Signed-off-by: Jim Cromie <jim.cromie@...il.com>
> ---
>  Documentation/dynamic-debug-howto.txt |  336 ++++++++++++++++++++++-----------
>  1 files changed, 222 insertions(+), 114 deletions(-)
> 
> diff --git a/Documentation/dynamic-debug-howto.txt b/Documentation/dynamic-debug-howto.txt
> index f959909..bf9037f 100644
> --- a/Documentation/dynamic-debug-howto.txt
> +++ b/Documentation/dynamic-debug-howto.txt
> @@ -4,117 +4,134 @@ Introduction
>  
>  This document describes how to use the dynamic debug (ddebug) feature.
>  
> -Dynamic debug is designed to allow you to dynamically enable/disable kernel
> -code to obtain additional kernel information. Currently, if
> -CONFIG_DYNAMIC_DEBUG is set, then all pr_debug()/dev_dbg() calls can be
> -dynamically enabled per-callsite.
> +Dynamic debug is designed to allow you to dynamically enable/disable
> +kernel code to obtain additional kernel information.  If kernel is

                                                         If {the | a} kernel is

> +built with CONFIG_DYNAMIC_DEBUG=y, then all pr_debug()/dev_dbg() calls
> +can be dynamically enabled per-callsite.
>  
>  Dynamic debug has even more useful features:
>  
> - * Simple query language allows turning on and off debugging statements by
> -   matching any combination of:
> + * Simple query language allows turning on and off debugging statements
> +   by matching any combination of 0 or 1 of:
>  
>     - source filename
>     - function name
>     - line number (including ranges of line numbers)
>     - module name
>     - format string
> +   - current debugging flags
>  
> - * Provides a debugfs control file: <debugfs>/dynamic_debug/control which can be
> -   read to display the complete list of known debug statements, to help guide you
> + * Provides a debugfs control file: <debugfs>/dynamic_debug/control
> +   which can be read to display the complete list of known debug
> +   statements, to help guide you.
>  
>  Controlling dynamic debug Behaviour
>  ===================================
>  
> -The behaviour of pr_debug()/dev_dbg()s are controlled via writing to a
> -control file in the 'debugfs' filesystem. Thus, you must first mount the debugfs
> -filesystem, in order to make use of this feature. Subsequently, we refer to the
> -control file as: <debugfs>/dynamic_debug/control. For example, if you want to
> -enable printing from source file 'svcsock.c', line 1603 you simply do:
> +The behaviour of pr_debug()/dev_dbg()/net_dbg()s are controlled via

   The behaviour                           ...      is controlled by

> +writing to a control file in the 'debugfs' filesystem. Thus, you must
> +first mount the debugfs filesystem, in order to make use of this

drop comma.

> +feature.  Subsequently, we refer to mount point as $DBGFS, and the

                                    to the mount point
also drop comma after $DBGFS.

> +control file as $CONTROL.  So if you want to enable printing from
> +source file 'svcsock.c', line 1603 you simply do:
>  
> -nullarbor:~ # echo 'file svcsock.c line 1603 +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo file svcsock.c line 1603 +p > $CONTROL
>  
>  If you make a mistake with the syntax, the write will fail thus:
>  
> -nullarbor:~ # echo 'file svcsock.c wtf 1 +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # 'echo file svcsock.c wtf 1 +p' > $CONTROL
>  -bash: echo: write error: Invalid argument
>  
>  Viewing Dynamic Debug Behaviour
> -===========================
> +===============================
>  
> -You can view the currently configured behaviour of all the debug statements
> -via:
> +You can view the currently configured behaviour by catting or grepping
> +the $CONTROL file:
>  
> -nullarbor:~ # cat <debugfs>/dynamic_debug/control
> +root@...age:~# grep freezer $CONTROL
> +kernel/freezer.c:128 [freezer]cancel_freezing =_ "  clean up: %s\012"
> +kernel/freezer.c:60 [freezer]refrigerator =_ "%s left refrigerator\012"
> +kernel/freezer.c:41 [freezer]refrigerator =_ "%s entered refrigerator\012"
> +
> +The third column shows the current flag settings for each debug

There are columns there??!!??  Hard to tell.

> +statement callsite (menmonic: what they are equal to, see below for

                       mnemonic:

> +definitions of the flags).  The default value, with nothing enabled,
> +is "=_".  So you can view all the debug statement callsites with any
> +non-default flags:
> +
> +nullarbor:~ # grep -v "=_" $CONTROL
>  # filename:lineno [module]function flags format
> -/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"
> -/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init - "\011max_inline       : %d\012"
> -/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init - "\011sq_depth         : %d\012"
> -/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init - "\011max_requests     : %d\012"
> -...
> +/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"
> +
> +
> +Command Language Reference
> +==========================
>  
> +At the lexical level, a command comprises a sequence of words separated
> +by whitespace characters.
>  
> -You can also apply standard Unix text manipulation filters to this
> -data, e.g.
> +nullarbor:~# echo file svcsock.c line 1603 +p > $CONTROL
>  
> -nullarbor:~ # grep -i rdma <debugfs>/dynamic_debug/control  | wc -l
> -62
> +nullarbor:~# echo 'file svcsock.c line 1603 +p' > $CONTROL
>  
> -nullarbor:~ # grep -i tcp <debugfs>/dynamic_debug/control | wc -l
> -42
> +nullarbor:~# echo -n '  file   svcsock.c     line  1603 +p  ' > $CONTROL
>  
> -Note in particular that the third column shows the enabled behaviour
> -flags for each debug statement callsite (see below for definitions of the
> -flags).  The default value, no extra behaviour enabled, is "-".  So
> -you can view all the debug statement callsites with any non-default flags:
> +nullarbor:~# echo -n 'file svcsock.c line 1603 +p' > $CONTROL
>  
> -nullarbor:~ # awk '$3 != "-"' <debugfs>/dynamic_debug/control
> -# filename:lineno [module]function flags format
> -/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"
> +Multiple query/commands
> +=======================
>  
> +Commands are bounded by a write() system call.  Subject to this limit

s/bounded/limited/ ?
> +(or 1024 for boot-line parameter) you can send multiple commands,

Maybe you could rewrite this paragraph so that I can understand what
it means?

> +separated by ';' or '\n'

End sentence with period ('.').

>  
> -Command Language Reference
> -==========================
> +voyage:~# echo   "func cancel_freezing +p ; func refrigerator +p; " > $CONTROL
> +voyage:~# printf "func cancel_freezing +p \n func refrigerator +p; " > $CONTROL
>  
> -At the lexical level, a command comprises a sequence of words separated
> -by whitespace characters.  Note that newlines are treated as word
> -separators and do *not* end a command or allow multiple commands to
> -be done together.  So these are all equivalent:
> +voyage:~# cat dyndbg-cmdfile
>  
> -nullarbor:~ # echo -c 'file svcsock.c line 1603 +p' >
> -				<debugfs>/dynamic_debug/control
> -nullarbor:~ # echo -c '  file   svcsock.c     line  1603 +p  ' >
> -				<debugfs>/dynamic_debug/control
> -nullarbor:~ # echo -c 'file svcsock.c\nline 1603 +p' >
> -				<debugfs>/dynamic_debug/control
> -nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
> -				<debugfs>/dynamic_debug/control
> +  # comments and blank lines ok, but cannot contain semicolon
> +  # multiple cmds per line, 1st must be terminated by semicolon

Change "1st" to "all but last" ?

> +  func foo p=_	; func buzz p=_
> +  func bar p=_	; func bum  p=_
> +  func yak p=_	; # trailing comment, requires semicolon to terminate cmd
>  
> -Commands are bounded by a write() system call.  If you want to do
> -multiple commands you need to do a separate "echo" for each, like:
> +  # heres the oddity: semicolon terminates comment, so this works
> +  func foo +p ; # comment ; func bar +p
> +  # allowing this keeps parsing simple
>  
> -nullarbor:~ # echo 'file svcsock.c line 1603 +p' > /proc/dprintk ;\
> -> echo 'file svcsock.c line 1563 +p' > /proc/dprintk
> +voyage:~# cat dyndbg-cmdfile > $CONTROL
> +dynamic_debug:ddebug_exec_queries: processed 7 queries, with 0 errs
> +
> +Multiple commands are processed independently, this allows you to send

                                   independently.  This allows

> +commands which may fail, for example if a module is not present.  The
> +last failing command returns its error.
> +
> +Or you can do an "echo" for each, like:
> +
> +nullarbor:~ # echo 'file svcsock.c line 1603 +p' > $CONTROL; \
> +> echo 'file svcsock.c line 1563 +p' > $CONTROL
>  
>  or even like:
>  
>  nullarbor:~ # (
>  > echo 'file svcsock.c line 1603 +p' ;\
>  > echo 'file svcsock.c line 1563 +p' ;\
> -> ) > /proc/dprintk
> +> ) > $CONTROL
>  
> -At the syntactical level, a command comprises a sequence of match
> +Query/command syntax
> +====================
> +
> +At the syntactic level, a command comprises a sequence of match
>  specifications, followed by a flags change specification.
>  
>  command ::= match-spec* flags-spec
>  
> -The match-spec's are used to choose a subset of the known dprintk()
> -callsites to which to apply the flags-spec.  Think of them as a query
> -with implicit ANDs between each pair.  Note that an empty list of
> -match-specs is possible, but is not very useful because it will not
> -match any debug statement callsites.
> +The match-specs are used to choose a subset of the known callsites to
> +which to apply the flags-spec.  Think of them as a query with implicit
> +ANDs between each pair.  This means that multiple specs of a given
> +type are nonsense; a module cannot match A and B simultaneously.  Note
> +that an empty list of match-specs matches all callsites.
>  
>  A match specification comprises a keyword, which controls the attribute
>  of the callsite to be compared, and a value to compare against.  Possible
> @@ -125,12 +142,13 @@ match-spec ::= 'func' string |
>  	       'module' string |
>  	       'format' string |
>  	       'line' line-range
> +// Note: no wildcards, regexs are accepted
>  
>  line-range ::= lineno |
>  	       '-'lineno |
>  	       lineno'-' |
>  	       lineno'-'lineno
> -// Note: line-range cannot contain space, e.g.
> +// Note: line-range cannot contain a space, e.g.
>  // "1-30" is valid range but "1 - 30" is not.
>  
>  lineno ::= unsigned-int
> @@ -144,11 +162,12 @@ func
>      func svc_tcp_accept
>  
>  file
> -    The given string is compared against either the full
> -    pathname or the basename of the source file of each
> -    callsite.  Examples:
> +    The given string is compared against either the full pathname,
> +    relative path from kernel source dir, or the basename of the
> +    source file of each callsite.  Examples:
>  
>      file svcsock.c
> +    file kernel/freezer.c
>      file /usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svcsock.c
>  
>  module
> @@ -157,7 +176,7 @@ module
>      seen in "lsmod", i.e. without the directory or the .ko
>      suffix and with '-' changed to '_'.  Examples:
>  
> -    module sunrpc
> +    module ide_pci_generic
>      module nfsd
>  
>  format
> @@ -190,79 +209,168 @@ line
>      line -1605	    // the 1605 lines from line 1 to line 1605
>      line 1600-	    // all lines from line 1600 to the end of the file
>  
> -The flags specification comprises a change operation followed
> -by one or more flag characters.  The change operation is one
> -of the characters:
> -
> --
> -    remove the given flags
> -
> -+
> -    add the given flags
> +flags specification
> +===================
>  
> -=
> -    set the flags to the given flags
> +The flags specification matches the regexp: ^[flmpta_]*[-+=][flmpta_]*$
> +and has 3 parts:
>  
> -The flags are:
> +flags filter (optional):
> +    The filter precedes the operation [-+=], and constrains matching
> +    to thoses callsite with given flags set.  This allows altering

          those

> +    flags on callsites with filtered flag values
>  
> -f
> -    Include the function name in the printed message
> -l
> -    Include line number in the printed message
> -m
> -    Include module name in the printed message
> -p
> -    Causes a printk() message to be emitted to dmesg
> -t
> -    Include thread ID in messages not generated from interrupt context
> +      pm+t	# add t to enabled sites which have m
> +      p+t	# add t to all enabled sites, both m and !m
> +      tmf-p	# disable sites with 'tmf'
> +      tmf+p	# re-enable those disabled sites
>  
> -Note the regexp ^[-+=][flmpt]+$ matches a flags specification.
> -Note also that there is no convenient syntax to remove all
> -the flags at once, you need to use "-flmpt".
> +flags change operation:
> +    '-' remove the given flags
> +    '+' add the given flags
> +    '=' set the flags to the given flags
>  
> +The flags are:
> +  'p' Causes a printk() message to be emitted to dmesg

                                                 to the kernel log (or kernel log buffer);

[dmesg is a program that can print the kernel log.]

> +      other flags can thus be left on, and used in filters.
> +  'm' Include module name in the printed message
> +  'f' Include the function name in the printed message
> +  'l' Include line number in the printed message
> +  't' Include thread ID in messages not generated from interrupt context
> +  'a' Also add query to pending queries, for later (re)application
> +  '_' default/null flag.
> +      Primarily for display, so grep "=_" can avoid " = " in format strings.
> +      Also usable (but not required) to clear all flags.
> +
> +Pending queries
> +===============
> +
> +Queries submitted with 'a' are applied to current callsites as above,
> +but are also added to a pending list.  When a module is loaded later,
> +pending queries are applied to the module in the order given.
> +
> +This is done before the module_init() routine is run, so pr_debug()s
> +can be active during initialization.  To better support module
> +debugging, pending queries remain on the list through modprobe-rmmod
> +cycles.
> +
> +You can review currently pending queries by catting or grepping
> +$DEBUFS/dynamic_debug/pending.  To simplify removal via

   $DBGFS ?

> +cut-paste-edit, its format is similar to the query syntax:
> +
> +  root@...age:~# cat /dbg/dynamic_debug/pending

use $DBGFS in path name?

> +  # func file module format line flags mask
> +  ...
> +   func a299 line 0-0 =pa
> +   func a300 line 0-0 =pa
> +
> +To remove a pending query, resubmit it with 'a' in filter-spec
> +and zeroed flag-specs:
> +
> +  # a simple helper shell-function, to shorten examples
> +  DBGFS=${DBGFS:=/dbg}
> +  CONTROL=$DBGFS/dynamic_debug/control
> +  function dbg_query() {
> +        echo "$*" > $CONTROL
> +        # see relevant settings, effects of the query/command
> +        grep $2 $DBGFS/dynamic_debug/*
> +  }
> +
> +  voyage:~# dbg_query module foo +apt	# original pending query
> +  voyage:~# dbg_query module foo a=	# zero 'a' flag to remove query
> +  voyage:~# dbg_query module foo a-a	# zero 'a', remove query
> +  voyage:~# dbg_query module foo a-ap	# zero 'a', also disable callsites
> +
> +Deleting or altering a pending query requires an exact match on most
> +of the match-spec; the same string specs must be given, but 'line 0-0'
> +matches with '' and vice-versa.  The filter-spec is ignored for
> +pending-list changes.
> +
> +  voyage:~# dbg_query module foo +apt	# add PQ-1 before each of following..

Sorry, I guess I'm dense today.  What is this "PQ-1"?

> +
> +  # will not remove PQ-1 (mismatch on lines)
> +  voyage:~# dbg_query module foo line 100-200 ap=
> +
> +  # removes PQ-1 (exact match with PQ-1), disables active callsites (if any)
> +  voyage:~# dbg_query module foo line 0-0 ap=
> +
> +  # delete PQ-1, leave callsites active (none of 'ptmfl' subtracted)
> +  voyage:~# dbg_query module foo a-a
> +
> +  # delete PQ-1, disable callsites (all flags zeroed)
> +  voyage:~# dbg_query module foo a=_
> +
> +  # delete PQ-1, leave callsites active (no 'm' on active callsites)
> +  voyage:~# dbg_query module foo am=_
> +
> +  # del PQ-1, and disable callsites (-p), leaving 't'
> +  voyage:~# dbg_query module foo a-ap
> +
> +  # del PQ-1, disable and clear callsites (-pt removes flags set by PQ-1)
> +  voyage:~# dbg_query module foo a-apt
> +
> +  # del PQ-1, disable callsites with 'pt', leave 't'
> +  voyage:~# dbg_query module foo apt-ap
> +
> +  # reactivate foo's callsites marked with 't' (see "flags filter" above)
> +  voyage:~# dbg_query module foo t+p
> +
> +  # add 'm' to foo's callsites with 't', add new pending query with 'pm'
> +  voyage:~# dbg_query module foo at+pm
> +
> +Altering a pending query ('a' in filter) will also alter the callsites
> +that it applies to (subject to filter match), but changing the active
> +callsites (using a query without the 'a') does not change the pending
> +query that applied it.
>  
>  Debug messages during boot process
>  ==================================
>  
> -To be able to activate debug messages during the boot process,
> -even before userspace and debugfs exists, use the boot parameter:
> -ddebug_query="QUERY"
> +To be able to activate debug messages during the boot process, even
> +before userspace and debugfs exists, use the boot parameter:
> +ddebug_query="QUERY".
>  
>  QUERY follows the syntax described above, but must not exceed 1023
> -characters. The enablement of debug messages is done as an arch_initcall.
> -Thus you can enable debug messages in all code processed after this
> +characters.  It may contain multiple commands separated by ';'
> +('\n' seems to be eaten by my bootloader).
> +
> +The enablement of debug messages is done as an arch_initcall.  Thus
> +you can enable debug messages in all code processed after this
>  arch_initcall via this boot parameter.
> -On an x86 system for example ACPI enablement is a subsys_initcall and
> -ddebug_query="file ec.c +p"
> +
> +On an x86 system for example ACPI enablement is a subsys_initcall, so
> +  ddebug_query="file ec.c +p"
>  will show early Embedded Controller transactions during ACPI setup if
>  your machine (typically a laptop) has an Embedded Controller.
>  PCI (or other devices) initialization also is a hot candidate for using
>  this boot parameter for debugging purposes.
>  
> -
>  Examples
>  ========
>  
>  // enable the message at line 1603 of file svcsock.c
> -nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' > $CONTROL
>  
>  // enable all the messages in file svcsock.c
> -nullarbor:~ # echo -n 'file svcsock.c +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'file svcsock.c +p' > $CONTROL
>  
>  // enable all the messages in the NFS server module
> -nullarbor:~ # echo -n 'module nfsd +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'module nfsd +p' > $CONTROL
>  
>  // enable all 12 messages in the function svc_process()
> -nullarbor:~ # echo -n 'func svc_process +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'func svc_process +p' > $CONTROL
>  
>  // disable all 12 messages in the function svc_process()
> -nullarbor:~ # echo -n 'func svc_process -p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'func svc_process -p' > $CONTROL
>  
>  // enable messages for NFS calls READ, READLINK, READDIR and READDIR+.
> -nullarbor:~ # echo -n 'format "nfsd: READ" +p' >
> -				<debugfs>/dynamic_debug/control
> +nullarbor:~ # echo -n 'format "nfsd: READ" +p' > $CONTROL
> +
> +// send query-command file to control
> +root@...age:~# cat dyndbg-cmdfile > $CONTROL
> +dynamic_debug:ddebug_proc_open: called
> +dynamic_debug:ddebug_proc_write: read 500 bytes from userspace
> +dynamic_debug:ddebug_exec_queries: query 0: "func foo p=_	"
> +dynamic_debug:ddebug_tokenize: split into words: "func" "foo" "p=_"
> +dynamic_debug:ddebug_parse_query: parsed func="foo" file="" module="" format="" lineno=0-0
> +...



thanks,
-- 
~Randy
*** Remember to use Documentation/SubmitChecklist when testing your code ***
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists