[PATCH 0/5] dynamic debug for -next

[PATCH 0/5] dynamic debug for -next

[Jim Cromie]

hi Greg, Jason, 

Please consider these "more selective verbose info" patches for your
-next tree:

- show module name in query from $module.dyndbg="...;..."
- don't log command input with quotes user might use, it only confuses.
- silence log of empty/tail query.
- refine verbosity: summary..detail: 1..4

While doing stress testing with (something like):
  echo "+p; -p; +p; -p; +p; -p; +p; -p; +p; -p" > control

The existing v2pr_info("changed:") is called ~30k times (~3k
callsites, 10x) on my desktop kernel, and the syslog work completely
overwhelms and hides the static-key IPI overheads (using this
workload).

While verbose=1 silences this, it also stops most parsing vpr-infos,
as I found while submitting 4kb command buffers, and seeing short
writes and resulting bad commands kernel-side.  I needed to hide the
"changed" messages, but still see the parsing error (and submit
context), where the short write and resulting illegal command revealed
itself.

The script fix was to syswrite the prepared multi-command string,
avoiding perl's buffered io, but the kernel-side tweaks made it easier
to isolate and debug my userspace problem filling the 4kb command
buffer.

With these changes, the script elicits this log; with last of 96
queries logged at v=3, then benchmarked with v=0.

FWIW, the script runs 299k simple flag changes @ 125x/s.
For static-key changes, its MUCH slower, taking 4s each.
500x cost is not unreasonable, considering systemwide IPI.

model name	: AMD Ryzen 7 5800H with Radeon Graphics (16 core)

v=3 messages, per query.
[  727.006884] dyndbg: query 95: <file "*" module "*" func "*"  -mf # off > mod:<*>
[  727.007268] dyndbg: split into words: <file> <*> <module> <*> <func> <*> <-mf>
[  727.007657] dyndbg: op=<->
[  727.007813] dyndbg: flags=0x6
[  727.007973] dyndbg: *flagsp=0x0 *maskp=0xfffffff9
[  727.008320] dyndbg: parsed: func=<*> file=<*> module=<*> format=<> lineno=0-0
[  727.009205] dyndbg: applied: func=<*> file=<*> module=<*> format=<> lineno=0-0

v=2 message, summarizing command buffer submission.
[  727.009584] dyndbg: processed 96 queries, with 299040 matches, 0 errs

benchmark 2 queries: 1- a wildcard in all terms, 2- baseline, no terms

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.08 sys =  0.08 CPU) @ 125.00/s (n=10)
            (warning: too few iterations for a reliable count)
 wildcards:  1 wallclock secs ( 0.00 usr +  0.16 sys =  0.16 CPU) @ 62.50/s (n=10)
            (warning: too few iterations for a reliable count)

Conclusion: Wildcarding isn't terribly expensive, so it is fair game
for format matching, just like the other fields.

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: 40 wallclock secs ( 0.00 usr + 40.08 sys = 40.08 CPU) @  0.25/s (n=10)
 wildcards: 40 wallclock secs ( 0.00 usr + 40.37 sys = 40.37 CPU) @  0.25/s (n=10)
bash-5.1# 

Here, +p -p static-key toggle dominates the workload, and is MUCH
slower than comparable simple-flag toggling above.


I do hope that verbose= is not frozen API.
It has always been an integer, not a boolean, implying range.

It has also seen refinement since its origin:

commit 74df138d508e ("dynamic_debug: change verbosity at runtime")

This made verbose usable as a knob, w/o requiring reboot, but also
(implicitly) made it API, because it got exposed to userspace ?

commit 481c0e33f1e7 ("dyndbg: refine debug verbosity; 1 is basic, 2 more chatty")

This altered the callsite "changed" info to verbose=2 (amongst others),
but that really wasn't enough selectivity to cope with the situation
described above.


Jim Cromie (5):
  dyndbg: show module in vpr-info in dd-exec-queries
  dyndbg: refine verbosity 1-4 overview-detail
  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

 lib/dynamic_debug.c | 45 ++++++++++++++++++++++++---------------------
 1 file changed, 24 insertions(+), 21 deletions(-)

-- 
2.31.1

[PATCH 1/5] 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), display that 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 cb5abb42c16a..dfe1e6a857bc 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 2/5] dyndbg: refine verbosity 1-4 summary-detail

[Jim Cromie]

adjust current v*pr_info() calls to fit an overview..detail scheme:

-1 module level activity: add/remove, etc
-2 command ingest, splitting, summary of effects.
   per >control write
