Re: [Intel-gfx] [PATCH v7 0/9] dyndbg: drm.debug adaptation

[jim . cromie]

On Mon, Oct 31, 2022 at 7:07 AM Ville Syrjälä
<ville.syrjala@xxxxxxxxxxxxxxx> wrote:
>
> On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@xxxxxxxxx wrote:
> > On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä
> > <ville.syrjala@xxxxxxxxxxxxxxx> wrote:
> > >
> > > On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@xxxxxxxxx wrote:
> > > > On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä
> > > > <ville.syrjala@xxxxxxxxxxxxxxx> wrote:
> > > > >
> > > > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@xxxxxxxxx wrote:
> > > > > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@xxxxxxxxxx> wrote:
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > > On 10/21/22 05:18, Jani Nikula wrote:
> > > > > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@xxxxxxxxxxxxxxx> wrote:
> > > > > > > >> On Sat, Sep 24, 2022 at 03:02:34PM +0200, Greg KH wrote:
> > > > > > > >>> On Sun, Sep 11, 2022 at 11:28:43PM -0600, Jim Cromie wrote:
> > > > > > > >>>> hi Greg, Dan, Jason, DRM-folk,
> > > > > > > >>>>
> > > > > > > >>>> heres follow-up to V6:
> > > > > > > >>>>   rebased on driver-core/driver-core-next for -v6 applied bits (thanks)
> > > > > > > >>>>   rework drm_debug_enabled{_raw,_instrumented,} per Dan.
> > > > > > > >>>>
> > > > > > > >>>> It excludes:
> > > > > > > >>>>   nouveau parts (immature)
> > > > > > > >>>>   tracefs parts (I missed --to=Steve on v6)
> > > > > > > >>>>   split _ddebug_site and de-duplicate experiment (way unready)
> > > > > > > >>>>
> > > > > > > >>>> IOW, its the remaining commits of V6 on which Dan gave his Reviewed-by.
> > > > > > > >>>>
> > > > > > > >>>> If these are good to apply, I'll rebase and repost the rest separately.
> > > > > > > >>>
> > > > > > > >>> All now queued up, thanks.
> > > > > > > >>
> > > > > > > >> This stuff broke i915 debugs. When I first load i915 no debug prints are
> > > > > > > >> produced. If I then go fiddle around in /sys/module/drm/parameters/debug
> > > > > > > >> the debug prints start to suddenly work.
> > > > > > > >
> > > > > > > > Wait what? I always assumed the default behaviour would stay the same,
> > > > > > > > which is usually how we roll. It's a regression in my books. We've got a
> > > > > > > > CI farm that's not very helpful in terms of dmesg logging right now
> > > > > > > > because of this.
> > > > > > > >
> > > > > > > > BR,
> > > > > > > > Jani.
> > > > > > > >
> > > > > > > >
> > > > > > >
> > > > > > > That doesn't sound good - so you are saying that prior to this change some
> > > > > > > of the drm debugs were default enabled. But now you have to manually enable
> > > > > > > them?
> > > > > > >
> > > > > > > Thanks,
> > > > > > >
> > > > > > > -Jason
> > > > > >
> > > > > >
> > > > > > Im just seeing this now.
> > > > > > Any new details ?
> > > > >
> > > > > No. We just disabled it as BROKEN for now. I was just today thinking
> > > > > about sending that patch out if no solutin is forthcoming soon since
> > > > > we need this working before 6.1 is released.
> > > > >
> > > > > Pretty sure you should see the problem immediately with any driver
> > > > > (at least if it's built as a module, didn't try builtin). Or at least
> > > > > can't think what would make i915 any more special.
> > > > >
> > > >
> > > > So, I should note -
> > > > 99% of my time & energy on this dyndbg + drm patchset
> > > > has been done using virtme,
> > > > so my world-view (and dev-hack-test env) has been smaller, simpler
> > > > maybe its been fatally simplistic.
> > > >
> > > > ive just rebuilt v6.0  (before the trouble)
> > > > and run it thru my virtual home box,
> > > > I didnt see any unfamiliar drm-debug output
> > > > that I might have inadvertently altered somehow
> > > >
> > > > I have some real HW I can put a reference kernel on,0
> > > > to look for the missing output, but its all gonna take some time,
> > > > esp to tighten up my dev-test-env
> > > >
> > > > in the meantime, there is:
> > > >
> > > > config DRM_USE_DYNAMIC_DEBUG
> > > > bool "use dynamic debug to implement drm.debug"
> > > > default y
> > > > depends on DRM
> > > > depends on DYNAMIC_DEBUG || DYNAMIC_DEBUG_CORE
> > > > depends on JUMP_LABEL
> > > > help
> > > >   Use dynamic-debug to avoid drm_debug_enabled() runtime overheads.
> > > >   Due to callsite counts in DRM drivers (~4k in amdgpu) and 56
> > > >   bytes per callsite, the .data costs can be substantial, and
> > > >   are therefore configurable.
> > > >
> > > > Does changing the default fix things for i915 dmesg ?
> > >
> > > I think we want to mark it BROKEN in addition to make sure no one
> >
> > Ok, I get the distinction now.
> > youre spelling that
> >   depends on BROKEN
> >
> > I have a notional explanation, and a conflating commit:
> >
> > can you eliminate
> > git log -p ccc2b496324c13e917ef05f563626f4e7826bef1
> >
> > as the cause ?
>
> Reverting that doesn't help.
>

