Message ID | 20220912052852.1123868-1-jim.cromie@gmail.com (mailing list archive) |
---|---|
Headers | show |
Series | dyndbg: drm.debug adaptation | expand |
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. greg k-h
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.
On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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.
On 10/21/22 05:18, Jani Nikula wrote: > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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
On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > On 10/21/22 05:18, Jani Nikula wrote: > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 ? I didnt knowingly change something, but since its apparently happening, heres a 1st WAG at a possible cause commit ccc2b496324c13e917ef05f563626f4e7826bef1 Author: Jim Cromie <jim.cromie@gmail.com> Date: Sun Sep 11 23:28:51 2022 -0600 drm_print: prefer bare printk KERN_DEBUG on generic fn drm_print.c calls pr_debug() just once, from __drm_printfn_debug(), which is a generic/service fn. The callsite is compile-time enabled by DEBUG in both DYNAMIC_DEBUG=y/n builds. For dyndbg builds, reverting this callsite back to bare printk is correcting a few anti-features: 1- callsite is generic, serves multiple drm users. it is soft-wired on currently by #define DEBUG could accidentally: #> echo -p > /proc/dynamic_debug/control 2- optional "decorations" by dyndbg are unhelpful/misleading here, they describe only the generic site, not end users IOW, 1,2 are unhelpful at best, and possibly confusing. reverting yields a nominal data and text shrink: text data bss dec hex filename 462583 36604 54592 553779 87333 /kernel/drivers/gpu/drm/drm.ko 462515 36532 54592 553639 872a7 -dirty/kernel/drivers/gpu/drm/drm.ko Signed-off-by: Jim Cromie <jim.cromie@gmail.com> Link: https://lore.kernel.org/r/20220912052852.1123868-9-jim.cromie@gmail.com Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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. > > I didnt knowingly change something, but since its apparently happening, > heres a 1st WAG at a possible cause > > commit ccc2b496324c13e917ef05f563626f4e7826bef1 > Author: Jim Cromie <jim.cromie@gmail.com> > Date: Sun Sep 11 23:28:51 2022 -0600 > > drm_print: prefer bare printk KERN_DEBUG on generic fn > > drm_print.c calls pr_debug() just once, from __drm_printfn_debug(), > which is a generic/service fn. The callsite is compile-time enabled > by DEBUG in both DYNAMIC_DEBUG=y/n builds. > > For dyndbg builds, reverting this callsite back to bare printk is > correcting a few anti-features: > > 1- callsite is generic, serves multiple drm users. > it is soft-wired on currently by #define DEBUG > could accidentally: #> echo -p > /proc/dynamic_debug/control > > 2- optional "decorations" by dyndbg are unhelpful/misleading here, > they describe only the generic site, not end users > > IOW, 1,2 are unhelpful at best, and possibly confusing. > > reverting yields a nominal data and text shrink: > > text data bss dec hex filename > 462583 36604 54592 553779 87333 /kernel/drivers/gpu/drm/drm.ko > 462515 36532 54592 553639 872a7 -dirty/kernel/drivers/gpu/drm/drm.ko > > Signed-off-by: Jim Cromie <jim.cromie@gmail.com> > Link: https://lore.kernel.org/r/20220912052852.1123868-9-jim.cromie@gmail.com > Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä <ville.syrjala@linux.intel.com> wrote: > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 ? or is the problem deeper ? theres also this Makefile addition, which I might have oversimplified CFLAGS-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE
On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > <ville.syrjala@linux.intel.com> wrote: > > > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 enables it by accident. We already got one bug report where I had to ask the reporter to rebuild their kernel since this had gotten enabled and we didn't get any debugs from the driver probe. > or is the problem deeper ? > > theres also this Makefile addition, which I might have oversimplified > > CFLAGS-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE
On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä <ville.syrjala@linux.intel.com> wrote: > > On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > > On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > > <ville.syrjala@linux.intel.com> wrote: > > > > > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > > > > > > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 ? commit ccc2b496324c13e917ef05f563626f4e7826bef1 Author: Jim Cromie <jim.cromie@gmail.com> Date: Sun Sep 11 23:28:51 2022 -0600 drm_print: prefer bare printk KERN_DEBUG on generic fn drm_print.c calls pr_debug() just once, from __drm_printfn_debug(), which is a generic/service fn. The callsite is compile-time enabled by DEBUG in both DYNAMIC_DEBUG=y/n builds. For dyndbg builds, reverting this callsite back to bare printk is correcting a few anti-features: 1- callsite is generic, serves multiple drm users. it is soft-wired on currently by #define DEBUG could accidentally: #> echo -p > /proc/dynamic_debug/control 2- optional "decorations" by dyndbg are unhelpful/misleading here, they describe only the generic site, not end users IOW, 1,2 are unhelpful at best, and possibly confusing. This shouldnt have turned off any debug of any kind (drm.debug nor plain pr_debug) but that former callsite no longer does the modname:func:line prefixing that could have been in effect and relied upon (tested for) by your CI I do need to clarify, I dont know exactly what debug/logging output is missing such that CI is failing related, Ive added DEBUG to test-dynmamic-debug, to prove the compile-time enablement of pr_debugs. patch forthcoming, with a couple other fixes. > enables it by accident. We already got one bug report where I had to > ask the reporter to rebuild their kernel since this had gotten > enabled and we didn't get any debugs from the driver probe. > > > or is the problem deeper ? > > > > theres also this Makefile addition, which I might have oversimplified > > > > CFLAGS-$(CONFIG_DRM_USE_DYNAMIC_DEBUG) += -DDYNAMIC_DEBUG_MODULE > > -- > Ville Syrjälä > Intel
On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@gmail.com wrote: > On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä > <ville.syrjala@linux.intel.com> wrote: > > > > On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > > > On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > > > <ville.syrjala@linux.intel.com> wrote: > > > > > > > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > > > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > > > > > > > > > > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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. > > > > commit ccc2b496324c13e917ef05f563626f4e7826bef1 > Author: Jim Cromie <jim.cromie@gmail.com> > Date: Sun Sep 11 23:28:51 2022 -0600 > > drm_print: prefer bare printk KERN_DEBUG on generic fn > > drm_print.c calls pr_debug() just once, from __drm_printfn_debug(), > which is a generic/service fn. The callsite is compile-time enabled > by DEBUG in both DYNAMIC_DEBUG=y/n builds. > > For dyndbg builds, reverting this callsite back to bare printk is > correcting a few anti-features: > > 1- callsite is generic, serves multiple drm users. > it is soft-wired on currently by #define DEBUG > could accidentally: #> echo -p > /proc/dynamic_debug/control > > 2- optional "decorations" by dyndbg are unhelpful/misleading here, > they describe only the generic site, not end users > > IOW, 1,2 are unhelpful at best, and possibly confusing. > > > This shouldnt have turned off any debug of any kind > (drm.debug nor plain pr_debug) > > but that former callsite no longer does the modname:func:line prefixing > that could have been in effect and relied upon (tested for) by your CI > > > 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.
On Mon, Oct 31, 2022 at 7:07 AM Ville Syrjälä <ville.syrjala@linux.intel.com> wrote: > > On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@gmail.com wrote: > > On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä > > <ville.syrjala@linux.intel.com> wrote: > > > > > > On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > > > > On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > > > > <ville.syrjala@linux.intel.com> wrote: > > > > > > > > > > On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > > > > > On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > > > > > > > > > > > > > > > > > > > > > > > > > > > On 10/21/22 05:18, Jani Nikula wrote: > > > > > > > > On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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
On 10/31/22 6:11 PM, jim.cromie@gmail.com wrote: > On Mon, Oct 31, 2022 at 7:07 AM Ville Syrjälä > <ville.syrjala@linux.intel.com> wrote: >> On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@gmail.com wrote: >>> On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä >>> <ville.syrjala@linux.intel.com> wrote: >>>> On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: >>>>> On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä >>>>> <ville.syrjala@linux.intel.com> wrote: >>>>>> On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: >>>>>>> On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: >>>>>>>> >>>>>>>> >>>>>>>> On 10/21/22 05:18, Jani Nikula wrote: >>>>>>>>> On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 Hi, I'm a bit confused with this. My understanding is that there is a 'regression' here from how this used to work. But the 'class' keyword is new - are we sure this is the command-line we are trying to fix? > > [ 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) Ok, I thought the sysfs callbacks only happen when the sysfs file is written? And thus this works once when the sysfs file is explicitly written by the user after boot but not before then? Thanks, -Jason > > 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
On Mon, Oct 31, 2022 at 08:20:54PM -0400, Jason Baron wrote: > > > On 10/31/22 6:11 PM, jim.cromie@gmail.com wrote: > > On Mon, Oct 31, 2022 at 7:07 AM Ville Syrjälä > > <ville.syrjala@linux.intel.com> wrote: > >> On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@gmail.com wrote: > >>> On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä > >>> <ville.syrjala@linux.intel.com> wrote: > >>>> On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > >>>>> On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > >>>>> <ville.syrjala@linux.intel.com> wrote: > >>>>>> On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > >>>>>>> On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > >>>>>>>> > >>>>>>>> > >>>>>>>> On 10/21/22 05:18, Jani Nikula wrote: > >>>>>>>>> On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 > > Hi, > > I'm a bit confused with this. My understanding is that there > is a 'regression' here from how this used to work. But the > 'class' keyword is new - are we sure this is the command-line > we are trying to fix? The thing we need fixed is just the bog standard drm.debug=0xe etc.
On Tue, Nov 1, 2022 at 2:52 AM Ville Syrjälä <ville.syrjala@linux.intel.com> wrote: > > On Mon, Oct 31, 2022 at 08:20:54PM -0400, Jason Baron wrote: > > > > > > On 10/31/22 6:11 PM, jim.cromie@gmail.com wrote: > > > On Mon, Oct 31, 2022 at 7:07 AM Ville Syrjälä > > > <ville.syrjala@linux.intel.com> wrote: > > >> On Sun, Oct 30, 2022 at 08:42:52AM -0600, jim.cromie@gmail.com wrote: > > >>> On Thu, Oct 27, 2022 at 2:10 PM Ville Syrjälä > > >>> <ville.syrjala@linux.intel.com> wrote: > > >>>> On Thu, Oct 27, 2022 at 01:55:39PM -0600, jim.cromie@gmail.com wrote: > > >>>>> On Thu, Oct 27, 2022 at 9:59 AM Ville Syrjälä > > >>>>> <ville.syrjala@linux.intel.com> wrote: > > >>>>>> On Thu, Oct 27, 2022 at 09:37:52AM -0600, jim.cromie@gmail.com wrote: > > >>>>>>> On Thu, Oct 27, 2022 at 9:08 AM Jason Baron <jbaron@akamai.com> wrote: > > >>>>>>>> > > >>>>>>>> > > >>>>>>>> On 10/21/22 05:18, Jani Nikula wrote: > > >>>>>>>>> On Thu, 20 Oct 2022, Ville Syrjälä <ville.syrjala@linux.intel.com> 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 > > > > Hi, > > > > I'm a bit confused with this. My understanding is that there > > is a 'regression' here from how this used to work. But the > > 'class' keyword is new - are we sure this is the command-line > > we are trying to fix? the regression here is that previously, any late changes to drm.debug are seen by all callers of drm_debug_enabled(), which checks the bits when called. Now, the change to drm.debug causes updates to currently loaded modules' prdbgs. But module loading of dependent modules is incomplete, and those prdbgs are too late. > > The thing we need fixed is just the bog standard drm.debug=0xe etc. my example was unfortunate, I repeated the test with options drm debug=0x1f the results are the same, dyndbgs callback applies the class queries, but the helper, driver modules arent yet loaded, so the class'd prdbgs arent there to be enabled. The Notional fix (Im working on it) dyndbg gets static list of CLASSMAPS, ddebug_attach_module_classes() can then distinguish the "owner" of each classmap (the 1st module declaring it), from the subsequently loaded modules (which reuse the same previously declared classmap) as subsequent modules (say drm_kms_helper) refs the DRM_UT_* classmap (just attached to drm module), ddebug_attach_module_classes() can invoke the callback to reapply drm.debug to the newly loaded module. or so I think. > -- > Ville Syrjälä > Intel