-3 command parsing, 6 vpr-infos changed to this.
-4 per-site change - was v2, too noisy there.
   can yield 3k logs per command.

-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 formerly obscured v1-3 messages, and dominated the
static-key workload being tested.

The verbose parameter has previously seen adjustment:
commit 481c0e33f1e7 ("dyndbg: refine debug verbosity; 1 is basic, 2 more chatty")

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
The script driving these adjustments is:

 !/usr/bin/perl -w

=for Doc

1st purpose was to benchmark the effect of wildcard queries on query
performance; if wildcards are cheap enough, we can deploy them in the
(floating) format search.  1st finding: wildcards take 2x as long to
process.

2nd purpose was to benchmark real static-key changes VS simple flag
changes.  Found ~100x decrease for the hard work.

The script maximizes workload per >control by packing it a long
sequence of "+p; -p;" commands; 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, likely load
dependent.  Error remains consistent.  Looks like a short write,
longer on writer than kernel-reader.  Try syswrite on handle to
control this.  That fixed short write.

=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 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});

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};
		  }
	      }
	);
}

sub bench_static_key_toggle {
    vx 0;
    dobatch(' file "*" module "*" func "*" ', "mf");
    dobatch(' file "*" module "*" func "*" ', "p");
}

sub bench_verbose_levels {
    for my $i (0..4) {
	vx $i;
	dobatch(' file "*" module "*" func "*" ', "mf");
    }
}

bench_static_key_toggle();

__END__
---
 lib/dynamic_debug.c | 22 ++++++++++++----------
 1 file changed, 12 insertions(+), 10 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dfe1e6a857bc..e645807cb20a 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 3/5] dyndbg: use alt-quotes in vpr-infos, not those user might use

[Jim Cromie]

   echo format $str +p > control

can be finicky from within a script, `awith respect to quoting
of input terms, so lets not complicate things by wrapping that input
with either quoting char, using <%s> instead.

This draws a checkpatch warning on pr_cont() altered quoting.
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 e645807cb20a..75e702223730 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 4/5] dyndbg: vpr-info on remove-module complete, not starting

[Jim Cromie]

On qemu --smp 3 runs, remove-module can get called 3 times.
So don't print on entry; instead print "removed" after entry is
found and removed, so just once.

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 75e702223730..18235de37f25 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 5/5] 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 a
vpr-info on an 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 18235de37f25..eef9ca92b05c 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 2/5] dyndbg: refine verbosity 1-4 summary-detail

[Greg KH]

On Tue, Oct 12, 2021 at 12:33:07PM -0600, Jim Cromie wrote:
> adjust current v*pr_info() calls to fit an overview..detail scheme:
> 
> -1 module level activity: add/remove, etc
> -2 command ingest, splitting, summary of effects.
>    per >control write
> -3 command parsing, 6 vpr-infos changed to this.
> -4 per-site change - was v2, too noisy there.
>    can yield 3k logs per command.
> 
> -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 formerly obscured v1-3 messages, and dominated the
> static-key workload being tested.
> 
> The verbose parameter has previously seen adjustment:
> commit 481c0e33f1e7 ("dyndbg: refine debug verbosity; 1 is basic, 2 more chatty")
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>

Where is this being documented?  How do we know what these different
"levels" mean?

thanks,

greg k-h

Re: [PATCH 3/5] dyndbg: use alt-quotes in vpr-infos, not those user might use

[Greg KH]

On Tue, Oct 12, 2021 at 12:33:08PM -0600, Jim Cromie wrote:
>    echo format $str +p > control
> 
> can be finicky from within a script, `awith respect to quoting

"`awith"?

> of input terms, so lets not complicate things by wrapping that input
> with either quoting char, using <%s> instead.
> 
> This draws a checkpatch warning on pr_cont() altered quoting.
> 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 e645807cb20a..75e702223730 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",

Wait, no, it now looks like you want '<' and '>' in the input lines
here.

That's confusing, why is this really all needed?

thanks,

greg k-h

Re: [PATCH 0/5] dynamic debug for -next

[Greg KH]

