2020-07-19 23:11:42

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 00/18] dynamic_debug fixes, cleanups, features, export

this is v5, changes from previous:
- moved a chunk from patch 13 to 12, per Jason
- shorten logging prefix to "dyndbg", drop __func__
- now with more commit-log advocacy
- shuffle EXPORT_GPL(ddebug_exec_queries) last.
- v4+ series Acked-by: [email protected]

v4: https://lore.kernel.org/lkml/[email protected]/
v3: https://lore.kernel.org/lkml/[email protected]/
v2: https://lore.kernel.org/lkml/[email protected]/
v1: https://lore.kernel.org/lkml/[email protected]/


Patchset starts with cleanups;
- change section name from vague "__verbose" to specific "__dyndbg"
- cleaner docs, drop obsolete comment & useless debug prints,
- refine verbose/debug logging
- fix a BUG_ON, ram reporting miscounts. etc..

Then adds query parsing conveniences
- allow "file inode.c:100-200" # combined file & line-range
- allow "file inode.c:start_*" # file & function
- accept "module=foo" query form

internal improvement
- combine flags & mask in a struct, clean 3 func interfaces with it.

make precise format queries easier
- accept "format=^ClassString" anchored query

finally, EXPORT_GPL(ddebug_exec_queries)

This gives module authors complete run-time control over all their
*pr_debug* callsites (when CONFIG_DYNAMIC_DEBUG=y).

Following the drm.debug UI model, drm.debug_chan2 could be wired to a
callback which invokes ddebug_exec_queries to toggle arbitary groups
of pr_debug callsites.

Useful callsite groups would exploit existing message-prefix
classifcation schemes:

"format=^[IF_TRACE]: +p; format=^[SURFACE]: +p" >control


Jim Cromie (18):
dyndbg-docs: eschew file /full/path query in docs
dyndbg-docs: initialization is done early, not arch
dyndbg: drop obsolete comment on ddebug_proc_open
dyndbg: refine debug verbosity; 1 is basic, 2 more chatty
dyndbg: rename __verbose section to __dyndbg
dyndbg: fix overcounting of ram used by dyndbg
dyndbg: fix a BUG_ON in ddebug_describe_flags
dyndbg: fix pr_err with empty string
dyndbg: prefer declarative init in caller, to memset in callee
dyndbg: make ddebug_tables list LIFO for add/remove_module
dyndbg: use gcc ?: to reduce word count
dyndbg: refactor parse_linerange out of ddebug_parse_query
dyndbg: accept 'file foo.c:func1' and 'file foo.c:10-100'
dyndbg: accept query terms like file=bar and module=foo
dyndbg: combine flags & mask into a struct, simplify with it
dyndbg: allow anchored match on format query term
dyndbg: shorten our logging prefix, drop __func__
dyndbg: export ddebug_exec_queries

.../admin-guide/dynamic-debug-howto.rst | 29 +-
include/asm-generic/vmlinux.lds.h | 6 +-
include/linux/dynamic_debug.h | 4 +-
kernel/module.c | 2 +-
lib/dynamic_debug.c | 269 ++++++++++--------
5 files changed, 173 insertions(+), 137 deletions(-)

--
2.26.2


2020-07-19 23:11:50

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 01/18] dyndbg-docs: eschew file /full/path query in docs

Regarding:
commit 2b6783191da7 ("dynamic_debug: add trim_prefix() to provide source-root relative paths")
commit a73619a845d5 ("kbuild: use -fmacro-prefix-map to make __FILE__ a relative path")

2nd commit broke dynamic-debug's "file $fullpath" query form, but
nobody noticed because 1st commit had trimmed prefixes from
control-file output, so the click-copy-pasting of fullpaths into new
queries had ceased; that query form became unused.

Removing the function is cleanest, but it could be useful in
old-compiler corner cases, where __FILE__ still has /full/path,
and it safely does nothing otherwize.

So instead, quietly deprecate "file /full/path" query form, by
removing all /full/paths examples in the docs. I skipped adding a
back-compat note.

Signed-off-by: Jim Cromie <[email protected]>
---
.../admin-guide/dynamic-debug-howto.rst | 19 +++++++++----------
1 file changed, 9 insertions(+), 10 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 1012bd9305e9..57108f64afc8 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -70,10 +70,10 @@ statements via::

nullarbor:~ # cat <debugfs>/dynamic_debug/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"
+ net/sunrpc/svc_rdma.c:323 [svcxprt_rdma]svc_rdma_cleanup =_ "SVCRDMA Module Removed, deregister RPC RDMA transport\012"
+ net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init =_ "\011max_inline : %d\012"
+ net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init =_ "\011sq_depth : %d\012"
+ net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init =_ "\011max_requests : %d\012"
...


@@ -93,7 +93,7 @@ the debug statement callsites with any non-default flags::

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"
+ net/sunrpc/svcsock.c:1603 [sunrpc]svc_send p "svc_process: st_sendto returned %d\012"

Command Language Reference
==========================
@@ -166,13 +166,12 @@ func
func svc_tcp_accept

file
- The given string is compared against either the full pathname, the
- src-root relative pathname, or the basename of the source file of
- each callsite. Examples::
+ The given string is compared against either the src-root relative
+ pathname, 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
+ file kernel/freezer.c # ie column 1 of control file

module
The given string is compared against the module name
--
2.26.2

2020-07-19 23:12:01

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 02/18] dyndbg-docs: initialization is done early, not arch

since cf964976484 in 2012, initialization is done with early_initcall,
update the Docs, which still say arch_initcall.

Signed-off-by: Jim Cromie <[email protected]>
---
Documentation/admin-guide/dynamic-debug-howto.rst | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 57108f64afc8..1423af580bed 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -250,8 +250,8 @@ the syntax described above, but must not exceed 1023 characters. Your
bootloader may impose lower limits.

These ``dyndbg`` params are processed just after the ddebug tables are
-processed, as part of the arch_initcall. Thus you can enable debug
-messages in all code run after this arch_initcall via this boot
+processed, as part of the early_initcall. Thus you can enable debug
+messages in all code run after this early_initcall via this boot
parameter.

On an x86 system for example ACPI enablement is a subsys_initcall and::
--
2.26.2

2020-07-19 23:12:03

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 03/18] dyndbg: drop obsolete comment on ddebug_proc_open

commit 4bad78c55002 ("lib/dynamic_debug.c: use seq_open_private() instead of seq_open()")'

The commit was one of a tree-wide set which replaced open-coded
boilerplate with a single tail-call. It therefore obsoleted the
comment about that boilerplate, clean that up now.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 7 -------
1 file changed, 7 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 321437bbf87d..2989a590ce9a 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -853,13 +853,6 @@ static const struct seq_operations ddebug_proc_seqops = {
.stop = ddebug_proc_stop
};

