Messages in this thread | | | From | Łukasz Bartosik <> | Date | Thu, 14 Dec 2023 16:20:16 +0100 | Subject | Re: [re: PATCH v2 00/15 - 00/11] dyndbg: add support for writing debug logs to trace |
| |
sob., 9 gru 2023 o 01:31 Łukasz Bartosik <lb@semihalf.com> napisał(a): > > pt., 8 gru 2023 o 01:15 Jim Cromie <jim.cromie@gmail.com> 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@semihalf.com/ > > > > 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 > >
| |