On Tue, Oct 12, 2021 at 12:33:05PM -0600, Jim Cromie wrote:
> hi Greg, Jason, 
> 
> Please consider these "more selective verbose info" patches for your
> -next tree:
> 
> - show module name in query from $module.dyndbg="...;..."
> - don't log command input with quotes user might use, it only confuses.
> - silence log of empty/tail query.
> - refine verbosity: summary..detail: 1..4
> 
> While doing stress testing with (something like):
>   echo "+p; -p; +p; -p; +p; -p; +p; -p; +p; -p" > control
> 
> The existing v2pr_info("changed:") is called ~30k times (~3k
> callsites, 10x) on my desktop kernel, and the syslog work completely
> overwhelms and hides the static-key IPI overheads (using this
> workload).
> 
> While verbose=1 silences this, it also stops most parsing vpr-infos,
> as I found while submitting 4kb command buffers, and seeing short
> writes and resulting bad commands kernel-side.  I needed to hide the
> "changed" messages, but still see the parsing error (and submit
> context), where the short write and resulting illegal command revealed
> itself.
> 
> The script fix was to syswrite the prepared multi-command string,
> avoiding perl's buffered io, but the kernel-side tweaks made it easier
> to isolate and debug my userspace problem filling the 4kb command
> buffer.
> 
> With these changes, the script elicits this log; with last of 96
> queries logged at v=3, then benchmarked with v=0.
> 
> FWIW, the script runs 299k simple flag changes @ 125x/s.
> For static-key changes, its MUCH slower, taking 4s each.
> 500x cost is not unreasonable, considering systemwide IPI.
> 
> model name	: AMD Ryzen 7 5800H with Radeon Graphics (16 core)
> 
> v=3 messages, per query.
> [  727.006884] dyndbg: query 95: <file "*" module "*" func "*"  -mf # off > mod:<*>
> [  727.007268] dyndbg: split into words: <file> <*> <module> <*> <func> <*> <-mf>
> [  727.007657] dyndbg: op=<->
> [  727.007813] dyndbg: flags=0x6
> [  727.007973] dyndbg: *flagsp=0x0 *maskp=0xfffffff9
> [  727.008320] dyndbg: parsed: func=<*> file=<*> module=<*> format=<> lineno=0-0
> [  727.009205] dyndbg: applied: func=<*> file=<*> module=<*> format=<> lineno=0-0
> 
> v=2 message, summarizing command buffer submission.
> [  727.009584] dyndbg: processed 96 queries, with 299040 matches, 0 errs
> 
> benchmark 2 queries: 1- a wildcard in all terms, 2- baseline, no terms
> 
> 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.08 sys =  0.08 CPU) @ 125.00/s (n=10)
>             (warning: too few iterations for a reliable count)
>  wildcards:  1 wallclock secs ( 0.00 usr +  0.16 sys =  0.16 CPU) @ 62.50/s (n=10)
>             (warning: too few iterations for a reliable count)
> 
> Conclusion: Wildcarding isn't terribly expensive, so it is fair game
> for format matching, just like the other fields.
> 
> 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: 40 wallclock secs ( 0.00 usr + 40.08 sys = 40.08 CPU) @  0.25/s (n=10)
>  wildcards: 40 wallclock secs ( 0.00 usr + 40.37 sys = 40.37 CPU) @  0.25/s (n=10)
> bash-5.1# 
> 
> Here, +p -p static-key toggle dominates the workload, and is MUCH
> slower than comparable simple-flag toggling above.
> 
> 
> I do hope that verbose= is not frozen API.
> It has always been an integer, not a boolean, implying range.
> 
> It has also seen refinement since its origin:
> 
> commit 74df138d508e ("dynamic_debug: change verbosity at runtime")
> 
> This made verbose usable as a knob, w/o requiring reboot, but also
> (implicitly) made it API, because it got exposed to userspace ?
> 
> commit 481c0e33f1e7 ("dyndbg: refine debug verbosity; 1 is basic, 2 more chatty")
> 
> This altered the callsite "changed" info to verbose=2 (amongst others),
> but that really wasn't enough selectivity to cope with the situation
> described above.

I took the first patch here, I wanted to take patches 4 and 5 as well,
but they did not apply because I didn't want to take 2 and 3 right now.

thanks,

greg k-h

Re: [PATCH 0/5] dynamic debug for -next

[jim.cromie]

On Wed, Oct 13, 2021 at 7:22 AM Greg KH <gregkh@linuxfoundation.org> wrote:
>
> On Tue, Oct 12, 2021 at 12:33:05PM -0600, Jim Cromie wrote:
> > hi Greg, Jason,
> >
> > Please consider these "more selective verbose info" patches for your
> > -next tree:
> >


>
> I took the first patch here, I wanted to take patches 4 and 5 as well,
> but they did not apply because I didn't want to take 2 and 3 right now.
>
> thanks,
>
> greg k-h

ok thanks, I'll re-order 4,5 w/o 2,3 and keep the latter locally

[PATCH 1/1] dyndbg: refine verbosity 1-4 summary-detail

