Re: [re: PATCH v2 00/15 - 00/11] dyndbg: add support for writing debug logs to trace
From: Łukasz Bartosik
Date: Thu Dec 14 2023 - 10:20:37 EST
sob., 9 gru 2023 o 01:31 Łukasz Bartosik <lb@xxxxxxxxxxxx> napisał(a):
>
> pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@xxxxxxxxx> napisał(a):
> >
> > hi Lukas,
> >
> > Sorry for the delay, I probably should have split this up.
> > (also cc'g gregkh)
> >
> > Ive been banging on your v2 patchset:
> > https://lore.kernel.org/lkml/20231130234048.157509-1-lb@xxxxxxxxxxxx/
> >
>
> Jim, thank you for your thorough testing and review.
>
> > Things are looking pretty good, a few issues follow. And some patches.
> >
>
> ;)
>
> > trivial:
> >
> > dyndbg: export _print_hex_dump # squash wo comment
> > dyndbg: tweak pr_info format s/trace dest/trace_dest/ # greppability squash
> > dyndbg: disambiguate quoting in a debug msg
> > dyndbg: fix old BUG_ON in >control parser
> >
> > Then:
> >
> > dyndbg: change +T:name_terminator to dot
> > dyndbg: treat comma as a token separator
> >
> > 1st allows 2nd, 2nd allows simpler arg-passing, boot-args, etc:
> >
> > echo module,test_dynamic_debug,class,L2,+p > /proc/dynamic_debug/control
> > modprobe test_dynamic_debug dyndbg=class,L2,+mfl
> >
> > Given theres no legacy wrt comma, swapping it now with dot seems
> > better semantically than "dot as token/list separator".
> >
> > Aside: /proc/dynamic_debug/control is always there (if configd), even
> > when <debugfs> isn't mounted. Its more universal, and copy-pastable.
> >
> > dyndbg: __skip_spaces - and comma
> > dyndbg: split multi-query strings with %
> >
> > % allows escape-free multi-cmd dyndbg args:
> >
> > modprobe test_dynamic_debug \
> > dyndbg=open,selftest%class,D2_CORE,+T:selftest.mf
> >
> > dyndbg: reduce verbose/debug clutter
> > dyndbg: move lock,unlock into ddebug_change, drop goto - revisit
> >
> > Ive just pushed it, I will bump my version here.
> > To github.com:jimc/linux.git
> > + 20d113eb6f9a...66fa2e4cb989 lukas-v2.1 -> lukas-v2.1 (forced update)
> >
hi Jim,
I will squash the following commits to their appropriate peers:
- dyndbg: export _print_hex_dump
- dyndbg: tweak pr_info format s/trace dest/trace_dest/
- dyndbg: change +T:name_terminator to dot
I will also drop completely "dyndbg: move lock,unlock into
ddebug_change, drop goto" and leave the remaining commits as is.
> > SELFTEST
> >
> > Ive taken the liberty to write an ad-hoc test script (inline below),
> > to exersize the parser with legacy command input, and with the new
> > stuff mentioned above: comma-separated-tokens, %-separated-multi-cmds,
> > while counting changes to builtin,etc modules, to validate against
> > expectations.
> >
> > The change-count tests achieve some closed-loop testing, but checking
> > syslog for messages written always seemed too hard/unreliable. Your
> > private trace-instances work promises a solution, by giving an
> > observable closed system to build upon.
> >
> > I made some attempts to write messages to the trace-buf, but ran out
> > of clues*tuits. And I encountered a couple more definite problems:
> >
>
> Let me dig through test scripts you created and issues you run into.
>
>
> > 1- modprobe/rmmod lifecycle probs
> >
> > Ive coded some blue-sky and not-so-proper "modprobe,+T:it,-T:it,rmmod"
> > life-cycle scenarios, which can wedge a previously created instance.
> > Once wedged, I cannot recover. See the test_private_trace{,_2,_3}
> > functions, and the error_log_ref() following each.
> >
The tests are very useful. I root caused the failures. Please see below.
> > This brittleness begs a question; should we have auto-open (mapping
> > new names to available 1-63 trc-ids) ? And non-close ? If it just did
> > the right thing, particularly on rmmod, it would prevent "misuse".
> >
I would rather not have auto-open. For me personal argument against it is
that I usually make a lot of typos and with auto-open if I don't
verify what I wrote
I won't know whether logs will be written to the "right" instance or a
newly created instance
with typo name. In case of open/close commands error pops up when I
try to write logs
to a trace instance which was not opened.
> > I don't think auto-open obsoletes the open (& esp) close commands, but
> > Id like to see scripted test scenarios using close in combo with the
> > right /sys/kernel/tracing/* manipulations, to prove its not all just a
> > fever dream.
> >
Would you please elaborate what you mean by close in combo with right
/sys/kernel/tracing/* manipulations ?
> > Your expertise in opening, writing to, manipulating & destroying
> > private (and the global) tracebufs, distilled into new shell funcs,
> > would be enormously helpful towards demonstrating the private-buffer
> > use case and its value.
> >
I will work on adding new tests for trace.
> > 2- some new flags parse error:
> >
> > [ 1273.074535] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 1273.075365] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T:foo%class,D2_KMS,+T:foo"
> > [ 1273.076307] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <test_dynamic_debug>
> > [ 1273.077068] dyndbg: split into words: "class" "D2_CORE" "+T:foo"
> > [ 1273.077673] dyndbg: unknown flag 'c'
> > [ 1273.078033] dyndbg: flags parse failed on 2: +T:foo
> > [ 1273.078519] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <test_dynamic_debug>
> > [ 1273.079266] dyndbg: split into words: "class" "D2_KMS" "+T:foo"
> > [ 1273.079872] dyndbg: unknown flag '�'
> > [ 1273.080228] dyndbg: flags parse failed on 2: +T:foo
> > [ 1273.080716] dyndbg: processed 2 queries, with 0 matches, 2 errs
> > : 0 matches on =Tl
> >
> > I have a suspicion this relates to moving the parse_flags call in
> > ddebug_query, but I havent dug in.
> >
> >
> > I also have some reservations about the default dest; 1st that it is a
> > global state var, as noted at bottom of control:
> >
> > [root@v6 lx]# ddgrep \\btrace\\b # a better/narrower search-term ?
> > ...
> > Default trace destination: foo # add a '#:' prefix to these lines ?
Do you mean
#: Default trace destination:
#: Opened trace instances:
or
Default trace destination: #:foo
Opened trace instances: #:foo, #:bar
> > Opened trace instances: # all values should be on this line
> >
I will put all opened trace instance names on the same line
> > Then theres the "preset" value, ie each site's dest_id (sorry I forgot
> > your fieldname). I presume the default would override such a "preset"
> > (otherwise it would have no effect).
> >
> > Is the default set on last open ? or on next use of +T:<foo> ?
> >
Default trace destination is set on [+-]T:<foo>
> > In the no-default world, a user/tester would decide how many
> > trace-instances are needed, and map sets of callsites to them.
> >
> > # configure drm-debug streams for this test scenario
> > cat<<EOF >/proc/dynamic_debug/control
> > open drm_core
> > open drm_mix
> > open driver_1 # we can separate by modname but not drvr-number
> > open driver_2
> > class DRM_UT_CORE -T:drm_core # set dest_id, disabled state
This sets default trace destination to drm_core
> > class DRM_UT_CORE +mf # traces dont do prefixing (should it?)
In this case logs will be neither written to syslog nor trace because
both pT flags are not set.
I verified that both output to trace instance and trace events honors
mf flags (prefixing) when they are set for a given callsite.
> > # mix KMS & ATOMIC into 1 stream
> > class DRM_UT_KMS -T:drm_mix
> > class DRM_UT_ATOMIC -T:drm_mix
> > EOF
> >
> > Then perhaps to turn on/off when needed: (legacy analogue version)
> >
> > echo 0x15 > /sys/module/drm/parameters/debug_trace
> >
> > With those trace-dest presets honored, the configured drm_core &
> > drm_mix streams persist. If a later enablement applies the
> > then-current default trace-dest, it would spoil this scheme.
> >
> > Could you elaborate a scenario or 2 where the default behavior does
> > something specific, and that its the right thing ? I dont understand
> > it yet.
> >
I'm a bit lost here. Help me out please. What do you mean by default behavior ?
> > OTOH
> >
> > One limitation of the above: the drm.debug_trace (posited above) would
> > turn on all Ts in all those class'd callsites across the whole
> > subsystem, irrespective of their preconfigured destination. That was
> > always inherent in drm.debug, but its less than perfect.
> >
> > It sort-of defeats the point of doing +T only on the useful callsites.
> >
> > And global event buf is also enabled, it might be flood-prone.
> >
> > echo 1 > /sys/kernel/tracing/events/dyndbg/enable
> >
> > It would help if we could filter on trace-instance names:
> > (this sounds familiar :-)
> >
> > ddcmd module '*' trace_dest drm_mix +T
> >
> >
> > In reality, the dest-id is not even dependent on tracing per-se, it is
> > a user classification system (in contrast to class <subsys-names>).
> > It just happens to be tied by +T:name syntax to tracefs.
> >
> > No promise about +p:_alt_log_.mflt having meaning, or working.
> >
> >
> >
> > anyway, Ive gone on long enough. heres that/those scripts
> >
> > cat dd-tools.rc
> > #!/bin/bash
> >
> > function ddcmd () {
> > echo $* > /proc/dynamic_debug/control
> > }
> > function ddcat () {
> > cat $1 > /proc/dynamic_debug/control
> > }
> > function vx () {
> > echo $1 > /sys/module/dynamic_debug/parameters/verbose
> > }
> > function ddgrep () {
> > grep $1 /proc/dynamic_debug/control
> > }
> > function doprints () {
> > cat /sys/module/test_dynamic_debug/parameters/do_prints
> > }
> >
> > cat dd-selftest.rc
> > #!/bin/bash
> > # dd-selftest.rc: shell-fns & test-script for dynamic-debug
> > # mostly run as:
> > # vng --force-9p -v -e ./dd-selftest.rc
> >
> > . dd-tools.rc
> > # vx 3
> >
> > function check_matches {
> > let ct=$(ddgrep $1 | wc -l )
> > echo ": $ct matches on $1 "
> > [ "$2" == "-v" ] && ddgrep $1
> > }
> > function check_instance {
> > # 1. trace instance name 2. -v for verbose
> > if [ -e /sys/kernel/tracing/instances/$1 ]; then
> > if [ "$2" == "-v" ] ; then
> > echo "ls -l /sys/kernel/tracing/instances/$1: "
> > ls -l /sys/kernel/tracing/instances/$1
> > fi
> > else
> > echo "no instance: $1"
> > fi
> > }
> > function tmark {
> > echo $* > /sys/kernel/tracing/trace_marker
> > }
> > function read_trace_instance {
> > # get traces opened, default
> > tail -n9 /proc/dynamic_debug/control | grep -P \\w+ | grep -vP ^drivers/
> > }
> > function error_log_ref {
> > # to show what I got
> > : echo "# error-log-ref: $1"
> > : echo cat \$2
> > }
> > function ifrmmod {
> > lsmod | grep $1 || echo $1 not there
> > lsmod | grep $1 && rmmod $1
> > }
> >
> > echo LOADING TEST FUNCS
> > echo SHLVL: $SHLVL
> >
> > function basic_tests {
> > echo \# BASIC_TESTS
> >
> > ddcmd =_ "# zero everything (except class'd sites)"
> > check_matches =p 0
> >
> > # there are several main's :-/
> > ddcmd module main file */module/main.c +p
> > check_matches =p 14
> > ddcmd =_
> > check_matches =p 0
> >
> > ddcmd module mptcp =_
> > ddcmd module mptcp +pmf
> > check_matches =pmf 120
> > ddcmd =_
> >
> > # multi-cmd newline separated with embedded comments
> > cat <<"EOF" > /proc/dynamic_debug/control
> > module main +mf # multi-query
> > module main file init/main.c +ml # newline separated
> > module kvm +fl # comment prefixed
> > module kvm_intel +flt #
> > EOF
> > # the intersection of all those main's is hard to track/count
> > # esp when mixed with overlapping greps
> > check_matches =mf 27
> > check_matches =ml 0
> > check_matches =mfl 6
> > check_matches =fl 29
> > check_matches =flt 16
> > ddcmd =_
> > }
> > basic_tests; # run
> >
> > function comma_terminator_tests {
> > echo \# COMMA_TERMINATOR_TESTS
> >
> > # try combos of space & comma
> > ddcmd module,mptcp,=_
> > ddcmd module,mptcp,+mf
> > ddcmd " module, mptcp, +mfl"
> > check_matches =pmf 120
> > ddcmd module , mptcp,-p
> > check_matches =mf 120
> > check_matches =p 0
> > ddcmd ,module ,, mptcp, -p
> > ddcmd ",module ,, mptcp, -p"
> > ddcmd =_
> > }
> > comma_terminator_tests; # run
> >
> > function private_trace_test {
> > echo \# PRIVATE_TRACE_TEST - proper lifo cycle - open, enable:named disable:named close
> >
> > ddcmd open usb_stream
> > check_instance usb_stream
> > ddcmd module usbcore +T:usb_stream.mf
> > check_matches =T:usb_stream.mf 161
> > ddcmd module usbcore -T:usb_stream.mf
> > check_matches =T:usb_stream.mf 0
> > read_trace_instance
> > ddcmd close usb_stream
> > read_trace_instance
> > ddcmd =_
> > }
> > private_trace_test; # run
> >
> > function test_percent_splitting {
> > echo \# TEST_PERCENT_SPLITTING - multi-command splitting on %
> > ddcmd =_
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+pf%class,D2_KMS,+pt%class,D2_ATOMIC,+pm
> > check_matches =pf -v
> > check_matches =pt -v
> > check_matches =pm -v
> > ddcmd class,D2_CORE,+mf%class,D2_KMS,+lt%class,D2_ATOMIC,+ml "# add some prefixes"
> > check_matches =pmf -v
> > check_matches =plt -v
> > check_matches =pml -v
> > doprints
> > ifrmmod test_dynamic_debug
> > }
> > test_percent_splitting; # run
> >
> > function test_actual_trace {
> > echo \# test_actual_trace
> > ddcmd =_
> > ifrmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T
> > check_matches =T -v
> > tmark here comes the WARN
> > doprints
> > cat /sys/kernel/tracing/trace
> > }
> > test_actual_trace; # run, hits 1313: WARN_ON_ONCE(!arr)
> >
> > error_log_ref test_actual_trace <<"EO_LOG"
> > [ 6.587595] dyndbg: read 3 bytes from userspace
> > [ 6.588174] dyndbg: query 0: <=_> on module: <*>
> > [ 6.588842] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> > [ 6.726160] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 6.727052] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 6.728158] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 6.729112] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 6.729969] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 6.730729] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 6.731494] dyndbg: module: test_dynamic_debug dyndbg="class,D2_CORE,+T"
> > [ 6.732350] dyndbg: query 0: <class,D2_CORE,+T> on module: <test_dynamic_debug>
> > [ 6.733291] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 6.734224] ------------[ cut here ]------------
> > [ 6.734811] WARNING: CPU: 1 PID: 472 at lib/dynamic_debug.c:1309 ddebug_printk+0xde/0xf0
> > [ 6.735814] Modules linked in: test_dynamic_debug(E+) intel_rapl_msr(E) crc32_pclmul(E) intel_rapl_common(E) ghash_clmulni_intel(E) crct10dif_pclmul(E) crc32c_intel(E) joydev(E) serio_raw(E) pcspkr(E) i2c_piix4(E) [last unloaded: test_dynamic_debug(E)]
> > [ 6.738594] CPU: 1 PID: 472 Comm: modprobe Tainted: G W E 6.6.0-tf2-virtme-00026-g20d113eb6f9a-dirty #220
> > [ 6.740008] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
> > [ 6.741669] RIP: 0010:ddebug_printk+0xde/0xf0
> > [ 6.742220] Code: 48 8d 44 24 28 48 89 44 24 20 e8 ed 71 9c ff 48 83 c4 58 5b 41 5c 5d c3 48 8d 56 02 48 8d 4c 24 10 31 f6 e8 84 f9 ff ff eb b5 <0f> 0b eb a0 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 41 57 48 89
> > [ 6.745072] RSP: 0018:ffffb38140453bd0 EFLAGS: 00010246
> > [ 6.745914] RAX: 0000000000000000 RBX: ffffffffc03b97e0 RCX: ffffb38140453c50
> > [ 6.747002] RDX: ffffb38140453be0 RSI: ffffffffb26f8150 RDI: 0000000000000000
> > [ 6.747883] RBP: ffffb38140453c38 R08: 0000000000000020 R09: ffffffffb3370ce4
> > [ 6.748753] R10: 0000000000000001 R11: 0000000000010000 R12: ffffffffb26f8150
> > [ 6.749586] R13: ffff9b68029bc440 R14: ffff9b6805640800 R15: ffff9b6805c9d640
> > [ 6.750497] FS: 00007f7cdc453740(0000) GS:ffff9b683ec80000(0000) knlGS:0000000000000000
> > [ 6.751537] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 6.752310] CR2: 000055ce7a609ae0 CR3: 000000000575a000 CR4: 0000000000750ee0
> > [ 6.753238] PKRU: 55555554
> > [ 6.753604] Call Trace:
> > [ 6.753910] <TASK>
> > [ 6.754240] ? ddebug_printk+0xde/0xf0
> > [ 6.754772] ? __warn+0x7d/0x130
> > [ 6.755197] ? ddebug_printk+0xde/0xf0
> > [ 6.755669] ? report_bug+0x189/0x1c0
> > [ 6.756176] ? handle_bug+0x38/0x70
> > [ 6.756642] ? exc_invalid_op+0x13/0x60
> > [ 6.757112] ? asm_exc_invalid_op+0x16/0x20
> > [ 6.757635] ? ddebug_printk+0xde/0xf0
> > [ 6.758123] ? 0xffffffffc03c0000
> > [ 6.758533] __dynamic_pr_debug+0x133/0x170
> > [ 6.759066] ? 0xffffffffc03c0000
> > [ 6.759438] do_cats+0x127/0x180 [test_dynamic_debug]
> > [ 6.760063] test_dynamic_debug_init+0x7/0x1000 [test_dynamic_debug]
> > [ 6.760890] do_one_initcall+0x43/0x2f0
> > [ 6.761399] ? kmalloc_trace+0x26/0x90
> > [ 6.761904] do_init_module+0x9d/0x290
> > [ 6.762377] init_module_from_file+0x77/0xd0
> > [ 6.762877] idempotent_init_module+0xf9/0x270
> > [ 6.763439] __x64_sys_finit_module+0x5a/0xb0
> > [ 6.764040] do_syscall_64+0x35/0x80
> > [ 6.764474] entry_SYSCALL_64_after_hwframe+0x46/0xb0
> > [ 6.765089] RIP: 0033:0x7f7cdc56b5ad
> > [ 6.765522] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 53 48 0c 00 f7 d8 64 89 01 48
> > [ 6.767763] RSP: 002b:00007fff198e28d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> > [ 6.768781] RAX: ffffffffffffffda RBX: 000055ce7bb53980 RCX: 00007f7cdc56b5ad
> > [ 6.769611] RDX: 0000000000000000 RSI: 000055ce7bb72930 RDI: 0000000000000006
> > [ 6.770598] RBP: 00007fff198e2990 R08: 0000000000000000 R09: 0000000000000002
> > [ 6.771447] R10: 0000000000000006 R11: 0000000000000246 R12: 000055ce7bb72930
> > [ 6.772328] R13: 0000000000040000 R14: 000055ce7bb53bc0 R15: 000055ce7bb72930
> > [ 6.773252] </TASK>
> > [ 6.773532] ---[ end trace 0000000000000000 ]---
> > : 2 matches on =T
> > drivers/cpufreq/intel_pstate.c:1912 [intel_pstate]core_get_max_pstate =_ "max_pstate=TAC %x\n"
> > lib/test_dynamic_debug.c:109 [test_dynamic_debug]do_cats =T:(null) "D2_CORE msg\n" class:D2_CORE
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 0/0 #P:4
> > EO_LOG
> >
I reproduced this warning and found root cause. This was caused by an
error in how default trace destination
is set. I will fix it in the next patchset.
> > # that 2nd =T match has :(null) in the control-line. I didnt chase it.
> >
The root cause of the T:(null) is the same as above (error in how
default trace destination is set).
> > function test_early_close () {
> > ddcmd open usb_stream
> > ddcmd module usbcore +T:usb_stream.mf
> > check_matches =T:usb_stream.mf 161
> > echo ":not-running # ddcmd module usbcore -T:usb_stream.mf"
> > ddcmd close usb_stream
> > }
> > # test_early_close - works, unused, refactored below.
> > function self_start {
> > echo \# open, modprobe +T:it
> > ddcmd open selftest
> > check_instance selftest
> > modprobe test_dynamic_debug dyndbg=+T:selftest.mf
> > check_matches =T:selftest.mf -v
> > }
> > function self_end_normal {
> > echo \# disable -T:it, rmmod, close
> > ddcmd module test_dynamic_debug -T:selftest # leave mf
> > check_matches =mf -v
> > ifrmmod test_dynamic_debug
> > ddcmd close selftest
> > }
> > function self_end_disable_anon {
> > echo \# disable, close, rmmod
> > ddcmd module test_dynamic_debug -T
> > check_matches =mf -v
> > ddcmd close selftest
> > ifrmmod test_dynamic_debug
> > }
> > function self_end_disable_anon_mf {
> > echo \# disable, close, rmmod
> > ddcmd module test_dynamic_debug -Tf
> > check_matches =m -v
> > ddcmd close selftest
> > ifrmmod test_dynamic_debug
> > }
> > function self_end_nodisable {
> > echo \# SKIPPING: ddcmd module test_dynamic_debug -T:selftest
> > rmmod test_dynamic_debug
> > echo FAIL_COMING on close
> > ddcmd close selftest
> > }
> > function self_test_ {
> > echo "# SELFTEST $1"
> > self_start
> > self_end_$1
> > }
> >
> > function cycle_tests_normal {
> > echo \# CYCLE_TESTS_NORMAL
> >
> > self_test_ normal # ok
> > self_test_ disable_anon # ok
> > ddgrep selftest
> >
> > self_test_ normal # ok
> > self_test_ disable_anon_mf #
> > ddgrep selftest
> > }
> > cycle_tests_normal; # run
> >
> > function cycle_tests_problem {
> > self_test_ nodisable # write error: Device or resource busy
> > ddgrep selftest # still used, defaulted - prob
> >
> > self_test_ normal # open error, write error persists
> > ddgrep selftest # still used, defaulted
> >
> > ddcmd close selftest # too late ??
> > }
> > # cycle_tests_problem;
> >
> >
> > function test_private_trace {
> > echo "# TEST_PRIVATE_TRACE"
> > ddcmd =_
> >
> > ifrmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo
> > modprobe test_dynamic_debug
> > ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo
> >
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark test_private_trace about to do_prints
> > doprints
> > cat /sys/kernel/tracing/trace
> >
> > ddcmd class,D2_CORE,-T:foo
> > ddcmd close foo
> > ddcmd close bar
> > ifrmmod test_dynamic_debug
> > }
> > test_private_trace; # run
> >
> > error_log_ref test_private_trace <<EOF
> > # test_private_trace
> > [ 7.803744] dyndbg: read 3 bytes from userspace
> > [ 7.804329] dyndbg: query 0: <=_> on module: <*>
> > [ 7.804844] dyndbg: processed 1 queries, with 3236 matches, 0 errs
> > rmmod: ERROR: Module test_dynamic_debug is not currently loaded
> > [ 7.838191] dyndbg: read 9 bytes from userspace
> > [ 7.838858] dyndbg: query 0: <open foo> on module: <*>
> > [ 7.872066] dyndbg: processed 1 queries, with 0 matches, 0 errs
> > [ 7.991723] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 7.992488] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 7.993178] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 7.993873] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 7.994560] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 7.995174] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 7.998426] dyndbg: read 42 bytes from userspace
> > [ 7.999169] dyndbg: query 0: <class,D2_CORE,+T:foo,> on module: <*>
> > [ 8.000126] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.000956] dyndbg: processed 2 queries, with 2 matches, 0 errs
> > : 0 matches on =Tl
> > : 0 matches on =Tmf
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 2/2 #P:4
> > #
> > # _-----=> irqs-off/BH-disabled
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / _-=> migrate-disable
> > # |||| / delay
> > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> > # | | | ||||| | |
> > dd-selftest.rc-375 [003] ..... 6.876234: tracing_mark_write: here comes the WARN
> > dd-selftest.rc-375 [003] ..... 8.168406: tracing_mark_write: should be ready
> > [ 8.093538] dyndbg: read 21 bytes from userspace
> > [ 8.094156] dyndbg: query 0: <class,D2_CORE,-T:foo> on module: <*>
> > [ 8.094924] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.095560] dyndbg: read 10 bytes from userspace
> > [ 8.096038] dyndbg: query 0: <close foo> on module: <*>
> > [ 8.096565] dyndbg: trace instance is being used name=foo, use_cnt=1
> > [ 8.097198] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Device or resource busy
> > [ 8.097850] dyndbg: read 10 bytes from userspace
> > [ 8.098356] dyndbg: query 0: <close bar> on module: <*>
> > [ 8.098887] dyndbg: processed 1 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: No such file or directory
> > EOF
> >
Here the root cause is that foo trace instance is still being used
when close command is issued, i.e.
ddcmd class,D2_CORE,+T:foo,%class,D2_KMS,+T:foo # foo use count is now 2
...
ddcmd class,D2_CORE,-T:foo
ddcmd close foo # it fails because foo instance is still being used by
D2_KMS callsite(s), use count is 1
It can be fixed for example by issuing
ddcmd class,D2_KMS,-T:foo
before close command
But I also realized that use count of trace instances is not
decremented when callsite using
it is removed as a part of module removal, I will fix it in the next patchset
> > function test_private_trace_2 {
> > echo "# TEST_PRIVATE_TRACE_2"
> >
> > ddcmd =_
> > rmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo \; open bar # 2nd fails
> > modprobe test_dynamic_debug
> > ddcmd class,D2_CORE,+T:foo
> > ddcmd class,D2_KMS,+T:foo
> > ddcmd class D2_CORE +T:foo \; class D2_KMS +T:foo
> >
> > echo \# this breaks ??
> > ddcmd "class,D2_CORE,+T:foo;,class,D2_KMS,+T:foo"
> > # ddcmd class,D2_CORE,+T:foo\;class,D2_KMS,+T:foo
> >
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark test_private_trace_2 about to do_prints
> > doprints
> > cat /sys/kernel/tracing/trace
> > #rmmod test_dynamic_debug
> > }
> > test_private_trace_2; # run
> >
> > # a real parse error in this log, with same input as worked above.
> > # the unkown flag 'c' error conflicts with what the following error
> > # says is the flags token
> >
> > error_log_ref test_private_trace_2 <<EOF
> > [ 8.107982] d# test_private_trace_2
> > yndbg: read 3 bytes from userspace
> > [ 8.108490] dyndbg: query 0: <=_> on module: <*>
> > [ 8.108997] dyndbg: processed 1 queries, with 3241 matches, 0 errs
> > [ 8.139645] dyndbg: removed module "test_dynamic_debug"
> > [ 8.152344] dyndbg: read 20 bytes from userspace
> > [ 8.152952] dyndbg: query 0: <open foo > on module: <*>
> > [ 8.153610] dyndbg: instance is already opened name:foo
> > [ 8.153610]
> > [ 8.153612] dyndbg: query 1: <open bar> on module: <*>
> > [ 8.185399] dyndbg: processed 2 queries, with 0 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: File exists
> > [ 8.300750] dyndbg: class[0]: module:test_dynamic_debug base:22 len:8 ty:3
> > [ 8.301509] dyndbg: class[1]: module:test_dynamic_debug base:14 len:8 ty:1
> > [ 8.302189] dyndbg: class[2]: module:test_dynamic_debug base:10 len:3 ty:2
> > [ 8.302876] dyndbg: class[3]: module:test_dynamic_debug base:0 len:10 ty:0
> > [ 8.303550] dyndbg: module:test_dynamic_debug attached 4 classes
> > [ 8.304147] dyndbg: 32 debug prints in module test_dynamic_debug
> > [ 8.307165] dyndbg: read 21 bytes from userspace
> > [ 8.307754] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.308914] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.310076] dyndbg: read 20 bytes from userspace
> > [ 8.310916] dyndbg: query 0: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.311915] dyndbg: processed 1 queries, with 1 matches, 0 errs
> > [ 8.312764] dyndbg: read 43 bytes from userspace
> > [ 8.313597] dyndbg: query 0: <class D2_CORE +T:foo > on module: <*>
> > [ 8.314697] dyndbg: query 1: <class D2_KMS +T:foo> on module: <*>
> > [ 8.315687] dyndbg: processed 2 queries, with 2 matches, 0 errs
> > # this breaks ??
> > [ 8.320048] dyndbg: read 41 bytes from userspace
> > [ 8.320904] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.321925] dyndbg: unknown flag 'c'
> > [ 8.322525] dyndbg: flags parse failed on 2: +T:foo
> > [ 8.323348] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.324428] dyndbg: processed 2 queries, with 1 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Invalid argument
> > [ 8.325536] dyndbg: read 41 bytes from userspace
> > [ 8.326305] dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > [ 8.327415] dyndbg: unknown flag 'c'
> > [ 8.328138] dyndbg: flags parse failed on 2: +T:foo
> > [ 8.328993] dyndbg: query 1: <class,D2_KMS,+T:foo> on module: <*>
> > [ 8.330035] dyndbg: processed 2 queries, with 1 matches, 1 errs
> > dd-tools.rc: line 4: echo: write error: Invalid argument
> > : 0 matches on =Tl
> > : 0 matches on =Tmf
> > did do_prints
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 3/3 #P:4
> > #
> > # _-----=> irqs-off/BH-disabled
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / _-=> migrate-disable
> > # |||| / delay
> > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> > # | | | ||||| | |
> > dd-selftest.rc-375 [001] ..... 6.934983: tracing_mark_write: here comes the WARN
> > dd-selftest.rc-375 [003] ..... 8.208645: tracing_mark_write: test_private_trace about to do_prints
> > dd-selftest.rc-375 [003] ..... 8.539307: tracing_mark_write: test_private_trace_2 about to do_prints
> > EOF
> >
The root cause is parsing error in read_T_args. I will fix it in the
next patchset.
> > function test_private_trace_3 {
> > echo "# TEST_PRIVATE_TRACE_3"
> >
> > ddcmd =_
> > rmmod test_dynamic_debug
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> >
> > ddcmd open foo # gets already open err
> > modprobe test_dynamic_debug dyndbg=class,D2_CORE,+T:foo%class,D2_KMS,+T:foo
> > # triggers:
> > # dyndbg: query 0: <class,D2_CORE,+T:foo> on module: <*>
> > # dyndbg: unknown flag 'c'
> > # dyndbg: flags parse failed
> >
This is again parsing error in read_T_args. I will fix it in the next patchset.
> > check_matches =Tl -v
> > check_matches =Tmf -v
> > echo 1 >/sys/kernel/tracing/tracing_on
> > echo 1 >/sys/kernel/tracing/events/dyndbg/enable
> > tmark should be ready
> > doprints
> > cat /sys/kernel/tracing/trace
> > #rmmod test_dynamic_debug
> > }
> > test_private_trace_3;
> >
> > echo -n "# done on: "
> > date
> >
Thank you for creating the scripts and thorough testing.
I plan to add more trace related tests and hopefully I will send new
patchset version next week.
Thanks,
Lukasz
> >
> > Jim Cromie (11):
> > dyndbg: export _print_hex_dump
> > dyndbg: tweak pr_info format s/trace dest/trace_dest/
> > dyndbg: disambiguate quoting in a debug msg
> > dyndbg: fix old BUG_ON in >control parser
> > dyndbg: change +T:name_terminator to dot
> > dyndbg: treat comma as a token separator
> > dyndbg: __skip_spaces
> > dyndbg: split multi-query strings with %
> > dyndbg: reduce verbose/debug clutter
> > dyndbg: move lock,unlock into ddebug_change, drop goto
> > dyndbg: id the bad word in parse-flags err msg
> >
> > lib/dynamic_debug.c | 52 ++++++++++++++++++++++++++++-----------------
> > 1 file changed, 32 insertions(+), 20 deletions(-)
> >
> > --
> > 2.43.0
> >