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