-/*
- * File_ops->open method for <debugfs>/dynamic_debug/control. Does
- * the seq_file setup dance, and also creates an iterator to walk the
- * _ddebugs. Note that we create a seq_file always, even for O_WRONLY
- * files where it's not needed, as doing so simplifies the ->release
- * method.
- */
static int ddebug_proc_open(struct inode *inode, struct file *file)
{
vpr_info("called\n");
--
2.26.2

2020-07-19 23:12:15

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 05/18] dyndbg: rename __verbose section to __dyndbg

dyndbg populates its callsite info into __verbose section, change that
to a more specific and descriptive name, __dyndbg.

Also, per checkpatch:
simplify __attribute(..) to __section(__dyndbg) declaration.

and 1 spelling fix, decriptor

Signed-off-by: Jim Cromie <[email protected]>
---
include/asm-generic/vmlinux.lds.h | 6 +++---
include/linux/dynamic_debug.h | 4 ++--
kernel/module.c | 2 +-
lib/dynamic_debug.c | 12 ++++++------
4 files changed, 12 insertions(+), 12 deletions(-)

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index db600ef218d7..05af5cef1ad6 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -320,9 +320,9 @@
*(__tracepoints) \
/* implement dynamic printk debug */ \
. = ALIGN(8); \
- __start___verbose = .; \
- KEEP(*(__verbose)) \
- __stop___verbose = .; \
+ __start___dyndbg = .; \
+ KEEP(*(__dyndbg)) \
+ __stop___dyndbg = .; \
LIKELY_PROFILE() \
BRANCH_PROFILE() \
TRACE_PRINTKS() \
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index abcd5fde30eb..aa9ff9e1c0b3 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -80,7 +80,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,

