[PATCH 0/6] dyndbg updates for 5.15-rcX

[PATCH 0/6] dyndbg updates for 5.15-rcX

[Jim Cromie]

Hi Jason, Greg,

Heres a set of "maintenance" patches distilled out of other work.  Its
almost all tweaks to verbose output, except for 1st, which changes a
strcmp to == because its true, and useful going forward.

Jim Cromie (6):
  dyndbg: recode for stronger precondition
  dyndbg: show module in vpr-info in dd-exec-queries
  dyndbg: rationalize verbosity
  dyndbg: use alt-quotes in vpr-infos, not those user might use
  dyndbg: vpr-info on remove-module complete, not starting
  dyndbg: no vpr-info on empty queries

 .../admin-guide/dynamic-debug-howto.rst       |  2 +-
 lib/dynamic_debug.c                           | 47 ++++++++++---------
 2 files changed, 26 insertions(+), 23 deletions(-)

-- 
2.31.1

[PATCH 1/6] dyndbg: recode for stronger precondition

[Jim Cromie]

The table of struct _ddebugs, due to its construction by the linker,
has an important property; namely that its "equal" fields have actual
ptr-equality, not just strcmp-equality.  Lets recognize that truth in
dynamic_debug_init(), while slicing the builtin table into a
per-module list.
---
 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 cb5abb42c16a..817a87e9c37f 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1101,7 +1101,7 @@ static int __init dynamic_debug_init(void)
 	iter_start = iter;
 	for (; iter < __stop___dyndbg; iter++) {
 		entries++;
-		if (strcmp(modname, iter->modname)) {
+		if (modname != iter->modname) {
 			modct++;
 			ret = ddebug_add_module(iter_start, n, modname);
 			if (ret)
-- 
2.31.1

[PATCH 2/6] dyndbg: show module in vpr-info in dd-exec-queries

[Jim Cromie]

dynamic_debug_exec_queries() accepts a separate module arg (so it can
support $module.dyndbg boot arg), show it in the vpr-info for a more
useful user-debug context.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 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 817a87e9c37f..5403a4515a4a 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -529,7 +529,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		if (!query || !*query || *query == '#')
 			continue;
 
-		vpr_info("query %d: \"%s\"\n", i, query);
+		v2pr_info("query %d: \"%s\" mod:%s\n", i, query, modname ?: "*");
 
 		rc = ddebug_exec_query(query, modname);
 		if (rc < 0) {
-- 
2.31.1

[PATCH 3/6] dyndbg: rationalize verbosity

[Jim Cromie]

change current v*pr_info() calls to fit this new scheme:

-1 module level activity: add/remove, etc
-2 command ingest, splitting
   per >control write
-3 command parsing - many v1s here now
-4 per-site changes - was v2

-2 is new, to isolate a problem where a stress-test script (which
feeds large multi-command strings) would produce short writes,
truncating last command and causing parsing errors, which confused
test results.  The 1st fix was to use syswrite in the script, to
deliver full proper commands.

-4 gets per-callsite "changed:" pr-infos, which are very noisy during
stress tests, and obscure v1-3 messages.

Update docs verbose example to 3 per its comment (potential conflict here)

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 .../admin-guide/dynamic-debug-howto.rst       |  2 +-
 lib/dynamic_debug.c                           | 22 ++++++++++---------
 2 files changed, 13 insertions(+), 11 deletions(-)

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index b119b8277b3e..ab28d200f016 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -358,7 +358,7 @@ Examples
   // boot-args example, with newlines and comments for readability
   Kernel command line: ...
     // see whats going on in dyndbg=value processing
-    dynamic_debug.verbose=1
+    dynamic_debug.verbose=3
     // enable pr_debugs in 2 builtins, #cmt is stripped
     dyndbg="module params +p #cmt ; module sys +p"
     // enable pr_debugs in 2 functions in a module loaded later
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 5403a4515a4a..47286a73fff4 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -118,6 +118,8 @@ do {								\
 
 #define vpr_info(fmt, ...)	vnpr_info(1, fmt, ##__VA_ARGS__)
 #define v2pr_info(fmt, ...)	vnpr_info(2, fmt, ##__VA_ARGS__)
+#define v3pr_info(fmt, ...)	vnpr_info(3, fmt, ##__VA_ARGS__)
+#define v4pr_info(fmt, ...)	vnpr_info(4, fmt, ##__VA_ARGS__)
 
 static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
 {
@@ -130,7 +132,7 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
 			fmtlen--;
 	}
 
-	vpr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u\n",
+	v3pr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u\n",
 		 msg,
 		 query->function ?: "",
 		 query->filename ?: "",
@@ -213,7 +215,7 @@ static int ddebug_change(const struct ddebug_query *query,
 				static_branch_enable(&dp->key.dd_key_true);
 #endif
 			dp->flags = newflags;
-			v2pr_info("changed %s:%d [%s]%s =%s\n",
+			v4pr_info("changed %s:%d [%s]%s =%s\n",
 				 trim_prefix(dp->filename), dp->lineno,
 				 dt->mod_name, dp->function,
 				 ddebug_describe_flags(dp->flags, &fbuf));
@@ -273,7 +275,7 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
 		buf = end;
 	}
 
-	if (verbose) {
+	if (verbose >= 3) {
 		int i;
 		pr_info("split into words:");
 		for (i = 0; i < nwords; i++)
@@ -333,7 +335,7 @@ static int parse_linerange(struct ddebug_query *query, const char *first)
 	} else {
 		query->last_lineno = query->first_lineno;
 	}
-	vpr_info("parsed line %d-%d\n", query->first_lineno,
+	v3pr_info("parsed line %d-%d\n", query->first_lineno,
 		 query->last_lineno);
 	return 0;
 }
@@ -447,7 +449,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 		pr_err("bad flag-op %c, at start of %s\n", *str, str);
 		return -EINVAL;
 	}
-	vpr_info("op='%c'\n", op);
+	v3pr_info("op='%c'\n", op);
 
 	for (; *str ; ++str) {
 		for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
@@ -461,7 +463,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 			return -EINVAL;
 		}
 	}
-	vpr_info("flags=0x%x\n", modifiers->flags);
+	v3pr_info("flags=0x%x\n", modifiers->flags);
 
 	/* calculate final flags, mask based upon op */
 	switch (op) {
@@ -477,7 +479,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 		modifiers->flags = 0;
 		break;
 	}
-	vpr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
+	v3pr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask);
 
 	return 0;
 }
@@ -540,7 +542,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		}
 		i++;
 	}
-	vpr_info("processed %d queries, with %d matches, %d errs\n",
+	v2pr_info("processed %d queries, with %d matches, %d errs\n",
 		 i, nfound, errs);
 
 	if (exitcode)
@@ -781,7 +783,7 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
 	tmpbuf = memdup_user_nul(ubuf, len);
 	if (IS_ERR(tmpbuf))
 		return PTR_ERR(tmpbuf);
-	vpr_info("read %d bytes from userspace\n", (int)len);
+	v2pr_info("read %zu bytes from userspace <\n%s>\n", len, tmpbuf);
 
 	ret = ddebug_exec_queries(tmpbuf, NULL);
 	kfree(tmpbuf);
@@ -969,7 +971,7 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
 	list_add(&dt->link, &ddebug_tables);
 	mutex_unlock(&ddebug_lock);
 
-	v2pr_info("%3u debug prints in module %s\n", n, dt->mod_name);
+	vpr_info("%3u debug prints in module %s\n", n, dt->mod_name);
 	return 0;
 }
 
-- 
2.31.1

[PATCH 4/6] dyndbg: use alt-quotes in vpr-infos, not those user might use

[Jim Cromie]

`echo format $str +p > control` can be finicky with respect to quoting
of input terms, so lets not complicate things by wrapping that input
with either quoting char, using <%s> instead.

no functional changes.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 47286a73fff4..d762bf4172f4 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -132,7 +132,7 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
 			fmtlen--;
 	}
 