thanks for eliminating it.

> >
> > I do need to clarify, I dont know exactly what debug/logging output
> > is missing such that CI is failing
>
> CI isn't failing. But any logs it produces are 100% useless,
> as are any user reported logs.
>
> The debugs that are missing are anything not coming directly
> from drm.ko.
>
> The stuff that I see being printed by i915.ko are drm_info()
> and the drm_printer stuff from i915_welcome_messages(). That
> also implies that drm_debug_enabled(DRM_UT_DRIVER) does at
> least still work correctly.
>
> I suspect that the problem is just that the debug calls
> aren't getting patched in when a module loads. And fiddling
> with the modparam after the fact does trigger that somehow.
>

ok, heres the 'tape' of a virtme boot,
then modprobe going wrong.

[    1.785873] dyndbg:   2 debug prints in module intel_rapl_msr
[    2.040598] virtme-init: udev is done
virtme-init: console is ttyS0

> load drm driver
bash-5.2# modprobe i915

> drm module is loaded 1st

[    6.549451] dyndbg: add-module: drm.302 sites
[    6.549991] dyndbg: class[0]: module:drm base:0 len:10 ty:0
[    6.550647] dyndbg:  0: 0 DRM_UT_CORE
[    6.551097] dyndbg:  1: 1 DRM_UT_DRIVER
[    6.551531] dyndbg:  2: 2 DRM_UT_KMS
[    6.551931] dyndbg:  3: 3 DRM_UT_PRIME
[    6.552402] dyndbg:  4: 4 DRM_UT_ATOMIC
[    6.552799] dyndbg:  5: 5 DRM_UT_VBL
[    6.553270] dyndbg:  6: 6 DRM_UT_STATE
[    6.553634] dyndbg:  7: 7 DRM_UT_LEASE
[    6.554043] dyndbg:  8: 8 DRM_UT_DP
[    6.554392] dyndbg:  9: 9 DRM_UT_DRMRES
[    6.554776] dyndbg: module:drm attached 1 classes
[    6.555241] dyndbg: 302 debug prints in module drm

> here modprobe reads /etc/modprobe.d/drm-test.conf:
options drm dyndbg="class DRM_UT_CORE +p; class DRM_UT_DRIVER +p"
and dyndbg applies it

