From 9c40e1aa84123750773a57c9cf39112459a952dd Mon Sep 17 00:00:00 2001 From: Andrew Halaney Date: Wed, 13 Oct 2021 11:40:21 -0400 Subject: dyndbg: Remove support for ddebug_query param This param has been deprecated for a very long time now, let's rip it out. Signed-off-by: Andrew Halaney Signed-off-by: Jason Baron Link: https://lore.kernel.org/r/1634139622-20667-3-git-send-email-jbaron@akamai.com Signed-off-by: Greg Kroah-Hartman --- Documentation/admin-guide/dynamic-debug-howto.rst | 6 ++---- Documentation/admin-guide/kernel-parameters.txt | 5 ----- 2 files changed, 2 insertions(+), 9 deletions(-) (limited to 'Documentation/admin-guide') diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst index b119b8277b3e..d0911e7cc271 100644 --- a/Documentation/admin-guide/dynamic-debug-howto.rst +++ b/Documentation/admin-guide/dynamic-debug-howto.rst @@ -249,8 +249,7 @@ Debug messages during Boot Process To activate debug messages for core code and built-in modules during the boot process, even before userspace and debugfs exists, use -``dyndbg="QUERY"``, ``module.dyndbg="QUERY"``, or ``ddebug_query="QUERY"`` -(``ddebug_query`` is obsoleted by ``dyndbg``, and deprecated). QUERY follows +``dyndbg="QUERY"`` or ``module.dyndbg="QUERY"``. QUERY follows the syntax described above, but must not exceed 1023 characters. Your bootloader may impose lower limits. @@ -270,8 +269,7 @@ this boot parameter for debugging purposes. If ``foo`` module is not built-in, ``foo.dyndbg`` will still be processed at boot time, without effect, but will be reprocessed when module is -loaded later. ``ddebug_query=`` and bare ``dyndbg=`` are only processed at -boot. +loaded later. Bare ``dyndbg=`` is only processed at boot. Debug Messages at Module Initialization Time diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 91ba391f9b32..9c0c57d1ca78 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -841,11 +841,6 @@ Format: , See also Documentation/input/devices/joystick-parport.rst - ddebug_query= [KNL,DYNAMIC_DEBUG] Enable debug messages at early boot - time. See - Documentation/admin-guide/dynamic-debug-howto.rst for - details. Deprecated, see dyndbg. - debug [KNL] Enable kernel debugging (events log level). debug_boot_weak_hash -- cgit v1.2.3 From 5879f1c94d67e05401cddd2043649548e38d65d3 Mon Sep 17 00:00:00 2001 From: Andrew Halaney Date: Wed, 13 Oct 2021 11:40:22 -0400 Subject: Documentation: dyndbg: Improve cli param examples Jim pointed out that using $module.dyndbg= is always a more flexible choice for using dynamic debug on the command line. The $module.dyndbg style is checked at boot and handles if $module is a builtin. If it is actually a loadable module, it is handled again later when the module is loaded. If you just use dyndbg="module $module +p" dynamic debug is only enabled when $module is a builtin. It was recommended to illustrate wildcard usage as well. Suggested-by: Jim Cromie Signed-off-by: Andrew Halaney Signed-off-by: Jason Baron Link: https://lore.kernel.org/r/1634139622-20667-4-git-send-email-jbaron@akamai.com Signed-off-by: Greg Kroah-Hartman --- Documentation/admin-guide/dynamic-debug-howto.rst | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) (limited to 'Documentation/admin-guide') diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst index d0911e7cc271..ae264aab42b6 100644 --- a/Documentation/admin-guide/dynamic-debug-howto.rst +++ b/Documentation/admin-guide/dynamic-debug-howto.rst @@ -357,7 +357,10 @@ Examples Kernel command line: ... // see whats going on in dyndbg=value processing dynamic_debug.verbose=1 - // enable pr_debugs in 2 builtins, #cmt is stripped - dyndbg="module params +p #cmt ; module sys +p" + // enable pr_debugs in the btrfs module (can be builtin or loadable) + btrfs.dyndbg="+p" + // enable pr_debugs in all files under init/ + // and the function parse_one, #cmt is stripped + dyndbg="file init/* +p #cmt ; func parse_one +p" // enable pr_debugs in 2 functions in a module loaded later pc87360.dyndbg="func pc87360_init_device +p; func pc87360_find +p" -- cgit v1.2.3 From 09ee10ff804ec4bc58eb9849226312ff1c4d7e7b Mon Sep 17 00:00:00 2001 From: Jim Cromie Date: Tue, 19 Oct 2021 15:07:46 -0600 Subject: dyndbg: refine verbosity 1-4 summary-detail 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 <', $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 Link: https://lore.kernel.org/r/20211019210746.185307-1-jim.cromie@gmail.com Signed-off-by: Greg Kroah-Hartman --- Documentation/admin-guide/dynamic-debug-howto.rst | 2 +- lib/dynamic_debug.c | 25 +++++++++++++---------- 2 files changed, 15 insertions(+), 12 deletions(-) (limited to 'Documentation/admin-guide') 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; } -- cgit v1.2.3