[Jim Cromie]

adjust current v*pr_info() calls to fit an overview..detail scheme:

1- module level activity: add/remove, etc
2- command ingest, splitting, summary of effects.
   per >control write
3- command parsing: op, flags, search terms
4- per-site change msg
   can yield ~3k x 2 logs per echo "+p;-p" > command.

Summarize these 4 levels in MODULE_PARM_DESC, and update verbose=3 in Doc.

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

4- gets per-callsite "changed:" pr-infos, which are very noisy during
stress tests, and formerly obscured v1-3 messages, and overwhelmed the
static-key workload being tested.

The verbose parameter has previously seen adjustment:
commit 481c0e33f1e7 ("dyndbg: refine debug verbosity; 1 is basic, 2 more chatty")

The script driving these adjustments is:

 !/usr/bin/perl -w

=for Doc

1st purpose was to benchmark the effect of wildcard queries on query
performance; if wildcards are risk free cheap enough, we can deploy
them in the (floating) format search.  1st finding: wildcards take 2x
as long to process.

2nd purpose was to benchmark real static-key changes VS simple flag
changes.  Found ~100x decrease for the hard work.

The script maximizes workload per >control by packing it a ~4kb
string of "+p; -p;" commands; 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, likely load
dependent.  Error remains consistent.  Looks like a short write,
longer on writer than kernel-reader.  Try syswrite on handle to
control this.  That fixed short write.

=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 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});

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};
		  }
	      }
	);
}

sub bench_static_key_toggle {
    vx 0;
    dobatch(' file "*" module "*" func "*" ', "mf");
    dobatch(' file "*" module "*" func "*" ', "p");
}

sub bench_verbose_levels {
    for my $i (0..4) {
	vx $i;
	dobatch(' file "*" module "*" func "*" ', "mf");
    }
}

bench_static_key_toggle();

__END__

Heres how the test-script runs:

:: verbose=3 parsing info

[   48.401646] dyndbg: query 95: "file "*" module "*" func "*"  -mf # off " mod:*
[   48.402040] dyndbg: split into words: "file" "*" "module" "*" "func" "*" "-mf"
[   48.402456] dyndbg: op='-'
[   48.402615] dyndbg: flags=0x6
[   48.402779] dyndbg: *flagsp=0x0 *maskp=0xfffffff9
[   48.403033] dyndbg: parsed: func="*" file="*" module="*" format="" lineno=0-0
[   48.403674] dyndbg: applied: func="*" file="*" module="*" format="" lineno=0-0

:: verbose=2 >control summary.
   ~300k site matches/changes per 4kb command

[   48.404063] dyndbg: processed 96 queries, with 296160 matches, 0 errs

:: 2 queries against each other, no-search vs all-wildcard-search

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.03 sys =  0.03 CPU) @ 333.33/s (n=10)
            (warning: too few iterations for a reliable count)
 wildcards:  0 wallclock secs ( 0.00 usr +  0.09 sys =  0.09 CPU) @ 111.11/s (n=10)
            (warning: too few iterations for a reliable count)

:: 2 queries, both doing real work / changing stati-key states.

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: 20 wallclock secs ( 0.00 usr + 20.36 sys = 20.36 CPU) @  0.49/s (n=10)
 wildcards: 21 wallclock secs ( 0.00 usr + 21.08 sys = 21.08 CPU) @  0.47/s (n=10)
bash-5.1#

Thats 150k static-key-toggles / sec
  ~600x slower than simple flags
  on qemu --smp 3 run

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

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index ae264aab42b6..a89cfa083155 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -356,7 +356,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 the btrfs module (can be builtin or loadable)
     btrfs.dyndbg="+p"
     // enable pr_debugs in all files under init/
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 87b1b0121234..dd7f56af9aed 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -71,6 +71,8 @@ static DEFINE_MUTEX(ddebug_lock);
 static LIST_HEAD(ddebug_tables);
 static int verbose;
 module_param(verbose, int, 0644);
+MODULE_PARM_DESC(verbose, " dynamic_debug/control processing "
+		 "( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)");
 
 /* Return the path relative to source root */
 static inline const char *trim_prefix(const char *path)
@@ -118,6 +120,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 +134,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 +217,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 +277,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 +337,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 +451,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 +465,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 +481,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,9 +544,8 @@ static int ddebug_exec_queries(char *query, const char *modname)
 		}
 		i++;
 	}
-
 	if (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)
@@ -780,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", len);
 
 	ret = ddebug_exec_queries(tmpbuf, NULL);
 	kfree(tmpbuf);
@@ -968,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