-	v3pr_info("%s: func=\"%s\" file=\"%s\" module=\"%s\" format=\"%.*s\" lineno=%u-%u\n",
+	v3pr_info("%s: func=<%s> file=<%s> module=<%s> format=<%.*s> lineno=%u-%u\n",
 		 msg,
 		 query->function ?: "",
 		 query->filename ?: "",
@@ -279,7 +279,7 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
 		int i;
 		pr_info("split into words:");
 		for (i = 0; i < nwords; i++)
-			pr_cont(" \"%s\"", words[i]);
+			pr_cont(" <%s>", words[i]);
 		pr_cont("\n");
 	}
 
@@ -419,7 +419,7 @@ static int ddebug_parse_query(char *words[], int nwords,
 			if (parse_linerange(query, arg))
 				return -EINVAL;
 		} else {
-			pr_err("unknown keyword \"%s\"\n", keyword);
+			pr_err("unknown keyword <%s>\n", keyword);
 			return -EINVAL;
 		}
 		if (rc)
@@ -449,7 +449,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers)
 		pr_err("bad flag-op %c, at start of %s\n", *str, str);
 		return -EINVAL;
 	}
-	v3pr_info("op='%c'\n", op);
+	v3pr_info("op=<%c>\n", op);
 
 	for (; *str ; ++str) {
 		for (i = ARRAY_SIZE(opt_array) - 1; i >= 0; i--) {
@@ -531,7 +531,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		if (!query || !*query || *query == '#')
 			continue;
 
-		v2pr_info("query %d: \"%s\" mod:%s\n", i, query, modname ?: "*");
+		v2pr_info("query %d: <%s> mod:<%s>\n", i, query, modname ?: "*");
 
 		rc = ddebug_exec_query(query, modname);
 		if (rc < 0) {
@@ -1000,7 +1000,7 @@ static int ddebug_dyndbg_param_cb(char *param, char *val,
 static int ddebug_dyndbg_boot_param_cb(char *param, char *val,
 				const char *unused, void *arg)
 {
-	vpr_info("%s=\"%s\"\n", param, val);
+	vpr_info("%s=<%s>\n", param, val);
 	return ddebug_dyndbg_param_cb(param, val, NULL, 0);
 }
 
@@ -1011,7 +1011,7 @@ static int ddebug_dyndbg_boot_param_cb(char *param, char *val,
  */
 int ddebug_dyndbg_module_param_cb(char *param, char *val, const char *module)
 {
-	vpr_info("module: %s %s=\"%s\"\n", module, param, val);
+	vpr_info("module: %s %s=<%s>\n", module, param, val);
 	return ddebug_dyndbg_param_cb(param, val, module, -ENOENT);
 }
 
@@ -1030,7 +1030,7 @@ int ddebug_remove_module(const char *mod_name)
 	struct ddebug_table *dt, *nextdt;
 	int ret = -ENOENT;
 
-	v2pr_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.31.1

[PATCH 5/6] dyndbg: vpr-info on remove-module complete, not starting

[Jim Cromie]

On qemu --smp 3 runs, remove-module can get called 3 times.
Instead, print once at end, if entry was found and removed.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index d762bf4172f4..8230fdc66d9d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1030,8 +1030,6 @@ int ddebug_remove_module(const char *mod_name)
 	struct ddebug_table *dt, *nextdt;
 	int ret = -ENOENT;
 
-	v2pr_info("removing module <%s>\n", mod_name);
-
 	mutex_lock(&ddebug_lock);
 	list_for_each_entry_safe(dt, nextdt, &ddebug_tables, link) {
 		if (dt->mod_name == mod_name) {
@@ -1041,6 +1039,8 @@ int ddebug_remove_module(const char *mod_name)
 		}
 	}
 	mutex_unlock(&ddebug_lock);
+	if (!ret)
+		v2pr_info("removed module <%s>\n", mod_name);
 	return ret;
 }
 
-- 
2.31.1

[PATCH 6/6] dyndbg: no vpr-info on empty queries

[Jim Cromie]

when `echo $cmd > control` contains multiple queries, extra query
separators (;\n) can parse as empty statements.  This is normal, and
pr-info on empty command is just noise.  Also change varname.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 8230fdc66d9d..1b83f8f897c3 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -520,9 +520,9 @@ static int ddebug_exec_query(char *query_string, const char *modname)
 static int ddebug_exec_queries(char *query, const char *modname)
 {
 	char *split;
-	int i, errs = 0, exitcode = 0, rc, nfound = 0;
+	int qct, errs = 0, exitcode = 0, rc, nfound = 0;
 
-	for (i = 0; query; query = split) {
+	for (qct = 0; query; query = split) {
 		split = strpbrk(query, ";\n");
 		if (split)
 			*split++ = '\0';
@@ -531,7 +531,7 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		if (!query || !*query || *query == '#')
 			continue;
 
-		v2pr_info("query %d: <%s> mod:<%s>\n", i, query, modname ?: "*");
+		v2pr_info("query %d: <%s> mod:<%s>\n", qct, query, modname ?: "*");
 
 		rc = ddebug_exec_query(query, modname);
 		if (rc < 0) {
@@ -540,10 +540,11 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		} else {
 			nfound += rc;
 		}
-		i++;
+		qct++;
 	}
-	v2pr_info("processed %d queries, with %d matches, %d errs\n",
-		 i, nfound, errs);
+	if (qct)
+		v2pr_info("processed %d queries, with %d matches, %d errs\n",
+			  qct, nfound, errs);
 
 	if (exitcode)
 		return exitcode;
-- 
2.31.1

Re: [PATCH 0/6] dyndbg updates for 5.15-rcX

[Greg KH]

On Wed, Sep 29, 2021 at 12:37:29PM -0600, Jim Cromie wrote:
> Hi Jason, Greg,
> 
> Heres a set of "maintenance" patches distilled out of other work.  Its
> almost all tweaks to verbose output, except for 1st, which changes a
> strcmp to == because its true, and useful going forward.
> 
> Jim Cromie (6):
>   dyndbg: recode for stronger precondition
>   dyndbg: show module in vpr-info in dd-exec-queries
>   dyndbg: rationalize verbosity
>   dyndbg: use alt-quotes in vpr-infos, not those user might use
>   dyndbg: vpr-info on remove-module complete, not starting
>   dyndbg: no vpr-info on empty queries
> 
>  .../admin-guide/dynamic-debug-howto.rst       |  2 +-
>  lib/dynamic_debug.c                           | 47 ++++++++++---------
>  2 files changed, 26 insertions(+), 23 deletions(-)

Are these real bug fixes that have to get into 5.15-final?  They seem
like 5.16-rc1 patches instead.

thanks,

gre gk-h

Re: [PATCH 1/6] dyndbg: recode for stronger precondition

[Greg KH]

On Wed, Sep 29, 2021 at 12:37:30PM -0600, Jim Cromie wrote:
> The table of struct _ddebugs, due to its construction by the linker,
> has an important property; namely that its "equal" fields have actual
> ptr-equality, not just strcmp-equality.  Lets recognize that truth in
> dynamic_debug_init(), while slicing the builtin table into a
> per-module list.
> ---
>  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 cb5abb42c16a..817a87e9c37f 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -1101,7 +1101,7 @@ static int __init dynamic_debug_init(void)
>  	iter_start = iter;
>  	for (; iter < __stop___dyndbg; iter++) {
>  		entries++;
> -		if (strcmp(modname, iter->modname)) {
> +		if (modname != iter->modname) {
>  			modct++;
>  			ret = ddebug_add_module(iter_start, n, modname);
>  			if (ret)
> -- 
> 2.31.1
> 

Always run checkpatch on a patch so you do not get a grumpy kernel
developer telling you to run checkpatch on your patch :(

I can't take this for the obvious reasons here...

thanks,

greg k-h

Re: [PATCH 3/6] dyndbg: rationalize verbosity

[Greg KH]

On Wed, Sep 29, 2021 at 12:37:32PM -0600, Jim Cromie wrote:
> change current v*pr_info() calls to fit this new scheme:
> 
> -1 module level activity: add/remove, etc
> -2 command ingest, splitting
>    per >control write
> -3 command parsing - many v1s here now
> -4 per-site changes - was v2
> 
> -2 is new, to isolate a problem where a stress-test script (which
> feeds large multi-command strings) would produce short writes,
> truncating last command and causing parsing errors, which confused
> test results.  The 1st fix was to use syswrite in the script, to
> deliver full proper commands.
> 
> -4 gets per-callsite "changed:" pr-infos, which are very noisy during
> stress tests, and obscure v1-3 messages.
> 
> Update docs verbose example to 3 per its comment (potential conflict here)
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
>  .../admin-guide/dynamic-debug-howto.rst       |  2 +-
>  lib/dynamic_debug.c                           | 22 ++++++++++---------
>  2 files changed, 13 insertions(+), 11 deletions(-)
> 
> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
> index b119b8277b3e..ab28d200f016 100644
> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
> @@ -358,7 +358,7 @@ Examples
>    // boot-args example, with newlines and comments for readability
>    Kernel command line: ...
>      // see whats going on in dyndbg=value processing
> -    dynamic_debug.verbose=1
> +    dynamic_debug.verbose=3

Did you just change the user/kernel interface here?  What happens to the
systems that were using '1' as a value?  Do they have to be changed?

Why is this needed?

thanks,

greg k-h

Re: [PATCH 0/6] dyndbg updates for 5.15-rcX

[jim.cromie]

On Thu, Sep 30, 2021 at 12:06 AM Greg KH <gregkh@linuxfoundation.org> wrote:
>
> On Wed, Sep 29, 2021 at 12:37:29PM -0600, Jim Cromie wrote:
> > Hi Jason, Greg,
> >
> > Heres a set of "maintenance" patches distilled out of other work.  Its
> > almost all tweaks to verbose output, except for 1st, which changes a
> > strcmp to == because its true, and useful going forward.
> >
> > Jim Cromie (6):
> >   dyndbg: recode for stronger precondition
> >   dyndbg: show module in vpr-info in dd-exec-queries
> >   dyndbg: rationalize verbosity
> >   dyndbg: use alt-quotes in vpr-infos, not those user might use
> >   dyndbg: vpr-info on remove-module complete, not starting
> >   dyndbg: no vpr-info on empty queries
> >
> >  .../admin-guide/dynamic-debug-howto.rst       |  2 +-
> >  lib/dynamic_debug.c                           | 47 ++++++++++---------
> >  2 files changed, 26 insertions(+), 23 deletions(-)
>
> Are these real bug fixes that have to get into 5.15-final?  They seem
> like 5.16-rc1 patches instead.
>

not real bug fixes.
I thought maybe theyre low-risk enough, maybe on rc1+, but I was late.
I'll try to hit the window right for 5.16



> thanks,
>
> gre gk-h

Re: [PATCH 0/6] dyndbg updates for 5.15-rcX

[Greg KH]

On Thu, Sep 30, 2021 at 03:33:44PM -0600, jim.cromie@gmail.com wrote:
> On Thu, Sep 30, 2021 at 12:06 AM Greg KH <gregkh@linuxfoundation.org> wrote:
> >
> > On Wed, Sep 29, 2021 at 12:37:29PM -0600, Jim Cromie wrote:
> > > Hi Jason, Greg,
> > >
> > > Heres a set of "maintenance" patches distilled out of other work.  Its
> > > almost all tweaks to verbose output, except for 1st, which changes a
> > > strcmp to == because its true, and useful going forward.
> > >
> > > Jim Cromie (6):
> > >   dyndbg: recode for stronger precondition
> > >   dyndbg: show module in vpr-info in dd-exec-queries
> > >   dyndbg: rationalize verbosity
> > >   dyndbg: use alt-quotes in vpr-infos, not those user might use
> > >   dyndbg: vpr-info on remove-module complete, not starting
> > >   dyndbg: no vpr-info on empty queries
> > >
> > >  .../admin-guide/dynamic-debug-howto.rst       |  2 +-
> > >  lib/dynamic_debug.c                           | 47 ++++++++++---------
> > >  2 files changed, 26 insertions(+), 23 deletions(-)
> >
> > Are these real bug fixes that have to get into 5.15-final?  They seem
> > like 5.16-rc1 patches instead.
> >
> 
> not real bug fixes.
> I thought maybe theyre low-risk enough, maybe on rc1+, but I was late.

Then please do not force me to be the one to push back, you know the
development model...

> I'll try to hit the window right for 5.16

So do you want me to pick these up now for my -next branch to get proper
testing in time for 5.16-rc1?

thanks,

greg k-h

Re: [PATCH 3/6] dyndbg: rationalize verbosity

[jim.cromie]

On Thu, Sep 30, 2021 at 12:10 AM Greg KH <gregkh@linuxfoundation.org> wrote:
>
> On Wed, Sep 29, 2021 at 12:37:32PM -0600, Jim Cromie wrote:
> > change current v*pr_info() calls to fit this new scheme:
> >
> > -1 module level activity: add/remove, etc
> > -2 command ingest, splitting
> >    per >control write
> > -3 command parsing - many v1s here now
> > -4 per-site changes - was v2
> >
> > -2 is new, to isolate a problem where a stress-test script (which
> > feeds large multi-command strings) would produce short writes,
> > truncating last command and causing parsing errors, which confused
> > test results.  The 1st fix was to use syswrite in the script, to
> > deliver full proper commands.
> >
> > -4 gets per-callsite "changed:" pr-infos, which are very noisy during
> > stress tests, and obscure v1-3 messages.
> >
> > Update docs verbose example to 3 per its comment (potential conflict here)
...

> > -    dynamic_debug.verbose=1
> > +    dynamic_debug.verbose=3
>
> Did you just change the user/kernel interface here?

I hope not.
pinning specific meanings to verbose=1
STM a pretty tight interpretation.

If it is an issue that it got documented, I added those examples,
so I can at least speak to intent.

commit 29e36c9ffb696ed8d73e1aee713d483ec74a9a43
Author: Jim Cromie <jim.cromie@gmail.com>
Date:   Fri Apr 27 14:30:41 2012 -0600

    dynamic_debug: update Documentation/*, Kconfig.debug

- its a bootargs example
so without the =1, it parses wrong, and elicits a warning -
Booting kernel: `' invalid for parameter `dynamic_debug.verbose'
maybe it should have been a boolean param,
but int seemed more generic, with an intrinsic 0..N range

- as an example, its not really meant to be normative, more helpful.
turning on verbose and leaving it is not intended as a recommendation

Id also plead that --verbose and --debug are the 1st knobs
a user would turn when trying to understand a new tool / command / feature


Also, the verbose knob has already seen some "enhancement"
481c0e33f1e7 dyndbg: refine debug verbosity; 1 is basic, 2 more chatty



What happens to the
> systems that were using '1' as a value?  Do they have to be changed?

verbose changes no operation. Only the feedback after
    echo $bogus_cmd >control

If a user is getting parsing errors, they need to correct the $cmd 1st,
(and enable verbose to see what went wrong when they resubmit the commands.)
expecting a syslog-watcher to backstop that is "unreliable"



>
> Why is this needed?

Ultimately, I needed it cuz I ran the following script against >control,
to pound the crap out of the static_key toggling slow-path.

script hammers hard by writing as many $cmd_off $cmd_on pairs as possible
  echo "$cmd_on; $cmd_off" >control

I found that the Nth cmd was getting truncated, wasnt sure why.
Needed better selectivity of log messages, was buried by "callsite
changed" messages.

Changing the script to use syswrite 4k fixed the problem,
I concluded the kernel was blameless, but could be more helpful.

#!/usr/bin/perl -w

=for Doc

1st purpose is to benchmark the effect of wildcard queries on query
performance; if wildcards are cheap enough, we can deploy them in the
(floating) format search.

This uncovered some broken stuff; the 85th query failed, and appears
to be truncated, so is gramatically incorrect.  Its either an error
here, or in the kernel.  Its not happening atm, retest.

Plot thickens: fail only happens doing +-p, not +-mf.  Or something
quirky.  Error remains consistent.  Looks like a short write, longer
on writer than kernel-reader.  Try syswrite on handle to control this.

=cut

use Getopt::Std;

getopts('vN:k:', \my %opts) or die <<EOH;
$0 options:
    -v verbose
    -k=n kernel dyndbg verbosity
    -N=n number of loops.. tbrc
EOH
$opts{N} //= 10; # !undef, 0 tests too long.

my $ctrl = '/proc/dynamic_debug/control';

vx($opts{k}) if defined $opts{k}; # works on -k0

open(my $CTL, '>', $ctrl) or die "cant open $ctrl for writing: $!\n";


sub vx {
    my $arg = shift;
    my $cmd = "echo $arg > /sys/module/dynamic_debug/parameters/verbose";
    system($cmd);
    warn("vx problem: rc:$? err:$! qry: $cmd\n") if ($?);
}

sub doit { # aka Qx
    my ($grep, $cmd) = @_;

    print "qry: $cmd >>\n";
    print qx/ echo '$cmd' > $ctrl /;
    #print qx/ grep $grep $ctrl /;
    open(my $h, "grep $grep $ctrl|") or die;
    while (<$h>) {
/ (=.+?) / and print "  yields: $1\n" and last;
    }
}

sub qryOK {
    my $qry = shift;

    print "syntax test: <\n$qry>\n" if $opts{v};
    my $bytes = syswrite $CTL, $qry;
    printf "short read: $bytes / %d\n", length $qry if $bytes < length $qry;
    if ($?) {
warn "rc:$? err:$! qry: $qry\n";
return 0;
    }
    return 1;
}

sub build_queries {
    my ($cmd, $flags, $ct) = @_;

    # build experiment and reference queries

    my $cycle = " $cmd +$flags # on ; $cmd -$flags # off \n";
    my $ref   = " +$flags ; -$flags \n";

    my $len = length $cycle;
    my $max = int(4096 / $len); # break/fit to buffer size
    $ct |= $max;
    print "qry: ct:$max x << \n$cycle >>\n";

    return unless qryOK($ref);
    return unless qryOK($cycle);

    my $wild = $cycle x $ct;
    my $empty = $ref x $ct;

    printf "len: %d, %d\n", length $wild, length $empty;

    return { trial => $wild,
     ref => $empty,
     probe => $cycle,
     zero => $ref,
     count => $ct,
     max => $max
    };
}

my $query_set = build_queries(' file "*" module "*" func "*" ', "mf");

qryOK($query_set->{zero});
qryOK($query_set->{probe});

qryOK($query_set->{ref});
qryOK($query_set->{trial});

#exit;
use Benchmark;
sub dobatch {
    my ($cmd, $flags, $reps, $ct) = @_;
    $reps ||= $opts{N};

    my $qs = build_queries($cmd, $flags, $ct);

    timethese($reps,
      {
  wildcards => sub {
      syswrite $CTL, $qs->{trial};
  },
  no_search => sub {
      syswrite $CTL, $qs->{ref};
  }
      }
);
}

vx 0;
dobatch(' file "*" module "*" func "*" ', "mf");
dobatch(' file "*" module "*" func "*" ', "p");

__END__


the last 2 lines run benchmarks
+/-p  (active static-key update)
vs +/- mf, (same apply code, just no static-key change)




Turning off the callsite-changed reports sped the tests considerably,
and is worth being able to do if isolating and stressing the static-key
from the console is useful.


As for the benchmark,

299k static-keys en/disabled every 0.48/sec

I cant say if thats fast or slow,  but it might be useful to compare
to something.




[   17.799142] dyndbg: query 95: <file "*" module "*" func "*"  -mf #
off > mod:<*>
[   17.799546] dyndbg: split into words: <file> <*> <module> <*>
<func> <*> <-mf>
[   17.799954] dyndbg: op=<->
[   17.800106] dyndbg: flags=0x6
[   17.800270] dyndbg: *flagsp=0x0 *maskp=0xfffffff9
[   17.800531] dyndbg: parsed: func=<*> file=<*> module=<*> format=<> lineno=0-0
[   17.801258] dyndbg: applied: func=<*> file=<*> module=<*> format=<>
lineno=0-0
[   17.801654] dyndbg: processed 96 queries, with 299040 matches, 0 errs
qry: ct:48 x <<
  file "*" module "*" func "*"  +mf # on ;  file "*" module "*" func
"*"  -mf # off
 >>
len: 4080, 576
Benchmark: timing 10 iterations of no_search, wildcards...
 no_search:  0 wallclock secs ( 0.00 usr +  0.07 sys =  0.07 CPU) @
142.86/s (n=10)
            (warning: too few iterations for a reliable count)
 wildcards:  0 wallclock secs ( 0.00 usr +  0.14 sys =  0.14 CPU) @
71.43/s (n=10)
            (warning: too few iterations for a reliable count)
qry: ct:49 x <<
  file "*" module "*" func "*"  +p # on ;  file "*" module "*" func
"*"  -p # off
 >>
len: 4067, 490
Benchmark: timing 10 iterations of no_search, wildcards...
 no_search: 21 wallclock secs ( 0.00 usr + 21.01 sys = 21.01 CPU) @
0.48/s (n=10)
 wildcards: 22 wallclock secs ( 0.00 usr + 21.26 sys = 21.26 CPU) @
0.47/s (n=10)
bash-5.1#






ISTM 1234 module-level ... callsite-updates seemed a worthwhile
mental model to rationalize the progressively detailed reports of a $cmd error.
And preserve output availability while suppressing noisy (for many
purposes) output.


If you conclude this change is good,
and want any of the above in a commit --amend, I'll do that.

otherwize I'll resend this (and others, including the !SOB one)
as part of next rev of  "use dyndbg in drm.debug".

>
> thanks,
>
> greg k-h