[    6.564284] dyndbg: module: drm dyndbg="class DRM_UT_CORE +p; class
DRM_UT_DRIVER +p"
[    6.564957] dyndbg: query 0: "class DRM_UT_CORE +p" mod:drm
[    6.565348] dyndbg: split into words: "class" "DRM_UT_CORE" "+p"
[    6.565836] dyndbg: op='+'
[    6.566059] dyndbg: flags=0x1
[    6.566321] dyndbg: *flagsp=0x1 *maskp=0xffffffff
[    6.566875] dyndbg: parsed: func="" file="" module="drm" format=""
lineno=0-0 class=DRM_UT_CORE
[    6.568753] dyndbg: applied: func="" file="" module="drm" format=""
lineno=0-0 class=DRM_UT_CORE
[    6.569473] dyndbg: query 1: "class DRM_UT_DRIVER +p" mod:drm
[    6.570139] dyndbg: split into words: "class" "DRM_UT_DRIVER" "+p"
[    6.570522] dyndbg: op='+'
[    6.570699] dyndbg: flags=0x1
[    6.570893] dyndbg: *flagsp=0x1 *maskp=0xffffffff
[    6.571200] dyndbg: parsed: func="" file="" module="drm" format=""
lineno=0-0 class=DRM_UT_DRIVER
[    6.571778] dyndbg: no matches for query
[    6.572031] dyndbg: no-match: func="" file="" module="drm"
format="" lineno=0-0 class=DRM_UT_DRIVER
[    6.572615] dyndbg: processed 2 queries, with 61 matches, 0 errs
[    6.573286] ACPI: bus type drm_connector registered

next required module is loaded, but drm.debug isnt propagated.

[    6.578645] dyndbg: add-module: drm_kms_helper.94 sites
[    6.579487] dyndbg: class[0]: module:drm_kms_helper base:0 len:10 ty:0
[    6.580639] dyndbg:  0: 0 DRM_UT_CORE
[    6.581135] dyndbg:  1: 1 DRM_UT_DRIVER
[    6.581651] dyndbg:  2: 2 DRM_UT_KMS
[    6.582178] dyndbg:  3: 3 DRM_UT_PRIME
[    6.582927] dyndbg:  4: 4 DRM_UT_ATOMIC
[    6.583627] dyndbg:  5: 5 DRM_UT_VBL
[    6.584350] dyndbg:  6: 6 DRM_UT_STATE
[    6.584999] dyndbg:  7: 7 DRM_UT_LEASE
[    6.585699] dyndbg:  8: 8 DRM_UT_DP
[    6.586354] dyndbg:  9: 9 DRM_UT_DRMRES
[    6.587040] dyndbg: module:drm_kms_helper attached 1 classes
[    6.588103] dyndbg:  94 debug prints in module drm_kms_helper

and so on

[    6.595628] dyndbg: add-module: drm_display_helper.150 sites
[    6.596442] dyndbg: class[0]: module:drm_display_helper base:0 len:10 ty:0
[    6.597453] dyndbg:  0: 0 DRM_UT_CORE
...
[    6.601678] dyndbg: module:drm_display_helper attached 1 classes
[    6.602335] dyndbg: 150 debug prints in module drm_display_helper

[    6.692760] dyndbg: add-module: i915.1657 sites
[    6.693023] dyndbg: class[0]: module:i915 base:0 len:10 ty:0
[    6.693323] dyndbg:  0: 0 DRM_UT_CORE
....
[    6.695220] dyndbg: module:i915 attached 1 classes
[    6.695463] dyndbg: 1657 debug prints in module i915
bash-5.2#
bash-5.2#


So, what I think I need to add:

ddebug_add_module()  scans the module being loaded,
looking for a param thats wired to dyndbg's modparam callback.
Then it calls that callback, with the val of the sysfs-node
(drm.debug in this case), and the module (i915)

the callback will then run the query to enable callsites per drm.debug.

I'll guess the kparams I need to find are in a section somewhere
Anyone want to toss a lawn-dart at the code I need to look at, copy ?

> --
> Ville Syrjälä
> Intel

thanks again
Jim