#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt) \
static struct _ddebug __aligned(8) \
- __attribute__((section("__verbose"))) name = { \
+ __section(__dyndbg) name = { \
.modname = KBUILD_MODNAME, \
.function = __func__, \
.filename = __FILE__, \
@@ -133,7 +133,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,

/*
* "Factory macro" for generating a call to func, guarded by a
- * DYNAMIC_DEBUG_BRANCH. The dynamic debug decriptor will be
+ * DYNAMIC_DEBUG_BRANCH. The dynamic debug descriptor will be
* initialized using the fmt argument. The function will be called with
* the address of the descriptor as first argument, followed by all
* the varargs. Note that fmt is repeated in invocations of this
diff --git a/kernel/module.c b/kernel/module.c
index aa183c9ac0a2..e7b4ff7e4fd0 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3237,7 +3237,7 @@ static int find_module_sections(struct module *mod, struct load_info *info)
if (section_addr(info, "__obsparm"))
pr_warn("%s: Ignoring obsolete parameters\n", mod->name);

- info->debug = section_objs(info, "__verbose",
+ info->debug = section_objs(info, "__dyndbg",
sizeof(*info->debug), &info->num_debug);

return 0;
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c97872cffc8e..66c0bdf06ce7 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -39,8 +39,8 @@

#include <rdma/ib_verbs.h>

-extern struct _ddebug __start___verbose[];
-extern struct _ddebug __stop___verbose[];
+extern struct _ddebug __start___dyndbg[];
+extern struct _ddebug __stop___dyndbg[];

struct ddebug_table {
struct list_head link;
@@ -1019,7 +1019,7 @@ static int __init dynamic_debug_init(void)
int n = 0, entries = 0, modct = 0;
int verbose_bytes = 0;

- if (&__start___verbose == &__stop___verbose) {
+ if (&__start___dyndbg == &__stop___dyndbg) {
if (IS_ENABLED(CONFIG_DYNAMIC_DEBUG)) {
pr_warn("_ddebug table is empty in a CONFIG_DYNAMIC_DEBUG build\n");
return 1;
@@ -1028,10 +1028,10 @@ static int __init dynamic_debug_init(void)
ddebug_init_success = 1;
return 0;
}
- iter = __start___verbose;
+ iter = __start___dyndbg;
modname = iter->modname;
iter_start = iter;
- for (; iter < __stop___verbose; iter++) {
+ for (; iter < __stop___dyndbg; iter++) {
entries++;
verbose_bytes += strlen(iter->modname) + strlen(iter->function)
+ strlen(iter->filename) + strlen(iter->format);
@@ -1054,7 +1054,7 @@ static int __init dynamic_debug_init(void)
ddebug_init_success = 1;
vpr_info("%d modules, %d entries and %d bytes in ddebug tables, %d bytes in (readonly) verbose section\n",
modct, entries, (int)(modct * sizeof(struct ddebug_table)),
- verbose_bytes + (int)(__stop___verbose - __start___verbose));
+ verbose_bytes + (int)(__stop___dyndbg - __start___dyndbg));

/* apply ddebug_query boot param, dont unload tables on err */
if (ddebug_setup_string[0] != '\0') {
--
2.26.2

2020-07-19 23:12:20

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 06/18] dyndbg: fix overcounting of ram used by dyndbg

during dyndbg init, verbose logging prints its ram overhead. It
counted strlens of struct _ddebug's 4 string members, in all callsite
entries, which would be approximately correct if each had been
mallocd. But they are pointers into shared .rodata; for example, all
10 kobject callsites have identical filename, module values.

Its best not to count that memory at all, since we cannot know they
were linked in because of CONFIG_DYNAMIC_DEBUG=y, and we want to
report a number that reflects what ram is saved by deconfiguring it.

Also fix wording and size under-reporting of the __dyndbg section.

Heres my overhead, on a virtme-run VM on a fedora-31 laptop:

dynamic_debug:dynamic_debug_init: 260 modules, 2479 entries \
and 10400 bytes in ddebug tables, 138824 bytes in __dyndbg section

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 8 ++------
1 file changed, 2 insertions(+), 6 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 66c0bdf06ce7..9b2445507988 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1017,7 +1017,6 @@ static int __init dynamic_debug_init(void)
char *cmdline;
int ret = 0;
int n = 0, entries = 0, modct = 0;
- int verbose_bytes = 0;

if (&__start___dyndbg == &__stop___dyndbg) {
if (IS_ENABLED(CONFIG_DYNAMIC_DEBUG)) {
@@ -1033,9 +1032,6 @@ static int __init dynamic_debug_init(void)
iter_start = iter;
for (; iter < __stop___dyndbg; iter++) {
entries++;
- verbose_bytes += strlen(iter->modname) + strlen(iter->function)
- + strlen(iter->filename) + strlen(iter->format);
-
if (strcmp(modname, iter->modname)) {
modct++;
ret = ddebug_add_module(iter_start, n, modname);
@@ -1052,9 +1048,9 @@ static int __init dynamic_debug_init(void)
goto out_err;

ddebug_init_success = 1;
- vpr_info("%d modules, %d entries and %d bytes in ddebug tables, %d bytes in (readonly) verbose section\n",
+ vpr_info("%d modules, %d entries and %d bytes in ddebug tables, %d bytes in __dyndbg section\n",
modct, entries, (int)(modct * sizeof(struct ddebug_table)),
- verbose_bytes + (int)(__stop___dyndbg - __start___dyndbg));
+ (int)(entries * sizeof(struct _ddebug)));

/* apply ddebug_query boot param, dont unload tables on err */
if (ddebug_setup_string[0] != '\0') {
--
2.26.2

2020-07-19 23:12:28

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 10/18] dyndbg: make ddebug_tables list LIFO for add/remove_module

loadable modules are the last in on this list, and are the only
modules that could be removed. ddebug_remove_module() searches from
head, but ddebug_add_module() uses list_add_tail(). Change it to
list_add() for a micro-optimization.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index da3ed54a6521..e879af4e66e0 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -895,7 +895,7 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
dt->ddebugs = tab;

mutex_lock(&ddebug_lock);
- list_add_tail(&dt->link, &ddebug_tables);
+ list_add(&dt->link, &ddebug_tables);
mutex_unlock(&ddebug_lock);

v2pr_info("%u debug prints in module %s\n", n, dt->mod_name);
--
2.26.2

2020-07-19 23:12:34

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 12/18] dyndbg: refactor parse_linerange out of ddebug_parse_query

Make the code-block reusable to later handle "file foo.c:101-200" etc.
This is a 99% code move, with reindent, function wrap&call, +pr_debug.

no functional changes.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 63 ++++++++++++++++++++++++++-------------------
1 file changed, 36 insertions(+), 27 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 6d0159075308..7a66d5e07f41 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -291,6 +291,41 @@ static inline int parse_lineno(const char *str, unsigned int *val)
return 0;
}

+static int parse_linerange(struct ddebug_query *query, const char *first)
+{
+ char *last = strchr(first, '-');
+
+ if (query->first_lineno || query->last_lineno) {
+ pr_err("match-spec: line used 2x\n");
+ return -EINVAL;
+ }
+ if (last)
+ *last++ = '\0';
+ if (parse_lineno(first, &query->first_lineno) < 0)
+ return -EINVAL;
+ if (last) {
+ /* range <first>-<last> */
+ if (parse_lineno(last, &query->last_lineno) < 0)
+ return -EINVAL;
+
+ /* special case for last lineno not specified */
+ if (query->last_lineno == 0)
+ query->last_lineno = UINT_MAX;
+
+ if (query->last_lineno < query->first_lineno) {
+ pr_err("last-line:%d < 1st-line:%d\n",
+ query->last_lineno,
+ query->first_lineno);
+ return -EINVAL;
+ }
+ } else {
+ query->last_lineno = query->first_lineno;
+ }
+ vpr_info("parsed line %d-%d\n", query->first_lineno,
+ query->last_lineno);
+ return 0;
+}
+
static int check_set(const char **dest, char *src, char *name)
{
int rc = 0;
@@ -348,34 +383,8 @@ static int ddebug_parse_query(char *words[], int nwords,
UNESCAPE_SPECIAL);
rc = check_set(&query->format, words[i+1], "format");
} else if (!strcmp(words[i], "line")) {
- char *first = words[i+1];
- char *last = strchr(first, '-');
- if (query->first_lineno || query->last_lineno) {
- pr_err("match-spec: line used 2x\n");
- return -EINVAL;
- }
- if (last)
- *last++ = '\0';
- if (parse_lineno(first, &query->first_lineno) < 0)
+ if (parse_linerange(query, words[i+1]))
return -EINVAL;
- if (last) {
- /* range <first>-<last> */
- if (parse_lineno(last, &query->last_lineno) < 0)
- return -EINVAL;
-
- /* special case for last lineno not specified */
- if (query->last_lineno == 0)
- query->last_lineno = UINT_MAX;
-
- if (query->last_lineno < query->first_lineno) {
- pr_err("last-line:%d < 1st-line:%d\n",
- query->last_lineno,
- query->first_lineno);
- return -EINVAL;
- }
- } else {
- query->last_lineno = query->first_lineno;
- }
} else {
pr_err("unknown keyword \"%s\"\n", words[i]);
return -EINVAL;
--
2.26.2

2020-07-19 23:12:45

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 15/18] dyndbg: combine flags & mask into a struct, simplify with it

flags & mask are used together everywhere, and are passed around
together between multiple functions; they belong together in a struct,
call that struct flag_settings.

Use struct flag_settings to rework 3 functions:
- ddebug_exec_query - declares query and flag-settings,
calls other 2, passing flags
- ddebug_parse_flags - fills flag_settings and returns
- ddebug_change - test all callsites against query,
modify passing sites.

benefits:
- bit-banging always needs flags & mask, best together.
- simpler function signatures
- 1 less parameter, less stack overhead

no functional changes

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 45 ++++++++++++++++++++++++---------------------
1 file changed, 24 insertions(+), 21 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index fad6c34c930d..c983049e986d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -62,6 +62,11 @@ struct ddebug_iter {
unsigned int idx;
};

+struct flag_settings {
+ unsigned int flags;
+ unsigned int mask;
+};
+
static DEFINE_MUTEX(ddebug_lock);
static LIST_HEAD(ddebug_tables);
static int verbose;
@@ -141,7 +146,7 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
* logs the changes. Takes ddebug_lock.
*/
static int ddebug_change(const struct ddebug_query *query,
- unsigned int flags, unsigned int mask)
+ struct flag_settings *modifiers)
{
int i;
struct ddebug_table *dt;
@@ -190,14 +195,14 @@ static int ddebug_change(const struct ddebug_query *query,

nfound++;

- newflags = (dp->flags & mask) | flags;
+ newflags = (dp->flags & modifiers->mask) | modifiers->flags;
if (newflags == dp->flags)
continue;
#ifdef CONFIG_JUMP_LABEL
if (dp->flags & _DPRINTK_FLAGS_PRINT) {
- if (!(flags & _DPRINTK_FLAGS_PRINT))
+ if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
static_branch_disable(&dp->key.dd_key_true);
- } else if (flags & _DPRINTK_FLAGS_PRINT)
+ } else if (modifiers->flags & _DPRINTK_FLAGS_PRINT)
static_branch_enable(&dp->key.dd_key_true);
#endif
dp->flags = newflags;
@@ -431,11 +436,9 @@ static int ddebug_parse_query(char *words[], int nwords,
* flags fields of matched _ddebug's. Returns 0 on success
* or <0 on error.
*/
-static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
- unsigned int *maskp)
+static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
{
- unsigned flags = 0;
- int op = '=', i;
+ int op, i;

switch (*str) {
case '+':
@@ -452,7 +455,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
for (; *str ; ++str) {
for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
if (*str == opt_array[i].opt_char) {
- flags |= opt_array[i].flag;
+ modifiers->flags |= opt_array[i].flag;
break;
}
}
@@ -461,30 +464,30 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
return -EINVAL;
}
}
- vpr_info("flags=0x%x\n", flags);
+ vpr_info("flags=0x%x\n", modifiers->flags);

- /* calculate final *flagsp, *maskp according to mask and op */
+ /* calculate final flags, mask based upon op */
switch (op) {
case '=':
- *maskp = 0;
- *flagsp = flags;
+ /* modifiers->flags already set */
+ modifiers->mask = 0;
break;
case '+':
- *maskp = ~0U;
- *flagsp = flags;
+ modifiers->mask = ~0U;
break;
case '-':
- *maskp = ~flags;
- *flagsp = 0;
+ modifiers->mask = ~modifiers->flags;
+ modifiers->flags = 0;
break;
}
- vpr_info("*flagsp=0x%x *maskp=0x%x\n", *flagsp, *maskp);
+ vpr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
+
return 0;
}

static int ddebug_exec_query(char *query_string, const char *modname)
{
- unsigned int flags = 0, mask = 0;
+ struct flag_settings modifiers = {};
struct ddebug_query query = {};
#define MAXWORDS 9
int nwords, nfound;
@@ -496,7 +499,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
return -EINVAL;
}
/* check flags 1st (last arg) so query is pairs of spec,val */
- if (ddebug_parse_flags(words[nwords-1], &flags, &mask)) {
+ if (ddebug_parse_flags(words[nwords-1], &modifiers)) {
pr_err("flags parse failed\n");
return -EINVAL;
}
@@ -505,7 +508,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
return -EINVAL;
}
/* actually go and implement the change */
- nfound = ddebug_change(&query, flags, mask);
+ nfound = ddebug_change(&query, &modifiers);
vpr_info_dq(&query, nfound ? "applied" : "no-match");

return nfound;
--
2.26.2

2020-07-19 23:12:50

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 16/18] dyndbg: allow anchored match on format query term

This should work:

echo module=amd* format=^[IF_TRACE]: +p >/proc/dynamic_debug/control

consider drivers/gpu/drm/amd/display/include/logger_types.h:
It has 11 defines like:

#define DC_LOG_IF_TRACE(...) pr_debug("[IF_TRACE]:"__VA_ARGS__)

These defines are used 804 times at recent count; they are a good use
case to evaluate existing format-message based classifications of
*pr_debug*. Those macros prefix the supplied format with a fixed
string, I'd expect most existing message classification schemes to do
something similar.

Hence we want to be able to anchor our match to the beginning of the
format string, allowing easy construction of clear and precise
queries, leveraging the existing classification scheme to enable and
disable those callsites.

Note that unlike other search terms, formats are implicitly floating
substring matches, without the need for explicit wildcards.

This makes no attempt at wider regex features, just the one we need.

TLDR: Using the anchor also means the []s are less helpful for
disamiguating the prefix from a random in-message occurrence, allowing
shorter prefixes.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 13 ++++++++++---
1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c983049e986d..c72bb4d2eb7e 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -181,9 +181,16 @@ static int ddebug_change(const struct ddebug_query *query,
continue;

/* match against the format */
- if (query->format &&
- !strstr(dp->format, query->format))
- continue;
+ if (query->format) {
+ if (*query->format == '^') {
+ char *p;
+ /* anchored search. match must be at beginning */
+ p = strstr(dp->format, query->format+1);
+ if (p != dp->format)
+ continue;
+ } else if (!strstr(dp->format, query->format))
+ continue;
+ }

/* match against the line number range */
if (query->first_lineno &&
--
2.26.2

2020-07-19 23:13:43

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 14/18] dyndbg: accept query terms like file=bar and module=foo

Current code expects "keyword" "arg" as 2 words, space separated.
Change to also accept "keyword=arg" form as well, and drop !(nwords%2)
requirement. Then in rest of function, use new keyword, arg variables
instead of word[i], word[i+1]

Signed-off-by: Jim Cromie <[email protected]>
---
.../admin-guide/dynamic-debug-howto.rst | 1 +
lib/dynamic_debug.c | 53 ++++++++++++-------
2 files changed, 34 insertions(+), 20 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 6c04aea8f4cd..e5a8def45f3f 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -156,6 +156,7 @@ against. Possible keywords are:::
``line-range`` cannot contain space, e.g.
"1-30" is valid range but "1 - 30" is not.

+ ``module=foo`` combined keyword=value form is interchangably accepted

The meanings of each keyword are:

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 7eb963b1bd11..fad6c34c930d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -341,7 +341,8 @@ static int check_set(const char **dest, char *src, char *name)

/*
* Parse words[] as a ddebug query specification, which is a series
- * of (keyword, value) pairs chosen from these possibilities:
+ * of (keyword, value) pairs or combined keyword=value terms,
+ * chosen from these possibilities:
*
* func <function-name>
* file <full-pathname>
@@ -360,22 +361,34 @@ static int ddebug_parse_query(char *words[], int nwords,
unsigned int i;
int rc = 0;
char *fline;
-
- /* check we have an even number of words */
- if (nwords % 2 != 0) {
- pr_err("expecting pairs of match-spec <value>\n");
- return -EINVAL;
- }
+ char *keyword, *arg;

if (modname)
/* support $modname.dyndbg=<multiple queries> */
query->module = modname;

- for (i = 0; i < nwords; i += 2) {
- if (!strcmp(words[i], "func")) {
- rc = check_set(&query->function, words[i+1], "func");
- } else if (!strcmp(words[i], "file")) {
- if (check_set(&query->filename, words[i+1], "file"))
+ for (i = 0; i < nwords; i++) {
+ /* accept keyword=arg */
+ vpr_info("%d w:%s\n", i, words[i]);
+
+ keyword = words[i];
+ arg = strchr(keyword, '=');
+ if (arg) {
+ *arg++ = '\0';
+ } else {
+ i++; /* next word is arg */
+ if (!(i < nwords)) {
+ pr_err("missing arg to keyword: %s\n", keyword);
+ return -EINVAL;
+ }
+ arg = words[i];
+ }
+ vpr_info("%d key:%s arg:%s\n", i, keyword, arg);
+
+ if (!strcmp(keyword, "func")) {
+ rc = check_set(&query->function, arg, "func");
+ } else if (!strcmp(keyword, "file")) {
+ if (check_set(&query->filename, arg, "file"))
return -EINVAL;

/* tail :$info is function or line-range */
@@ -391,18 +404,18 @@ static int ddebug_parse_query(char *words[], int nwords,
if (parse_linerange(query, fline))
return -EINVAL;
}
- } else if (!strcmp(words[i], "module")) {
- rc = check_set(&query->module, words[i+1], "module");
- } else if (!strcmp(words[i], "format")) {
- string_unescape_inplace(words[i+1], UNESCAPE_SPACE |
+ } else if (!strcmp(keyword, "module")) {
+ rc = check_set(&query->module, arg, "module");
+ } else if (!strcmp(keyword, "format")) {
+ string_unescape_inplace(arg, UNESCAPE_SPACE |
UNESCAPE_OCTAL |
UNESCAPE_SPECIAL);
- rc = check_set(&query->format, words[i+1], "format");
- } else if (!strcmp(words[i], "line")) {
- if (parse_linerange(query, words[i+1]))
+ rc = check_set(&query->format, arg, "format");
+ } else if (!strcmp(keyword, "line")) {
+ if (parse_linerange(query, arg))
return -EINVAL;
} else {
- pr_err("unknown keyword \"%s\"\n", words[i]);
+ pr_err("unknown keyword \"%s\"\n", keyword);
return -EINVAL;
}
if (rc)
--
2.26.2

2020-07-19 23:13:57

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 04/18] dyndbg: refine debug verbosity; 1 is basic, 2 more chatty

The verbose/debug logging done for `cat $MNT/dynamic_debug/control` is
voluminous (2 per control file entry + 2 per PAGE). Moreover, it just
prints pointer and sequence, which is not useful to a dyndbg user.
So just drop them.

Also require verbose>=2 for several other debug printks that are a bit
too chatty for typical needs;

ddebug_change() prints changes, once per modified callsite. Since
queries like "+p" will enable ~2300 callsites in a typical laptop, a
user probably doesn't need to see them often. ddebug_exec_queries()
still summarizes with verbose=1.

ddebug_(add|remove)_module() also print 1 line per action on a module,
not needed by typical modprobe user.

This leaves verbose=1 better focussed on the >control parsing process.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 21 ++++++++-------------
1 file changed, 8 insertions(+), 13 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 2989a590ce9a..c97872cffc8e 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -105,12 +105,15 @@ static char *ddebug_describe_flags(struct _ddebug *dp, char *buf,
return buf;
}

-#define vpr_info(fmt, ...) \
+#define vnpr_info(lvl, fmt, ...) \
do { \
- if (verbose) \
+ if (verbose >= lvl) \
pr_info(fmt, ##__VA_ARGS__); \
} while (0)

+#define vpr_info(fmt, ...) vnpr_info(1, fmt, ##__VA_ARGS__)
+#define v2pr_info(fmt, ...) vnpr_info(2, fmt, ##__VA_ARGS__)
+
static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
{
/* trim any trailing newlines */
@@ -198,7 +201,7 @@ static int ddebug_change(const struct ddebug_query *query,
static_branch_enable(&dp->key.dd_key_true);
#endif
dp->flags = newflags;
- vpr_info("changed %s:%d [%s]%s =%s\n",
+ v2pr_info("changed %s:%d [%s]%s =%s\n",
trim_prefix(dp->filename), dp->lineno,
dt->mod_name, dp->function,
ddebug_describe_flags(dp, flagbuf,
@@ -771,8 +774,6 @@ static void *ddebug_proc_start(struct seq_file *m, loff_t *pos)
struct _ddebug *dp;
int n = *pos;

- vpr_info("called m=%p *pos=%lld\n", m, (unsigned long long)*pos);
-
mutex_lock(&ddebug_lock);

if (!n)
@@ -795,9 +796,6 @@ static void *ddebug_proc_next(struct seq_file *m, void *p, loff_t *pos)
struct ddebug_iter *iter = m->private;
struct _ddebug *dp;

- vpr_info("called m=%p p=%p *pos=%lld\n",
- m, p, (unsigned long long)*pos);
-
if (p == SEQ_START_TOKEN)
dp = ddebug_iter_first(iter);
else
@@ -818,8 +816,6 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
struct _ddebug *dp = p;
char flagsbuf[10];

- vpr_info("called m=%p p=%p\n", m, p);
-
if (p == SEQ_START_TOKEN) {
seq_puts(m,
"# filename:lineno [module]function flags format\n");
@@ -842,7 +838,6 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
*/
static void ddebug_proc_stop(struct seq_file *m, void *p)
{
- vpr_info("called m=%p p=%p\n", m, p);
mutex_unlock(&ddebug_lock);
}

@@ -905,7 +900,7 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
list_add_tail(&dt->link, &ddebug_tables);
mutex_unlock(&ddebug_lock);

- vpr_info("%u debug prints in module %s\n", n, dt->mod_name);
+ v2pr_info("%u debug prints in module %s\n", n, dt->mod_name);
return 0;
}

@@ -964,7 +959,7 @@ int ddebug_remove_module(const char *mod_name)
struct ddebug_table *dt, *nextdt;
int ret = -ENOENT;

- vpr_info("removing module \"%s\"\n", mod_name);
+ v2pr_info("removing module \"%s\"\n", mod_name);

mutex_lock(&ddebug_lock);
list_for_each_entry_safe(dt, nextdt, &ddebug_tables, link) {
--
2.26.2

2020-07-19 23:14:00

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 07/18] dyndbg: fix a BUG_ON in ddebug_describe_flags

ddebug_describe_flags() currently fills a caller provided string buffer,
after testing its size (also passed) in a BUG_ON. Fix this by
replacing them with a known-big-enough string buffer wrapped in a
struct, and passing that instead.

Also simplify ddebug_describe_flags() flags parameter from a struct to
a member in that struct, and hoist the member deref up to the caller.
This makes the function reusable (soon) where flags are unpacked.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 23 +++++++++++------------
1 file changed, 11 insertions(+), 12 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 9b2445507988..0cb5679f6c54 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -87,22 +87,22 @@ static struct { unsigned flag:8; char opt_char; } opt_array[] = {
{ _DPRINTK_FLAGS_NONE, '_' },
};

+struct flagsbuf { char buf[ARRAY_SIZE(opt_array)+1]; };
+
/* format a string into buf[] which describes the _ddebug's flags */
-static char *ddebug_describe_flags(struct _ddebug *dp, char *buf,
- size_t maxlen)
+static char *ddebug_describe_flags(unsigned int flags, struct flagsbuf *fb)
{
- char *p = buf;
+ char *p = fb->buf;
int i;

- BUG_ON(maxlen < 6);
for (i = 0; i < ARRAY_SIZE(opt_array); ++i)
- if (dp->flags & opt_array[i].flag)
+ if (flags & opt_array[i].flag)
*p++ = opt_array[i].opt_char;
- if (p == buf)
+ if (p == fb->buf)
*p++ = '_';
*p = '\0';

- return buf;
+ return fb->buf;
}

#define vnpr_info(lvl, fmt, ...) \
@@ -147,7 +147,7 @@ static int ddebug_change(const struct ddebug_query *query,
struct ddebug_table *dt;
unsigned int newflags;
unsigned int nfound = 0;
- char flagbuf[10];
+ struct flagsbuf fbuf;

/* search for matching ddebugs */
mutex_lock(&ddebug_lock);
@@ -204,8 +204,7 @@ static int ddebug_change(const struct ddebug_query *query,
v2pr_info("changed %s:%d [%s]%s =%s\n",
trim_prefix(dp->filename), dp->lineno,
dt->mod_name, dp->function,
- ddebug_describe_flags(dp, flagbuf,
- sizeof(flagbuf)));
+ ddebug_describe_flags(dp->flags, &fbuf));
}
}
mutex_unlock(&ddebug_lock);
@@ -814,7 +813,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
{
struct ddebug_iter *iter = m->private;
struct _ddebug *dp = p;
- char flagsbuf[10];
+ struct flagsbuf flags;

if (p == SEQ_START_TOKEN) {
seq_puts(m,
@@ -825,7 +824,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
seq_printf(m, "%s:%u [%s]%s =%s \"",
trim_prefix(dp->filename), dp->lineno,
iter->table->mod_name, dp->function,
- ddebug_describe_flags(dp, flagsbuf, sizeof(flagsbuf)));
+ ddebug_describe_flags(dp->flags, &flags));
seq_escape(m, dp->format, "\t\r\n\"");
seq_puts(m, "\"\n");

--
2.26.2

2020-07-19 23:14:30

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 13/18] dyndbg: accept 'file foo.c:func1' and 'file foo.c:10-100'

Accept these additional query forms:

echo "file $filestr +_" > control

path/to/file.c:100 # as from control, column 1
path/to/file.c:1-100 # or any legal line-range
path/to/file.c:func_A # as from an editor/browser
path/to/file.c:drm_* # wildcards still work
path/to/file.c:*_foo # lead wildcard too

1st 2 examples are treated as line-ranges, 3-5 are treated as func's

Doc these changes, and sprinkle in a few extra wild-card examples and
trailing # explanation texts.

Signed-off-by: Jim Cromie <[email protected]>
---
.../admin-guide/dynamic-debug-howto.rst | 5 +++++
lib/dynamic_debug.c | 18 +++++++++++++++++-
2 files changed, 22 insertions(+), 1 deletion(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index 1423af580bed..6c04aea8f4cd 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -164,6 +164,7 @@ func
of each callsite. Example::

func svc_tcp_accept
+ func *recv* # in rfcomm, bluetooth, ping, tcp

file
The given string is compared against either the src-root relative
@@ -172,6 +173,9 @@ file

file svcsock.c
file kernel/freezer.c # ie column 1 of control file
+ file drivers/usb/* # all callsites under it
+ file inode.c:start_* # parse :tail as a func (above)
+ file inode.c:1-100 # parse :tail as a line-range (above)

module
The given string is compared against the module name
@@ -181,6 +185,7 @@ module

module sunrpc
module nfsd
+ module drm* # both drm, drm_kms_helper

format
The given string is searched for in the dynamic debug format
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 7a66d5e07f41..7eb963b1bd11 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -359,6 +359,7 @@ static int ddebug_parse_query(char *words[], int nwords,
{
unsigned int i;
int rc = 0;
+ char *fline;

/* check we have an even number of words */
if (nwords % 2 != 0) {
@@ -374,7 +375,22 @@ static int ddebug_parse_query(char *words[], int nwords,
if (!strcmp(words[i], "func")) {
rc = check_set(&query->function, words[i+1], "func");
} else if (!strcmp(words[i], "file")) {
- rc = check_set(&query->filename, words[i+1], "file");
+ if (check_set(&query->filename, words[i+1], "file"))
+ return -EINVAL;
+
+ /* tail :$info is function or line-range */
+ fline = strchr(query->filename, ':');
+ if (!fline)
+ break;
+ *fline++ = '\0';
+ if (isalpha(*fline) || *fline == '*' || *fline == '?') {
+ /* take as function name */
+ if (check_set(&query->function, fline, "func"))
+ return -EINVAL;
+ } else {
+ if (parse_linerange(query, fline))
+ return -EINVAL;
+ }
} else if (!strcmp(words[i], "module")) {
rc = check_set(&query->module, words[i+1], "module");
} else if (!strcmp(words[i], "format")) {
--
2.26.2

2020-07-19 23:14:49

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 09/18] dyndbg: prefer declarative init in caller, to memset in callee

ddebug_exec_query declares an auto var, and passes it to
ddebug_parse_query, which memsets it before using it. Drop that
memset, instead initialize the variable in the caller; let the
compiler decide how to do it.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 3 +--
1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 1d25a846553b..da3ed54a6521 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -330,7 +330,6 @@ static int ddebug_parse_query(char *words[], int nwords,
pr_err("expecting pairs of match-spec <value>\n");
return -EINVAL;
}
- memset(query, 0, sizeof(*query));

if (modname)
/* support $modname.dyndbg=<multiple queries> */
@@ -448,7 +447,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
static int ddebug_exec_query(char *query_string, const char *modname)
{
unsigned int flags = 0, mask = 0;
- struct ddebug_query query;
+ struct ddebug_query query = {};
#define MAXWORDS 9
int nwords, nfound;
char *words[MAXWORDS];
--
2.26.2

2020-07-19 23:14:53

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 17/18] dyndbg: shorten our logging prefix, drop __func__

For log-message output, reduce column space consumed by current
pr_fmt by dropping __func__ and shortening "dynamic_debug" to
"dyndbg". This improves readability on narrow consoles, and better
matches other kernel boot info messages.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c72bb4d2eb7e..e87b630bd793 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -11,7 +11,7 @@
* Copyright (C) 2013 Du, Changbin <[email protected]>
*/

-#define pr_fmt(fmt) KBUILD_MODNAME ":%s: " fmt, __func__
+#define pr_fmt(fmt) "dyndbg: " fmt

#include <linux/kernel.h>
#include <linux/module.h>
--
2.26.2

2020-07-19 23:15:06

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 18/18] dyndbg: export ddebug_exec_queries

Export ddebug_exec_queries() for use by modules.

This will allow module authors to control all their *pr_debug*s
dynamically. And since ddebug_exec_queries() is what implements
"echo $query >control", it gives the same per-callsite control.

Virtues of this:
- simplicity. just an export.
- full control over any/all subsets of callsites.
- same "query/command-string" in code and console
- full callsite selectivity with module file line format

Format in particular deserves special attention; it is where
low-hanging fruit will be found.

Consider: drivers/gpu/drm/amd/display/include/logger_types.h:

#define DC_LOG_SURFACE(...) pr_debug("[SURFACE]:"__VA_ARGS__)
#define DC_LOG_HW_LINK_TRAINING(...) pr_debug("[HW_LINK_TRAINING]:"__VA_ARGS__)
.. 9 more ..

Thats 11 string prefixes, used in 804 places in drivers/gpu/**
Clearly this is a systematized classification of those callsites.
And one I'd expect to see repeated often.

Using ddebug_exec_queries(), authors can select on those prefixes
as a unitary set, equivalent to:

echo "module=MODULE_NAME format=^[SURFACE]: +p" >control

Trivially, those sets can be subsected with the other query terms too,
say file=foo, should the author see fit.

Perhaps as important, users can modify the set of enabled callsites,
presumably to aid debugging by enabling helpful debug callsites, and
disabling those that just clutter the info.

Authors could even alter [fmlt] flags, though I dont see a good reason
why they would. Perhaps harnessed by bug-logging automation to get
fuller, or more minimal bug-reports.

DRM

drm has both drm.debug, which defines 32 categories of drm_printk
logging, and entirely separate uses of pr_debug, which are dynamic on
this i915 laptop, running mainline. So I can observe and report on
both.

The i915 driver has 118 dyndbg callsites, with following
"classifications" defined in drivers/gpu/drm/i915/gvt/**

$ grep 915 /proc/dynamic_debug/control | cut -d= -f2 | cut -d: -f1,2 | sort -u
_ "gvt: cmd
_ "gvt: core
_ "gvt: dpy
_ "gvt: el
_ "gvt: irq
_ "gvt: mm
_ "gvt: mmio
_ "gvt: render
_ "gvt: sched
_ "%s for root hub!\012"
_ "Vendor defined info completion code %u\012"

This classification is entirely out-of-band for control by drm.debug,
and is only available to root user at the console. But module authors
can activate them with ddebug_exec_queries(sprintf("format=^%s +p")),
and then decide how to expose the groups to the user for max utility.

drm.debug

drm.debug has 32 bit-flags, and matching enum drm_debug_category
values to classify the ~2943 DRM_DEBUG*() callsites in drivers/gpu

The drm.debug callback could invoke ddebug_exec_queries() with 32
different hardcoded query strings, needing only (bit) ? " +p" : " -p"
added.

I briefly enabled drm.debug=0xff on my i915 laptop, which yielded
these unique prefixes: (dmesg | cut -c17- | cut -d\] -f1 | sort -u)

[drm:drm_atomic_check_only [drm
[drm:drm_atomic_get_crtc_state [drm
[drm:drm_atomic_get_plane_state [drm
[drm:drm_atomic_nonblocking_commit [drm
[drm:drm_atomic_set_fb_for_plane [drm
[drm:drm_atomic_state_default_clear [drm
[drm:__drm_atomic_state_free [drm
[drm:drm_atomic_state_init [drm
[drm:drm_crtc_vblank_helper_get_vblank_timestamp_internal [drm
[drm:drm_handle_vblank [drm
[drm:drm_ioctl [drm
[drm:drm_mode_addfb2 [drm
[drm:drm_mode_object_get [drm
[drm:drm_mode_object_put.part.0 [drm
[drm:drm_update_vblank_count [drm
[drm:drm_vblank_enable [drm
[drm:drm_vblank_restore [drm
[drm:vblank_disable_fn [drm
i915 0000:00:02.0: [drm:gen9_set_dc_state [i915
i915 0000:00:02.0: [drm:intel_atomic_get_global_obj_state [i915
i915 0000:00:02.0: [drm:__intel_display_power_get_domain.part.0 [i915
i915 0000:00:02.0: [drm:__intel_display_power_put_domain [i915
i915 0000:00:02.0: [drm:intel_plane_atomic_calc_changes [i915
i915 0000:00:02.0: [drm:skl_enable_dc6 [i915

Several good format=^prefixes are apparent there, and some misses.

^[drm:drm_atomic_ # misses: [drm:__drm_atomic_state_free [drm
^[drm:drm_ioctl
^[drm:drm_mode
^[drm:drm_vblank_ # misses: [drm:drm_update_vblank_count & [drm:vblank_disable_fn

Its not a perfect 1:1 single format-match per class, but the misses
above can be covered with 1 & 2 additional queries, which can be
concatenated together with ";" separators and submitted with 1 call.

Benefits:

For drm, adapting DRM_DEBUG to use dynamic-debug inside could
replicate (and thereby obsolete) lots of bit-checking in current
DRM_DEBUG callsites, at least with JUMP_LABEL optimized code.
ddebug_exec_queries() and a handful of fixed query-strings can select
and thereby control the already classified callsites.

With the classes mapped to queries, the enum type and parameter can be
eliminated (folded away with macro magic), at least for DYNAMIC_DEBUG
& JUMP_LABEL builds.

Is it safe ?

ddebug_exec_queries() is currently exposed to user space in
several limited ways;

1 it is called from module-load callback, where it implements the
$modname.dyndbg=+p "fake" parameter provided to all modules.

2 it handles query input via >control directly

IOW, it is "fully" exposed to local root user; exposing the same
functionality to other kernel modules is no additional risk.

The other standard issue to check is locking:

dyndbg has a single mutex, taken by ddebug_change to handle >control,
and by ddebug_proc_(start|stop) to span `cat control`. Queries
submitted via export will typically have module specified, which
dramatically cuts the scan by ddebug_change vs "module=* +p".
ISTM this proposed export presents no locking problems.

TLDR;

It would be interesting to see how drm.dyndbg=$QUERY and
drm.debug=$HEXY would interact; it might be order dependent, as
if given as modprobe args or in /etc/modprobe.d/

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index e87b630bd793..1d012e597cc3 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -525,7 +525,7 @@ static int ddebug_exec_query(char *query_string, const char *modname)
last error or number of matching callsites. Module name is either
in param (for boot arg) or perhaps in query string.
*/
-static int ddebug_exec_queries(char *query, const char *modname)
+int ddebug_exec_queries(char *query, const char *modname)
{
char *split;
int i, errs = 0, exitcode = 0, rc, nfound = 0;
@@ -557,6 +557,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
return exitcode;
return nfound;
}
+EXPORT_SYMBOL_GPL(ddebug_exec_queries);

#define PREFIX_SIZE 64

--
2.26.2

2020-07-19 23:15:41

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 11/18] dyndbg: use gcc ?: to reduce word count

reduce word count via gcc ?: extension, no actual code change.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index e879af4e66e0..6d0159075308 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -127,10 +127,10 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)

vpr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u\n",
msg,
- query->function ? query->function : "",
- query->filename ? query->filename : "",
- query->module ? query->module : "",
- fmtlen, query->format ? query->format : "",
+ query->function ?: "",
+ query->filename ?: "",
+ query->module ?: "",
+ fmtlen, query->format ?: "",
query->first_lineno, query->last_lineno);
}

--
2.26.2

2020-07-19 23:15:44

by Jim Cromie

[permalink] [raw]
Subject: [PATCH v5 08/18] dyndbg: fix pr_err with empty string

this pr_err attempts to print the string after the OP, but the string
has been parsed and chopped up, so looks empty.

Signed-off-by: Jim Cromie <[email protected]>
---
lib/dynamic_debug.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 0cb5679f6c54..1d25a846553b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -420,7 +420,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
}
}
if (i < 0) {
- pr_err("unknown flag '%c' in \"%s\"\n", *str, str);
+ pr_err("unknown flag '%c'\n", *str);
return -EINVAL;
}
}
--
2.26.2

2020-07-24 13:49:52

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH v5 00/18] dynamic_debug fixes, cleanups, features, export



On 7/19/20 7:10 PM, Jim Cromie wrote:
> this is v5, changes from previous:
> - moved a chunk from patch 13 to 12, per Jason
> - shorten logging prefix to "dyndbg", drop __func__
> - now with more commit-log advocacy
> - shuffle EXPORT_GPL(ddebug_exec_queries) last.
> - v4+ series Acked-by: [email protected]

Yes, series looks good to me:
Acked-by: <[email protected]>

Greg, what do you think about pulling in this series?

Thanks,

-Jason

>
> v4: https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_lkml_20200620180643.887546-2D1-2Djim.cromie-40gmail.com_&d=DwIDAg&c=96ZbZZcaMF4w0F4jpN6LZg&r=1fLh1mlLqbfetnnGsbwXfpwmGlG4m83mXgtV4vZ1B1A&m=Fx_Nr_SBO_RxVITjMD8U8davIy4lmiMx9iQ0RiHncbw&s=Yk6jd9kp4ASId49a5PYXxFrYDDDw8eD595yeyH8JOrU&e=
> v3: https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_lkml_20200617162536.611386-2D1-2Djim.cromie-40gmail.com_&d=DwIDAg&c=96ZbZZcaMF4w0F4jpN6LZg&r=1fLh1mlLqbfetnnGsbwXfpwmGlG4m83mXgtV4vZ1B1A&m=Fx_Nr_SBO_RxVITjMD8U8davIy4lmiMx9iQ0RiHncbw&s=fwZUOLHfC4rKPBAanu69vs_StJyGBUag2iMQm7l9k5s&e=
> v2: https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_lkml_20200613155738.2249399-2D1-2Djim.cromie-40gmail.com_&d=DwIDAg&c=96ZbZZcaMF4w0F4jpN6LZg&r=1fLh1mlLqbfetnnGsbwXfpwmGlG4m83mXgtV4vZ1B1A&m=Fx_Nr_SBO_RxVITjMD8U8davIy4lmiMx9iQ0RiHncbw&s=Xwb7nTFjQ7rmEnEQXARt_J5EV8Jy2lRMq4PiKKBfWeE&e=
> v1: https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_lkml_20200605162645.289174-2D1-2Djim.cromie-40gmail.com_&d=DwIDAg&c=96ZbZZcaMF4w0F4jpN6LZg&r=1fLh1mlLqbfetnnGsbwXfpwmGlG4m83mXgtV4vZ1B1A&m=Fx_Nr_SBO_RxVITjMD8U8davIy4lmiMx9iQ0RiHncbw&s=09pJ7MRxLOyDjzN2yYYEOrqP0HtPJZPWLL9rVhKj1EI&e=
>
>
> Patchset starts with cleanups;
> - change section name from vague "__verbose" to specific "__dyndbg"
> - cleaner docs, drop obsolete comment & useless debug prints,
> - refine verbose/debug logging
> - fix a BUG_ON, ram reporting miscounts. etc..
>
> Then adds query parsing conveniences
> - allow "file inode.c:100-200" # combined file & line-range
> - allow "file inode.c:start_*" # file & function
> - accept "module=foo" query form
>
> internal improvement
> - combine flags & mask in a struct, clean 3 func interfaces with it.
>
> make precise format queries easier
> - accept "format=^ClassString" anchored query
>
> finally, EXPORT_GPL(ddebug_exec_queries)
>
> This gives module authors complete run-time control over all their
> *pr_debug* callsites (when CONFIG_DYNAMIC_DEBUG=y).
>
> Following the drm.debug UI model, drm.debug_chan2 could be wired to a
> callback which invokes ddebug_exec_queries to toggle arbitary groups
> of pr_debug callsites.
>
> Useful callsite groups would exploit existing message-prefix
> classifcation schemes:
>
> "format=^[IF_TRACE]: +p; format=^[SURFACE]: +p" >control
>
>
> Jim Cromie (18):
> dyndbg-docs: eschew file /full/path query in docs
> dyndbg-docs: initialization is done early, not arch
> dyndbg: drop obsolete comment on ddebug_proc_open
> dyndbg: refine debug verbosity; 1 is basic, 2 more chatty
> dyndbg: rename __verbose section to __dyndbg
> dyndbg: fix overcounting of ram used by dyndbg
> dyndbg: fix a BUG_ON in ddebug_describe_flags
> dyndbg: fix pr_err with empty string
> dyndbg: prefer declarative init in caller, to memset in callee
> dyndbg: make ddebug_tables list LIFO for add/remove_module
> dyndbg: use gcc ?: to reduce word count
> dyndbg: refactor parse_linerange out of ddebug_parse_query
> dyndbg: accept 'file foo.c:func1' and 'file foo.c:10-100'
> dyndbg: accept query terms like file=bar and module=foo
> dyndbg: combine flags & mask into a struct, simplify with it
> dyndbg: allow anchored match on format query term
> dyndbg: shorten our logging prefix, drop __func__
> dyndbg: export ddebug_exec_queries
>
> .../admin-guide/dynamic-debug-howto.rst | 29 +-
> include/asm-generic/vmlinux.lds.h | 6 +-
> include/linux/dynamic_debug.h | 4 +-
> kernel/module.c | 2 +-
> lib/dynamic_debug.c | 269 ++++++++++--------
> 5 files changed, 173 insertions(+), 137 deletions(-)
>

2020-07-24 15:01:39

by Greg Kroah-Hartman

[permalink] [raw]
Subject: Re: [PATCH v5 00/18] dynamic_debug fixes, cleanups, features, export

On Fri, Jul 24, 2020 at 09:48:54AM -0400, Jason Baron wrote:
>
>
> On 7/19/20 7:10 PM, Jim Cromie wrote:
> > this is v5, changes from previous:
> > - moved a chunk from patch 13 to 12, per Jason
> > - shorten logging prefix to "dyndbg", drop __func__
> > - now with more commit-log advocacy
> > - shuffle EXPORT_GPL(ddebug_exec_queries) last.
> > - v4+ series Acked-by: [email protected]
>
> Yes, series looks good to me:
> Acked-by: <[email protected]>
>
> Greg, what do you think about pulling in this series?

Me? Am I the one who takes these patches?

Ok, will do, give me a few hours...

thanks,

greg k-h

2020-07-24 15:03:16

by Greg Kroah-Hartman

[permalink] [raw]
Subject: Re: [PATCH v5 00/18] dynamic_debug fixes, cleanups, features, export

On Fri, Jul 24, 2020 at 04:59:00PM +0200, Greg KH wrote:
> On Fri, Jul 24, 2020 at 09:48:54AM -0400, Jason Baron wrote:
> >
> >
> > On 7/19/20 7:10 PM, Jim Cromie wrote:
> > > this is v5, changes from previous:
> > > - moved a chunk from patch 13 to 12, per Jason
> > > - shorten logging prefix to "dyndbg", drop __func__
> > > - now with more commit-log advocacy
> > > - shuffle EXPORT_GPL(ddebug_exec_queries) last.
> > > - v4+ series Acked-by: [email protected]
> >
> > Yes, series looks good to me:
> > Acked-by: <[email protected]>
> >
> > Greg, what do you think about pulling in this series?
>
> Me? Am I the one who takes these patches?
>
> Ok, will do, give me a few hours...

Nevermind, b4 made quick work of that, now queued up, thanks.

greg k-h