| Message ID | 20211111220206.121610-9-jim.cromie@gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | use DYNAMIC_DEBUG to implement DRM.debug & DRM.trace | expand |
On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > Sean Paul proposed, in: > https://patchwork.freedesktop.org/series/78133/ > drm/trace: Mirror DRM debug logs to tracefs > > His patchset's objective is to be able to independently steer some of > the drm.debug stream to an alternate tracing destination, by splitting > drm_debug_enabled() into syslog & trace flavors, and enabling them > separately. 2 advantages were identified: > > 1- syslog is heavyweight, tracefs is much lighter > 2- separate selection of enabled categories means less traffic > > Dynamic-Debug can do 2nd exceedingly well: > > A- all work is behind jump-label's NOOP, zero off cost. > B- exact site selectivity, precisely the useful traffic. > can tailor enabled set interactively, at shell. > > Since the tracefs interface is effective for drm (the threads suggest > so), adding that interface to dynamic-debug has real potential for > everyone including drm. > > if CONFIG_TRACING: > > Grab Sean's trace_init/cleanup code, use it to provide tracefs > available by default to all pr_debugs. This will likely need some > further per-module treatment; perhaps something reflecting hierarchy > of module,file,function,line, maybe with a tuned flattening. > > endif CONFIG_TRACING > > Add a new +T flag to enable tracing, independent of +p, and add and > use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > the flag checks. Existing code treats T like other flags. I posted a patchset a while ago to do something very similar, but that got stalled for some reason and I unfortunately didn't follow it up: https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/ A key difference between that patchset and this patch (besides that small fact that I used +x instead of +T) was that my patchset allowed the dyndbg trace to be emitted to the main buffer and did not force them to be in an instance-specific buffer. That feature is quite important at least for my use case since I often use dyndbg combined with function tracing, and the latter doesn't work on non-main instances according to Documentation/trace/ftrace.rst. For example, here's a random example of a bootargs from one of my recent debugging sessions: trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci* ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x"
On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: >> Sean Paul proposed, in: >> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ >> drm/trace: Mirror DRM debug logs to tracefs >> >> His patchset's objective is to be able to independently steer some of >> the drm.debug stream to an alternate tracing destination, by splitting >> drm_debug_enabled() into syslog & trace flavors, and enabling them >> separately. 2 advantages were identified: >> >> 1- syslog is heavyweight, tracefs is much lighter >> 2- separate selection of enabled categories means less traffic >> >> Dynamic-Debug can do 2nd exceedingly well: >> >> A- all work is behind jump-label's NOOP, zero off cost. >> B- exact site selectivity, precisely the useful traffic. >> can tailor enabled set interactively, at shell. >> >> Since the tracefs interface is effective for drm (the threads suggest >> so), adding that interface to dynamic-debug has real potential for >> everyone including drm. >> >> if CONFIG_TRACING: >> >> Grab Sean's trace_init/cleanup code, use it to provide tracefs >> available by default to all pr_debugs. This will likely need some >> further per-module treatment; perhaps something reflecting hierarchy >> of module,file,function,line, maybe with a tuned flattening. >> >> endif CONFIG_TRACING >> >> Add a new +T flag to enable tracing, independent of +p, and add and >> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate >> the flag checks. Existing code treats T like other flags. > > I posted a patchset a while ago to do something very similar, but that > got stalled for some reason and I unfortunately didn't follow it up: > > https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > > A key difference between that patchset and this patch (besides that > small fact that I used +x instead of +T) was that my patchset allowed > the dyndbg trace to be emitted to the main buffer and did not force them > to be in an instance-specific buffer. Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different sources as you mentioned. Thanks, -Jason > > That feature is quite important at least for my use case since I often > use dyndbg combined with function tracing, and the latter doesn't work > on non-main instances according to Documentation/trace/ftrace.rst. > > For example, here's a random example of a bootargs from one of my recent > debugging sessions: > > trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci* > ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x" >
On Fri, 12 Nov 2021 10:08:41 -0500 Jason Baron <jbaron@akamai.com> wrote: > > A key difference between that patchset and this patch (besides that > > small fact that I used +x instead of +T) was that my patchset allowed > > the dyndbg trace to be emitted to the main buffer and did not force them > > to be in an instance-specific buffer. > > Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different > sources as you mentioned. I do not want anything to print to the "main buffer" that can not be filtered or turned off by the tracing infrastructure itself (aka tracefs file system). Once we allow that, then the trace file will become useless because everything will write to the main buffer and fill it with noise. Events that can be enabled and disabled from tracefs are fine, as they can be limited. This is why I added that nasty warning if people leave around trace_printk(), because it does exactly this (write to the main buffer). It's fine for debugging a custom kernel, but should never be enabled in something that is shipped, or part of mainline. -- Steve
On 11/12/21 12:07 PM, Steven Rostedt wrote: > On Fri, 12 Nov 2021 10:08:41 -0500 > Jason Baron <jbaron@akamai.com> wrote: > >>> A key difference between that patchset and this patch (besides that >>> small fact that I used +x instead of +T) was that my patchset allowed >>> the dyndbg trace to be emitted to the main buffer and did not force them >>> to be in an instance-specific buffer. >> >> Yes, I agree I'd prefer that we print here to the 'main' buffer - it seems to keep things simpler and easier to combine the output from different >> sources as you mentioned. > > I do not want anything to print to the "main buffer" that can not be > filtered or turned off by the tracing infrastructure itself (aka tracefs > file system). > > Once we allow that, then the trace file will become useless because > everything will write to the main buffer and fill it with noise. > > Events that can be enabled and disabled from tracefs are fine, as they can > be limited. This is why I added that nasty warning if people leave around > trace_printk(), because it does exactly this (write to the main buffer). > It's fine for debugging a custom kernel, but should never be enabled in > something that is shipped, or part of mainline. > > -- Steve > Ok, it looks like Vincent's patch defines a dyndbg event and then uses 'trace_dyndbg()' to output to the 'main' log. So all dynamic output to the 'main' ftrace buffer goes through that event if I understand it correctly. Here's a pointer to it for reference: https://lore.kernel.org/lkml/20200825153338.17061-3-vincent.whitchurch@axis.com/ Would you be ok with that approach? Thanks, -Jason
On Fri, 12 Nov 2021 12:32:23 -0500 Jason Baron <jbaron@akamai.com> wrote: > Ok, it looks like Vincent's patch defines a dyndbg event and then uses > 'trace_dyndbg()' to output to the 'main' log. So all dynamic output to > the 'main' ftrace buffer goes through that event if I understand it > correctly. Here's a pointer to it for reference: > > https://lore.kernel.org/lkml/20200825153338.17061-3-vincent.whitchurch@axis.com/ > > Would you be ok with that approach? Yes that approach is fine, because it doesn't actually go to the main log unless you enable the dyndbg trace event in the main buffer. You could also enable that event in an instance and have it go there. -- Steve
On Fri, 12 Nov 2021 10:08:41 -0500 Jason Baron <jbaron@akamai.com> wrote: > On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > > On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > >> Sean Paul proposed, in: > >> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > >> drm/trace: Mirror DRM debug logs to tracefs > >> > >> His patchset's objective is to be able to independently steer some of > >> the drm.debug stream to an alternate tracing destination, by splitting > >> drm_debug_enabled() into syslog & trace flavors, and enabling them > >> separately. 2 advantages were identified: > >> > >> 1- syslog is heavyweight, tracefs is much lighter > >> 2- separate selection of enabled categories means less traffic > >> > >> Dynamic-Debug can do 2nd exceedingly well: > >> > >> A- all work is behind jump-label's NOOP, zero off cost. > >> B- exact site selectivity, precisely the useful traffic. > >> can tailor enabled set interactively, at shell. > >> > >> Since the tracefs interface is effective for drm (the threads suggest > >> so), adding that interface to dynamic-debug has real potential for > >> everyone including drm. > >> > >> if CONFIG_TRACING: > >> > >> Grab Sean's trace_init/cleanup code, use it to provide tracefs > >> available by default to all pr_debugs. This will likely need some > >> further per-module treatment; perhaps something reflecting hierarchy > >> of module,file,function,line, maybe with a tuned flattening. > >> > >> endif CONFIG_TRACING > >> > >> Add a new +T flag to enable tracing, independent of +p, and add and > >> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > >> the flag checks. Existing code treats T like other flags. > > > > I posted a patchset a while ago to do something very similar, but that > > got stalled for some reason and I unfortunately didn't follow it up: > > > > https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > > > > A key difference between that patchset and this patch (besides that > > small fact that I used +x instead of +T) was that my patchset allowed > > the dyndbg trace to be emitted to the main buffer and did not force them > > to be in an instance-specific buffer. > > Yes, I agree I'd prefer that we print here to the 'main' buffer - it > seems to keep things simpler and easier to combine the output from > different sources as you mentioned. Hi, I'm not quite sure I understand this discussion, but I would like to remind you all of what Sean's original work is about: Userspace configures DRM tracing into a flight recorder buffer (I guess this is what you refer to "instance-specific buffer"). Userspace runs happily for months, and then hits a problem: a failure in the DRM sub-system most likely, e.g. an ioctl that should never fail, failed. Userspace handles that failure by dumping the flight recorder buffer into a file and saving or sending a bug report. The flight recorder contents give a log of all relevant DRM in-kernel actions leading to the unexpected failure to help developers debug it. I don't mind if one can additionally send the flight recorder stream to the main buffer, but I do want the separate flight recorder buffer to be an option so that a) unrelated things cannot flood the interesting bits out of it, and b) the scope of collected information is relevant. The very reason for this work is problems that are very difficult to reproduce in practice, either because the problem itself is triggered very rarely and randomly, or because the end users of the system have either no knowledge or no access to reconfigure debug logging and then reproduce the problem with good debug logs. Thank you very much for pushing this work forward! Thanks, pq > > Thanks, > > -Jason > > > > > That feature is quite important at least for my use case since I often > > use dyndbg combined with function tracing, and the latter doesn't work > > on non-main instances according to Documentation/trace/ftrace.rst. > > > > For example, here's a random example of a bootargs from one of my recent > > debugging sessions: > > > > trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci* > > ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x" > >
On 11/16/21 3:46 AM, Pekka Paalanen wrote: > On Fri, 12 Nov 2021 10:08:41 -0500 > Jason Baron <jbaron@akamai.com> wrote: > >> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: >>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: >>>> Sean Paul proposed, in: >>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ >>>> drm/trace: Mirror DRM debug logs to tracefs >>>> >>>> His patchset's objective is to be able to independently steer some of >>>> the drm.debug stream to an alternate tracing destination, by splitting >>>> drm_debug_enabled() into syslog & trace flavors, and enabling them >>>> separately. 2 advantages were identified: >>>> >>>> 1- syslog is heavyweight, tracefs is much lighter >>>> 2- separate selection of enabled categories means less traffic >>>> >>>> Dynamic-Debug can do 2nd exceedingly well: >>>> >>>> A- all work is behind jump-label's NOOP, zero off cost. >>>> B- exact site selectivity, precisely the useful traffic. >>>> can tailor enabled set interactively, at shell. >>>> >>>> Since the tracefs interface is effective for drm (the threads suggest >>>> so), adding that interface to dynamic-debug has real potential for >>>> everyone including drm. >>>> >>>> if CONFIG_TRACING: >>>> >>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs >>>> available by default to all pr_debugs. This will likely need some >>>> further per-module treatment; perhaps something reflecting hierarchy >>>> of module,file,function,line, maybe with a tuned flattening. >>>> >>>> endif CONFIG_TRACING >>>> >>>> Add a new +T flag to enable tracing, independent of +p, and add and >>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate >>>> the flag checks. Existing code treats T like other flags. >>> >>> I posted a patchset a while ago to do something very similar, but that >>> got stalled for some reason and I unfortunately didn't follow it up: >>> >>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ >>> >>> A key difference between that patchset and this patch (besides that >>> small fact that I used +x instead of +T) was that my patchset allowed >>> the dyndbg trace to be emitted to the main buffer and did not force them >>> to be in an instance-specific buffer. >> >> Yes, I agree I'd prefer that we print here to the 'main' buffer - it >> seems to keep things simpler and easier to combine the output from >> different sources as you mentioned. > > Hi, > > I'm not quite sure I understand this discussion, but I would like to > remind you all of what Sean's original work is about: > > Userspace configures DRM tracing into a flight recorder buffer (I guess > this is what you refer to "instance-specific buffer"). > > Userspace runs happily for months, and then hits a problem: a failure > in the DRM sub-system most likely, e.g. an ioctl that should never > fail, failed. Userspace handles that failure by dumping the flight > recorder buffer into a file and saving or sending a bug report. The > flight recorder contents give a log of all relevant DRM in-kernel > actions leading to the unexpected failure to help developers debug it. > > I don't mind if one can additionally send the flight recorder stream to > the main buffer, but I do want the separate flight recorder buffer to > be an option so that a) unrelated things cannot flood the interesting > bits out of it, and b) the scope of collected information is relevant. > > The very reason for this work is problems that are very difficult to > reproduce in practice, either because the problem itself is triggered > very rarely and randomly, or because the end users of the system have > either no knowledge or no access to reconfigure debug logging and then > reproduce the problem with good debug logs. > > Thank you very much for pushing this work forward! > > So I think Vincent (earlier in the thread) was saying that he finds it very helpful have dynamic debug output go to the 'main' trace buffer, while you seem to be saying you'd prefer it just go to dynamic debug specific trace buffer. So we certainly can have dynamic output potentially go to both places - although I think this would mean two tracepoints? But I really wonder if we really need a separate tracing buffer for dynamic debug when what goes to the 'main' buffer can be controlled and filtered to avoid your concern around a 'flood'? Thanks, -Jason
On Thu, 18 Nov 2021 09:29:27 -0500 Jason Baron <jbaron@akamai.com> wrote: > On 11/16/21 3:46 AM, Pekka Paalanen wrote: > > On Fri, 12 Nov 2021 10:08:41 -0500 > > Jason Baron <jbaron@akamai.com> wrote: > > > >> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > >>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > >>>> Sean Paul proposed, in: > >>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > >>>> drm/trace: Mirror DRM debug logs to tracefs > >>>> > >>>> His patchset's objective is to be able to independently steer some of > >>>> the drm.debug stream to an alternate tracing destination, by splitting > >>>> drm_debug_enabled() into syslog & trace flavors, and enabling them > >>>> separately. 2 advantages were identified: > >>>> > >>>> 1- syslog is heavyweight, tracefs is much lighter > >>>> 2- separate selection of enabled categories means less traffic > >>>> > >>>> Dynamic-Debug can do 2nd exceedingly well: > >>>> > >>>> A- all work is behind jump-label's NOOP, zero off cost. > >>>> B- exact site selectivity, precisely the useful traffic. > >>>> can tailor enabled set interactively, at shell. > >>>> > >>>> Since the tracefs interface is effective for drm (the threads suggest > >>>> so), adding that interface to dynamic-debug has real potential for > >>>> everyone including drm. > >>>> > >>>> if CONFIG_TRACING: > >>>> > >>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs > >>>> available by default to all pr_debugs. This will likely need some > >>>> further per-module treatment; perhaps something reflecting hierarchy > >>>> of module,file,function,line, maybe with a tuned flattening. > >>>> > >>>> endif CONFIG_TRACING > >>>> > >>>> Add a new +T flag to enable tracing, independent of +p, and add and > >>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > >>>> the flag checks. Existing code treats T like other flags. > >>> > >>> I posted a patchset a while ago to do something very similar, but that > >>> got stalled for some reason and I unfortunately didn't follow it up: > >>> > >>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > >>> > >>> A key difference between that patchset and this patch (besides that > >>> small fact that I used +x instead of +T) was that my patchset allowed > >>> the dyndbg trace to be emitted to the main buffer and did not force them > >>> to be in an instance-specific buffer. > >> > >> Yes, I agree I'd prefer that we print here to the 'main' buffer - it > >> seems to keep things simpler and easier to combine the output from > >> different sources as you mentioned. > > > > Hi, > > > > I'm not quite sure I understand this discussion, but I would like to > > remind you all of what Sean's original work is about: > > > > Userspace configures DRM tracing into a flight recorder buffer (I guess > > this is what you refer to "instance-specific buffer"). > > > > Userspace runs happily for months, and then hits a problem: a failure > > in the DRM sub-system most likely, e.g. an ioctl that should never > > fail, failed. Userspace handles that failure by dumping the flight > > recorder buffer into a file and saving or sending a bug report. The > > flight recorder contents give a log of all relevant DRM in-kernel > > actions leading to the unexpected failure to help developers debug it. > > > > I don't mind if one can additionally send the flight recorder stream to > > the main buffer, but I do want the separate flight recorder buffer to > > be an option so that a) unrelated things cannot flood the interesting > > bits out of it, and b) the scope of collected information is relevant. > > > > The very reason for this work is problems that are very difficult to > > reproduce in practice, either because the problem itself is triggered > > very rarely and randomly, or because the end users of the system have > > either no knowledge or no access to reconfigure debug logging and then > > reproduce the problem with good debug logs. > > > > Thank you very much for pushing this work forward! > > > > > > So I think Vincent (earlier in the thread) was saying that he finds it > very helpful have dynamic debug output go to the 'main' trace buffer, > while you seem to be saying you'd prefer it just go to dynamic debug > specific trace buffer. Seems like we have different use cases: traditional debugging, and in-production flight recorder for problem reporting. I'm not surprised if they need different treatment. > So we certainly can have dynamic output potentially go to both places - > although I think this would mean two tracepoints? But I really wonder > if we really need a separate tracing buffer for dynamic debug when > what goes to the 'main' buffer can be controlled and filtered to avoid > your concern around a 'flood'? If the DRM tracing goes into the main buffer, then systems in production cannot have any other sub-system traced in a similar fashion. To me it would feel very arrogant to say that to make use of DRM flight recording, you cannot trace much or anything else. The very purpose of the flight recorder is run in production all the time, not in a special debugging session. There is also the question of access and contents of the trace buffer. Ultimately, if automatic bug reports are enabled in a system, the contents of the trace buffer would be sent as-is to some bug tracking system. If there is a chance to put non-DRM stuff in the trace buffer, that could be a security problem. My use case is Weston. When Weston encounters an unexpected problem in production, something should automatically capture the DRM flight recorder contents and save it alongside the Weston log. Would be really nice if Weston itself could do that, but I suspect it is going to need root privileges so it needs some helper daemon. Maybe Sean can reiterate their use case more? Thanks, pq
On 11/18/21 10:24 AM, Pekka Paalanen wrote: > On Thu, 18 Nov 2021 09:29:27 -0500 > Jason Baron <jbaron@akamai.com> wrote: > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote: >>> On Fri, 12 Nov 2021 10:08:41 -0500 >>> Jason Baron <jbaron@akamai.com> wrote: >>> >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: >>>>>> Sean Paul proposed, in: >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ >>>>>> drm/trace: Mirror DRM debug logs to tracefs >>>>>> >>>>>> His patchset's objective is to be able to independently steer some of >>>>>> the drm.debug stream to an alternate tracing destination, by splitting >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them >>>>>> separately. 2 advantages were identified: >>>>>> >>>>>> 1- syslog is heavyweight, tracefs is much lighter >>>>>> 2- separate selection of enabled categories means less traffic >>>>>> >>>>>> Dynamic-Debug can do 2nd exceedingly well: >>>>>> >>>>>> A- all work is behind jump-label's NOOP, zero off cost. >>>>>> B- exact site selectivity, precisely the useful traffic. >>>>>> can tailor enabled set interactively, at shell. >>>>>> >>>>>> Since the tracefs interface is effective for drm (the threads suggest >>>>>> so), adding that interface to dynamic-debug has real potential for >>>>>> everyone including drm. >>>>>> >>>>>> if CONFIG_TRACING: >>>>>> >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs >>>>>> available by default to all pr_debugs. This will likely need some >>>>>> further per-module treatment; perhaps something reflecting hierarchy >>>>>> of module,file,function,line, maybe with a tuned flattening. >>>>>> >>>>>> endif CONFIG_TRACING >>>>>> >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate >>>>>> the flag checks. Existing code treats T like other flags. >>>>> >>>>> I posted a patchset a while ago to do something very similar, but that >>>>> got stalled for some reason and I unfortunately didn't follow it up: >>>>> >>>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ >>>>> >>>>> A key difference between that patchset and this patch (besides that >>>>> small fact that I used +x instead of +T) was that my patchset allowed >>>>> the dyndbg trace to be emitted to the main buffer and did not force them >>>>> to be in an instance-specific buffer. >>>> >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it >>>> seems to keep things simpler and easier to combine the output from >>>> different sources as you mentioned. >>> >>> Hi, >>> >>> I'm not quite sure I understand this discussion, but I would like to >>> remind you all of what Sean's original work is about: >>> >>> Userspace configures DRM tracing into a flight recorder buffer (I guess >>> this is what you refer to "instance-specific buffer"). >>> >>> Userspace runs happily for months, and then hits a problem: a failure >>> in the DRM sub-system most likely, e.g. an ioctl that should never >>> fail, failed. Userspace handles that failure by dumping the flight >>> recorder buffer into a file and saving or sending a bug report. The >>> flight recorder contents give a log of all relevant DRM in-kernel >>> actions leading to the unexpected failure to help developers debug it. >>> >>> I don't mind if one can additionally send the flight recorder stream to >>> the main buffer, but I do want the separate flight recorder buffer to >>> be an option so that a) unrelated things cannot flood the interesting >>> bits out of it, and b) the scope of collected information is relevant. >>> >>> The very reason for this work is problems that are very difficult to >>> reproduce in practice, either because the problem itself is triggered >>> very rarely and randomly, or because the end users of the system have >>> either no knowledge or no access to reconfigure debug logging and then >>> reproduce the problem with good debug logs. >>> >>> Thank you very much for pushing this work forward! >>> >>> >> >> So I think Vincent (earlier in the thread) was saying that he finds it >> very helpful have dynamic debug output go to the 'main' trace buffer, >> while you seem to be saying you'd prefer it just go to dynamic debug >> specific trace buffer. > > Seems like we have different use cases: traditional debugging, and > in-production flight recorder for problem reporting. I'm not surprised > if they need different treatment. > >> So we certainly can have dynamic output potentially go to both places - >> although I think this would mean two tracepoints? But I really wonder >> if we really need a separate tracing buffer for dynamic debug when >> what goes to the 'main' buffer can be controlled and filtered to avoid >> your concern around a 'flood'? > > If the DRM tracing goes into the main buffer, then systems in > production cannot have any other sub-system traced in a similar > fashion. To me it would feel very arrogant to say that to make use of > DRM flight recording, you cannot trace much or anything else. > > The very purpose of the flight recorder is run in production all the > time, not in a special debugging session. > > There is also the question of access and contents of the trace buffer. > Ultimately, if automatic bug reports are enabled in a system, the > contents of the trace buffer would be sent as-is to some bug tracking > system. If there is a chance to put non-DRM stuff in the trace buffer, > that could be a security problem. > > My use case is Weston. When Weston encounters an unexpected problem in > production, something should automatically capture the DRM flight > recorder contents and save it alongside the Weston log. Would be really > nice if Weston itself could do that, but I suspect it is going to need > root privileges so it needs some helper daemon. > > Maybe Sean can reiterate their use case more? > > > Thanks, > pq > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs" buffer to put the dynamic debug output (including drm output from dynamic debug) into. And I was saying let's just put in the 'main' trace buffer (predicated on a dynamic debug specific tracepoint), since there seems to be a a use-case for that and it keeps things simpler. But I went back to Sean's original patch, and it creates a drm specific trace buffer "drm" (via trace_array_get_by_name("drm")). Here: https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5 So I think that may be some of the confusion here? The current thread/ proposal is not for a drm specific trace buffer... Having a subsystem specific trace buffer would allow subsystem specific trace log permissions depending on the sensitivity of the data. But doesn't drm output today go to the system log which is typically world readable today? So I could see us supporting subsystem specific trace buffer output via dynamic debug here. We could add new dev_debug() variants that allow say a trace buffer to be supplied. So in that way subsystems could 'opt-out' of having their data put into the global trace buffer. And perhaps some subsystems we would want to allow output to both buffers? The subsystem specific one and the global one? Thanks, -Jason
On Fri, Nov 19, 2021 at 9:21 AM Jason Baron <jbaron@akamai.com> wrote: > > > > On 11/18/21 10:24 AM, Pekka Paalanen wrote: > > On Thu, 18 Nov 2021 09:29:27 -0500 > > Jason Baron <jbaron@akamai.com> wrote: > > > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote: > >>> On Fri, 12 Nov 2021 10:08:41 -0500 > >>> Jason Baron <jbaron@akamai.com> wrote: > >>> > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > >>>>>> Sean Paul proposed, in: > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > >>>>>> drm/trace: Mirror DRM debug logs to tracefs > >>>>>> > >>>>>> His patchset's objective is to be able to independently steer some of > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them > >>>>>> separately. 2 advantages were identified: > >>>>>> > >>>>>> 1- syslog is heavyweight, tracefs is much lighter > >>>>>> 2- separate selection of enabled categories means less traffic > >>>>>> > >>>>>> Dynamic-Debug can do 2nd exceedingly well: > >>>>>> > >>>>>> A- all work is behind jump-label's NOOP, zero off cost. > >>>>>> B- exact site selectivity, precisely the useful traffic. > >>>>>> can tailor enabled set interactively, at shell. > >>>>>> > >>>>>> Since the tracefs interface is effective for drm (the threads suggest > >>>>>> so), adding that interface to dynamic-debug has real potential for > >>>>>> everyone including drm. > >>>>>> > >>>>>> if CONFIG_TRACING: > >>>>>> > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs > >>>>>> available by default to all pr_debugs. This will likely need some > >>>>>> further per-module treatment; perhaps something reflecting hierarchy > >>>>>> of module,file,function,line, maybe with a tuned flattening. > >>>>>> > >>>>>> endif CONFIG_TRACING > >>>>>> > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > >>>>>> the flag checks. Existing code treats T like other flags. > >>>>> > >>>>> I posted a patchset a while ago to do something very similar, but that > >>>>> got stalled for some reason and I unfortunately didn't follow it up: > >>>>> > >>>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > >>>>> > >>>>> A key difference between that patchset and this patch (besides that > >>>>> small fact that I used +x instead of +T) was that my patchset allowed > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them > >>>>> to be in an instance-specific buffer. > >>>> > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it > >>>> seems to keep things simpler and easier to combine the output from > >>>> different sources as you mentioned. > >>> > >>> Hi, > >>> > >>> I'm not quite sure I understand this discussion, but I would like to > >>> remind you all of what Sean's original work is about: > >>> > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess > >>> this is what you refer to "instance-specific buffer"). > >>> > >>> Userspace runs happily for months, and then hits a problem: a failure > >>> in the DRM sub-system most likely, e.g. an ioctl that should never > >>> fail, failed. Userspace handles that failure by dumping the flight > >>> recorder buffer into a file and saving or sending a bug report. The > >>> flight recorder contents give a log of all relevant DRM in-kernel > >>> actions leading to the unexpected failure to help developers debug it. > >>> > >>> I don't mind if one can additionally send the flight recorder stream to > >>> the main buffer, but I do want the separate flight recorder buffer to > >>> be an option so that a) unrelated things cannot flood the interesting > >>> bits out of it, and b) the scope of collected information is relevant. > >>> > >>> The very reason for this work is problems that are very difficult to > >>> reproduce in practice, either because the problem itself is triggered > >>> very rarely and randomly, or because the end users of the system have > >>> either no knowledge or no access to reconfigure debug logging and then > >>> reproduce the problem with good debug logs. > >>> > >>> Thank you very much for pushing this work forward! > >>> > >>> > >> > >> So I think Vincent (earlier in the thread) was saying that he finds it > >> very helpful have dynamic debug output go to the 'main' trace buffer, > >> while you seem to be saying you'd prefer it just go to dynamic debug > >> specific trace buffer. > > > > Seems like we have different use cases: traditional debugging, and > > in-production flight recorder for problem reporting. I'm not surprised > > if they need different treatment. > > > >> So we certainly can have dynamic output potentially go to both places - > >> although I think this would mean two tracepoints? But I really wonder > >> if we really need a separate tracing buffer for dynamic debug when > >> what goes to the 'main' buffer can be controlled and filtered to avoid > >> your concern around a 'flood'? > > > > If the DRM tracing goes into the main buffer, then systems in > > production cannot have any other sub-system traced in a similar > > fashion. To me it would feel very arrogant to say that to make use of > > DRM flight recording, you cannot trace much or anything else. > > > > The very purpose of the flight recorder is run in production all the > > time, not in a special debugging session. > > > > There is also the question of access and contents of the trace buffer. > > Ultimately, if automatic bug reports are enabled in a system, the > > contents of the trace buffer would be sent as-is to some bug tracking > > system. If there is a chance to put non-DRM stuff in the trace buffer, > > that could be a security problem. > > > > My use case is Weston. When Weston encounters an unexpected problem in > > production, something should automatically capture the DRM flight > > recorder contents and save it alongside the Weston log. Would be really > > nice if Weston itself could do that, but I suspect it is going to need > > root privileges so it needs some helper daemon. > > > > Maybe Sean can reiterate their use case more? > > > > > > Thanks, > > pq > > > > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs" > buffer to put the dynamic debug output (including drm output from dynamic > debug) into. And I was saying let's just put in the 'main' trace buffer > (predicated on a dynamic debug specific tracepoint), since there seems > to be a a use-case for that and it keeps things simpler. > > But I went back to Sean's original patch, and it creates a drm specific > trace buffer "drm" (via trace_array_get_by_name("drm")). Here: > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5 > > So I think that may be some of the confusion here? The current thread/ > proposal is not for a drm specific trace buffer... > while thats true, it was a KISS choice, not intrinsic. Now that a requirement has emerged, I can think about it. I thought use of all the pr_debug()s as a tracefs event provider made sense, since the callsite descriptor is passed in, and could be passed in to the tracefs interface. Vincent's code has the macro magic to define that event, which IIUC is what makes it controllable by ftrace, and therefore acceptable in principle to Steve. Would there be any reason to expand his set of 2 events into dev_dbg, pr_debug etc varieties ? (ie any value to separating dev, !dev ?, maybe so) Sean's code uses trace_array_printk primarily, which is EXPORTed, which is a virtue. Vincents code does +/* + * This code is heavily based on __ftrace_trace_stack(). + * + * Allow 4 levels of nesting: normal, softirq, irq, NMI. + */ to implement +static void dynamic_trace(const char *fmt, va_list args) Has this __ftrace_trace_stack() code been bundled into or hidden under a supported interface ? would it look anything like trace_array_printk() ? what problem is that code solving inside dynamic-debug.c ? > Having a subsystem specific trace buffer would allow subsystem specific > trace log permissions depending on the sensitivity of the data. But > doesn't drm output today go to the system log which is typically world > readable today? > > So I could see us supporting subsystem specific trace buffer output > via dynamic debug here. We could add new dev_debug() variants that > allow say a trace buffer to be supplied. So in that way subsystems > could 'opt-out' of having their data put into the global trace buffer. > And perhaps some subsystems we would want to allow output to both > buffers? The subsystem specific one and the global one? > * trace_array_printk - Print a message to a specific instance * @tr: The instance trace_array descriptor * @ip: The instruction pointer that this is called from. * @fmt: The format to print (printf format) * what happens when @tr == NULL ? It could allow up-flow of events to the global instance > Thanks, > > -Jason > > So I wonder, is there any conceptual utility to this ? echo 1 > instances/foo/filter_up # enable event upflow (or query-time merging?) Maybe enabling this causes other files (the ones missing from instances/foo) to magically appear so all those filtering capacities also appear.
On Fri, 19 Nov 2021 15:46:31 -0700 jim.cromie@gmail.com wrote: > > So I could see us supporting subsystem specific trace buffer output > > via dynamic debug here. We could add new dev_debug() variants that > > allow say a trace buffer to be supplied. So in that way subsystems > > could 'opt-out' of having their data put into the global trace buffer. > > And perhaps some subsystems we would want to allow output to both > > buffers? The subsystem specific one and the global one? > > > > * trace_array_printk - Print a message to a specific instance > * @tr: The instance trace_array descriptor > * @ip: The instruction pointer that this is called from. > * @fmt: The format to print (printf format) > * > > what happens when @tr == NULL ? It does nothing, but perhaps crash the kernel. > It could allow up-flow of events to the global instance Absolutely not! Then it's just a reimplementation of trace_printk(). Which I refuse to have. Nothing should just dump to the main instance. Once we allow that, then everyone will be dumping there and you will no longer be able to trace anything because it will be filled with noise. What is allowed is an event that acts like a trace_printk() but is an event, which you can turn off (have default off), and even pick which instance to go to. > > > Thanks, > > > > -Jason > > > > > > So I wonder, is there any conceptual utility to this ? > > echo 1 > instances/foo/filter_up # enable event upflow (or query-time merging?) > > Maybe enabling this causes other files (the ones missing from > instances/foo) to magically appear > so all those filtering capacities also appear. I've been busy doing other things so I haven't been keeping up with this thread (which I need to go back and read). Perhaps it was already stated, but I don't know why you want that. trace-cmd can read several instances (including the top level one) and interleave them nicely, if that is what you are looking for. So can KernelShark. -- Steve
On Fri, 19 Nov 2021 11:21:36 -0500 Jason Baron <jbaron@akamai.com> wrote: > On 11/18/21 10:24 AM, Pekka Paalanen wrote: > > On Thu, 18 Nov 2021 09:29:27 -0500 > > Jason Baron <jbaron@akamai.com> wrote: > > > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote: > >>> On Fri, 12 Nov 2021 10:08:41 -0500 > >>> Jason Baron <jbaron@akamai.com> wrote: > >>> > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > >>>>>> Sean Paul proposed, in: > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > >>>>>> drm/trace: Mirror DRM debug logs to tracefs > >>>>>> > >>>>>> His patchset's objective is to be able to independently steer some of > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them > >>>>>> separately. 2 advantages were identified: > >>>>>> > >>>>>> 1- syslog is heavyweight, tracefs is much lighter > >>>>>> 2- separate selection of enabled categories means less traffic > >>>>>> > >>>>>> Dynamic-Debug can do 2nd exceedingly well: > >>>>>> > >>>>>> A- all work is behind jump-label's NOOP, zero off cost. > >>>>>> B- exact site selectivity, precisely the useful traffic. > >>>>>> can tailor enabled set interactively, at shell. > >>>>>> > >>>>>> Since the tracefs interface is effective for drm (the threads suggest > >>>>>> so), adding that interface to dynamic-debug has real potential for > >>>>>> everyone including drm. > >>>>>> > >>>>>> if CONFIG_TRACING: > >>>>>> > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs > >>>>>> available by default to all pr_debugs. This will likely need some > >>>>>> further per-module treatment; perhaps something reflecting hierarchy > >>>>>> of module,file,function,line, maybe with a tuned flattening. > >>>>>> > >>>>>> endif CONFIG_TRACING > >>>>>> > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > >>>>>> the flag checks. Existing code treats T like other flags. > >>>>> > >>>>> I posted a patchset a while ago to do something very similar, but that > >>>>> got stalled for some reason and I unfortunately didn't follow it up: > >>>>> > >>>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > >>>>> > >>>>> A key difference between that patchset and this patch (besides that > >>>>> small fact that I used +x instead of +T) was that my patchset allowed > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them > >>>>> to be in an instance-specific buffer. > >>>> > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it > >>>> seems to keep things simpler and easier to combine the output from > >>>> different sources as you mentioned. > >>> > >>> Hi, > >>> > >>> I'm not quite sure I understand this discussion, but I would like to > >>> remind you all of what Sean's original work is about: > >>> > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess > >>> this is what you refer to "instance-specific buffer"). > >>> > >>> Userspace runs happily for months, and then hits a problem: a failure > >>> in the DRM sub-system most likely, e.g. an ioctl that should never > >>> fail, failed. Userspace handles that failure by dumping the flight > >>> recorder buffer into a file and saving or sending a bug report. The > >>> flight recorder contents give a log of all relevant DRM in-kernel > >>> actions leading to the unexpected failure to help developers debug it. > >>> > >>> I don't mind if one can additionally send the flight recorder stream to > >>> the main buffer, but I do want the separate flight recorder buffer to > >>> be an option so that a) unrelated things cannot flood the interesting > >>> bits out of it, and b) the scope of collected information is relevant. > >>> > >>> The very reason for this work is problems that are very difficult to > >>> reproduce in practice, either because the problem itself is triggered > >>> very rarely and randomly, or because the end users of the system have > >>> either no knowledge or no access to reconfigure debug logging and then > >>> reproduce the problem with good debug logs. > >>> > >>> Thank you very much for pushing this work forward! > >>> > >>> > >> > >> So I think Vincent (earlier in the thread) was saying that he finds it > >> very helpful have dynamic debug output go to the 'main' trace buffer, > >> while you seem to be saying you'd prefer it just go to dynamic debug > >> specific trace buffer. > > > > Seems like we have different use cases: traditional debugging, and > > in-production flight recorder for problem reporting. I'm not surprised > > if they need different treatment. > > > >> So we certainly can have dynamic output potentially go to both places - > >> although I think this would mean two tracepoints? But I really wonder > >> if we really need a separate tracing buffer for dynamic debug when > >> what goes to the 'main' buffer can be controlled and filtered to avoid > >> your concern around a 'flood'? > > > > If the DRM tracing goes into the main buffer, then systems in > > production cannot have any other sub-system traced in a similar > > fashion. To me it would feel very arrogant to say that to make use of > > DRM flight recording, you cannot trace much or anything else. > > > > The very purpose of the flight recorder is run in production all the > > time, not in a special debugging session. > > > > There is also the question of access and contents of the trace buffer. > > Ultimately, if automatic bug reports are enabled in a system, the > > contents of the trace buffer would be sent as-is to some bug tracking > > system. If there is a chance to put non-DRM stuff in the trace buffer, > > that could be a security problem. > > > > My use case is Weston. When Weston encounters an unexpected problem in > > production, something should automatically capture the DRM flight > > recorder contents and save it alongside the Weston log. Would be really > > nice if Weston itself could do that, but I suspect it is going to need > > root privileges so it needs some helper daemon. > > > > Maybe Sean can reiterate their use case more? > > > > > > Thanks, > > pq > > > > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs" > buffer to put the dynamic debug output (including drm output from dynamic > debug) into. And I was saying let's just put in the 'main' trace buffer > (predicated on a dynamic debug specific tracepoint), since there seems > to be a a use-case for that and it keeps things simpler. > > But I went back to Sean's original patch, and it creates a drm specific > trace buffer "drm" (via trace_array_get_by_name("drm")). Here: > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5 > > So I think that may be some of the confusion here? The current thread/ > proposal is not for a drm specific trace buffer... Hi Jason, I may very well have confused things, sorry about that. If this series is not superseding the idea of the DRM flight recorder, then don't mind me. It just sounded very similar and I also haven't seen new revisions of the flight recorder in a long time. > Having a subsystem specific trace buffer would allow subsystem specific > trace log permissions depending on the sensitivity of the data. But > doesn't drm output today go to the system log which is typically world > readable today? Yes, and that is exactly the problem. The DRM debug output is so high traffic it would make the system log both unusable due to cruft and slow down the whole machine. The debug output is only useful when something went wrong, and at that point it is too late to enable debugging. That's why a flight recorder with an over-written circular in-memory buffer is needed. The log being world-readable (it's not in every distribution, I believe) only means on that one machine, but there are hopes of making some logs truly world-readable by posting them to the internet (bug reports). I would be very wary of anything uploading my system logs automatically with bug reports, both from the reporter point of view (am I exposing things I don't want to) and from the bug report receiving service point of view (e.g. GDPR regulations). > So I could see us supporting subsystem specific trace buffer output > via dynamic debug here. We could add new dev_debug() variants that > allow say a trace buffer to be supplied. So in that way subsystems > could 'opt-out' of having their data put into the global trace buffer. > And perhaps some subsystems we would want to allow output to both > buffers? The subsystem specific one and the global one? Unfortunately the rest of the discussion goes too high over my head. Thanks, pq
On Mon, Nov 22, 2021 at 2:02 AM Pekka Paalanen <ppaalanen@gmail.com> wrote: > > On Fri, 19 Nov 2021 11:21:36 -0500 > Jason Baron <jbaron@akamai.com> wrote: > > > On 11/18/21 10:24 AM, Pekka Paalanen wrote: > > > On Thu, 18 Nov 2021 09:29:27 -0500 > > > Jason Baron <jbaron@akamai.com> wrote: > > > > > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote: > > >>> On Fri, 12 Nov 2021 10:08:41 -0500 > > >>> Jason Baron <jbaron@akamai.com> wrote: > > >>> > > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > > >>>>>> Sean Paul proposed, in: > > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > > >>>>>> drm/trace: Mirror DRM debug logs to tracefs > > >>>>>> > > >>>>>> His patchset's objective is to be able to independently steer some of > > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting > > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them > > >>>>>> separately. 2 advantages were identified: > > >>>>>> > > >>>>>> 1- syslog is heavyweight, tracefs is much lighter > > >>>>>> 2- separate selection of enabled categories means less traffic > > >>>>>> > > >>>>>> Dynamic-Debug can do 2nd exceedingly well: > > >>>>>> > > >>>>>> A- all work is behind jump-label's NOOP, zero off cost. > > >>>>>> B- exact site selectivity, precisely the useful traffic. > > >>>>>> can tailor enabled set interactively, at shell. > > >>>>>> > > >>>>>> Since the tracefs interface is effective for drm (the threads suggest > > >>>>>> so), adding that interface to dynamic-debug has real potential for > > >>>>>> everyone including drm. > > >>>>>> > > >>>>>> if CONFIG_TRACING: > > >>>>>> > > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs > > >>>>>> available by default to all pr_debugs. This will likely need some > > >>>>>> further per-module treatment; perhaps something reflecting hierarchy > > >>>>>> of module,file,function,line, maybe with a tuned flattening. > > >>>>>> > > >>>>>> endif CONFIG_TRACING > > >>>>>> > > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and > > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > > >>>>>> the flag checks. Existing code treats T like other flags. > > >>>>> > > >>>>> I posted a patchset a while ago to do something very similar, but that > > >>>>> got stalled for some reason and I unfortunately didn't follow it up: > > >>>>> > > >>>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > > >>>>> > > >>>>> A key difference between that patchset and this patch (besides that > > >>>>> small fact that I used +x instead of +T) was that my patchset allowed > > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them > > >>>>> to be in an instance-specific buffer. > > >>>> > > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it > > >>>> seems to keep things simpler and easier to combine the output from > > >>>> different sources as you mentioned. > > >>> > > >>> Hi, > > >>> > > >>> I'm not quite sure I understand this discussion, but I would like to > > >>> remind you all of what Sean's original work is about: > > >>> > > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess > > >>> this is what you refer to "instance-specific buffer"). > > >>> > > >>> Userspace runs happily for months, and then hits a problem: a failure > > >>> in the DRM sub-system most likely, e.g. an ioctl that should never > > >>> fail, failed. Userspace handles that failure by dumping the flight > > >>> recorder buffer into a file and saving or sending a bug report. The > > >>> flight recorder contents give a log of all relevant DRM in-kernel > > >>> actions leading to the unexpected failure to help developers debug it. > > >>> > > >>> I don't mind if one can additionally send the flight recorder stream to > > >>> the main buffer, but I do want the separate flight recorder buffer to > > >>> be an option so that a) unrelated things cannot flood the interesting > > >>> bits out of it, and b) the scope of collected information is relevant. > > >>> > > >>> The very reason for this work is problems that are very difficult to > > >>> reproduce in practice, either because the problem itself is triggered > > >>> very rarely and randomly, or because the end users of the system have > > >>> either no knowledge or no access to reconfigure debug logging and then > > >>> reproduce the problem with good debug logs. > > >>> > > >>> Thank you very much for pushing this work forward! > > >>> > > >>> > > >> > > >> So I think Vincent (earlier in the thread) was saying that he finds it > > >> very helpful have dynamic debug output go to the 'main' trace buffer, > > >> while you seem to be saying you'd prefer it just go to dynamic debug > > >> specific trace buffer. > > > > > > Seems like we have different use cases: traditional debugging, and > > > in-production flight recorder for problem reporting. I'm not surprised > > > if they need different treatment. > > > > > >> So we certainly can have dynamic output potentially go to both places - > > >> although I think this would mean two tracepoints? But I really wonder > > >> if we really need a separate tracing buffer for dynamic debug when > > >> what goes to the 'main' buffer can be controlled and filtered to avoid > > >> your concern around a 'flood'? > > > > > > If the DRM tracing goes into the main buffer, then systems in > > > production cannot have any other sub-system traced in a similar > > > fashion. To me it would feel very arrogant to say that to make use of > > > DRM flight recording, you cannot trace much or anything else. > > > > > > The very purpose of the flight recorder is run in production all the > > > time, not in a special debugging session. > > > > > > There is also the question of access and contents of the trace buffer. > > > Ultimately, if automatic bug reports are enabled in a system, the > > > contents of the trace buffer would be sent as-is to some bug tracking > > > system. If there is a chance to put non-DRM stuff in the trace buffer, > > > that could be a security problem. > > > > > > My use case is Weston. When Weston encounters an unexpected problem in > > > production, something should automatically capture the DRM flight > > > recorder contents and save it alongside the Weston log. Would be really > > > nice if Weston itself could do that, but I suspect it is going to need > > > root privileges so it needs some helper daemon. > > > > > > Maybe Sean can reiterate their use case more? > > > > > > > > > Thanks, > > > pq > > > > > > > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs" > > buffer to put the dynamic debug output (including drm output from dynamic > > debug) into. And I was saying let's just put in the 'main' trace buffer > > (predicated on a dynamic debug specific tracepoint), since there seems > > to be a a use-case for that and it keeps things simpler. > > > > But I went back to Sean's original patch, and it creates a drm specific > > trace buffer "drm" (via trace_array_get_by_name("drm")). Here: > > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5 > > > > So I think that may be some of the confusion here? The current thread/ > > proposal is not for a drm specific trace buffer... > > Hi Jason, > > I may very well have confused things, sorry about that. If this series > is not superseding the idea of the DRM flight recorder, then don't mind > me. It just sounded very similar and I also haven't seen new revisions > of the flight recorder in a long time. IMO this series has clarified the requirement for a flight-recorder mode, which seems to fit ideally in a separate instance. > > Having a subsystem specific trace buffer would allow subsystem specific > > trace log permissions depending on the sensitivity of the data. But > > doesn't drm output today go to the system log which is typically world > > readable today? > > Yes, and that is exactly the problem. The DRM debug output is so high > traffic it would make the system log both unusable due to cruft and > slow down the whole machine. The debug output is only useful when > something went wrong, and at that point it is too late to enable > debugging. That's why a flight recorder with an over-written circular > in-memory buffer is needed. Seans patch reuses enum drm_debug_category to split the tracing stream into 10 sub-streams - how much traffic from each ? - are some sub-streams more valuable for post-mortem ? - any value from further refinement of categories ? - drop irrelevant callsites individually to reduce clutter, extend buffer time/space ?
On Mon, 22 Nov 2021 15:42:38 -0700 jim.cromie@gmail.com wrote: > On Mon, Nov 22, 2021 at 2:02 AM Pekka Paalanen <ppaalanen@gmail.com> wrote: > > > > On Fri, 19 Nov 2021 11:21:36 -0500 > > Jason Baron <jbaron@akamai.com> wrote: > > > > > On 11/18/21 10:24 AM, Pekka Paalanen wrote: > > > > On Thu, 18 Nov 2021 09:29:27 -0500 > > > > Jason Baron <jbaron@akamai.com> wrote: > > > > > > > >> On 11/16/21 3:46 AM, Pekka Paalanen wrote: > > > >>> On Fri, 12 Nov 2021 10:08:41 -0500 > > > >>> Jason Baron <jbaron@akamai.com> wrote: > > > >>> > > > >>>> On 11/12/21 6:49 AM, Vincent Whitchurch wrote: > > > >>>>> On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > > > >>>>>> Sean Paul proposed, in: > > > >>>>>> https://urldefense.com/v3/__https://patchwork.freedesktop.org/series/78133/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRA8Dki4A$ > > > >>>>>> drm/trace: Mirror DRM debug logs to tracefs > > > >>>>>> > > > >>>>>> His patchset's objective is to be able to independently steer some of > > > >>>>>> the drm.debug stream to an alternate tracing destination, by splitting > > > >>>>>> drm_debug_enabled() into syslog & trace flavors, and enabling them > > > >>>>>> separately. 2 advantages were identified: > > > >>>>>> > > > >>>>>> 1- syslog is heavyweight, tracefs is much lighter > > > >>>>>> 2- separate selection of enabled categories means less traffic > > > >>>>>> > > > >>>>>> Dynamic-Debug can do 2nd exceedingly well: > > > >>>>>> > > > >>>>>> A- all work is behind jump-label's NOOP, zero off cost. > > > >>>>>> B- exact site selectivity, precisely the useful traffic. > > > >>>>>> can tailor enabled set interactively, at shell. > > > >>>>>> > > > >>>>>> Since the tracefs interface is effective for drm (the threads suggest > > > >>>>>> so), adding that interface to dynamic-debug has real potential for > > > >>>>>> everyone including drm. > > > >>>>>> > > > >>>>>> if CONFIG_TRACING: > > > >>>>>> > > > >>>>>> Grab Sean's trace_init/cleanup code, use it to provide tracefs > > > >>>>>> available by default to all pr_debugs. This will likely need some > > > >>>>>> further per-module treatment; perhaps something reflecting hierarchy > > > >>>>>> of module,file,function,line, maybe with a tuned flattening. > > > >>>>>> > > > >>>>>> endif CONFIG_TRACING > > > >>>>>> > > > >>>>>> Add a new +T flag to enable tracing, independent of +p, and add and > > > >>>>>> use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate > > > >>>>>> the flag checks. Existing code treats T like other flags. > > > >>>>> > > > >>>>> I posted a patchset a while ago to do something very similar, but that > > > >>>>> got stalled for some reason and I unfortunately didn't follow it up: > > > >>>>> > > > >>>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/__;!!GjvTz_vk!HcKnMRByYkIdyF1apqQjlN5aBIomzJR1an3YWXM6KXs0EftVMQdrewRGytKHPg$ > > > >>>>> > > > >>>>> A key difference between that patchset and this patch (besides that > > > >>>>> small fact that I used +x instead of +T) was that my patchset allowed > > > >>>>> the dyndbg trace to be emitted to the main buffer and did not force them > > > >>>>> to be in an instance-specific buffer. > > > >>>> > > > >>>> Yes, I agree I'd prefer that we print here to the 'main' buffer - it > > > >>>> seems to keep things simpler and easier to combine the output from > > > >>>> different sources as you mentioned. > > > >>> > > > >>> Hi, > > > >>> > > > >>> I'm not quite sure I understand this discussion, but I would like to > > > >>> remind you all of what Sean's original work is about: > > > >>> > > > >>> Userspace configures DRM tracing into a flight recorder buffer (I guess > > > >>> this is what you refer to "instance-specific buffer"). > > > >>> > > > >>> Userspace runs happily for months, and then hits a problem: a failure > > > >>> in the DRM sub-system most likely, e.g. an ioctl that should never > > > >>> fail, failed. Userspace handles that failure by dumping the flight > > > >>> recorder buffer into a file and saving or sending a bug report. The > > > >>> flight recorder contents give a log of all relevant DRM in-kernel > > > >>> actions leading to the unexpected failure to help developers debug it. > > > >>> > > > >>> I don't mind if one can additionally send the flight recorder stream to > > > >>> the main buffer, but I do want the separate flight recorder buffer to > > > >>> be an option so that a) unrelated things cannot flood the interesting > > > >>> bits out of it, and b) the scope of collected information is relevant. > > > >>> > > > >>> The very reason for this work is problems that are very difficult to > > > >>> reproduce in practice, either because the problem itself is triggered > > > >>> very rarely and randomly, or because the end users of the system have > > > >>> either no knowledge or no access to reconfigure debug logging and then > > > >>> reproduce the problem with good debug logs. > > > >>> > > > >>> Thank you very much for pushing this work forward! > > > >>> > > > >>> > > > >> > > > >> So I think Vincent (earlier in the thread) was saying that he finds it > > > >> very helpful have dynamic debug output go to the 'main' trace buffer, > > > >> while you seem to be saying you'd prefer it just go to dynamic debug > > > >> specific trace buffer. > > > > > > > > Seems like we have different use cases: traditional debugging, and > > > > in-production flight recorder for problem reporting. I'm not surprised > > > > if they need different treatment. > > > > > > > >> So we certainly can have dynamic output potentially go to both places - > > > >> although I think this would mean two tracepoints? But I really wonder > > > >> if we really need a separate tracing buffer for dynamic debug when > > > >> what goes to the 'main' buffer can be controlled and filtered to avoid > > > >> your concern around a 'flood'? > > > > > > > > If the DRM tracing goes into the main buffer, then systems in > > > > production cannot have any other sub-system traced in a similar > > > > fashion. To me it would feel very arrogant to say that to make use of > > > > DRM flight recording, you cannot trace much or anything else. > > > > > > > > The very purpose of the flight recorder is run in production all the > > > > time, not in a special debugging session. > > > > > > > > There is also the question of access and contents of the trace buffer. > > > > Ultimately, if automatic bug reports are enabled in a system, the > > > > contents of the trace buffer would be sent as-is to some bug tracking > > > > system. If there is a chance to put non-DRM stuff in the trace buffer, > > > > that could be a security problem. > > > > > > > > My use case is Weston. When Weston encounters an unexpected problem in > > > > production, something should automatically capture the DRM flight > > > > recorder contents and save it alongside the Weston log. Would be really > > > > nice if Weston itself could do that, but I suspect it is going to need > > > > root privileges so it needs some helper daemon. > > > > > > > > Maybe Sean can reiterate their use case more? > > > > > > > > > > > > Thanks, > > > > pq > > > > > > > > > > Ok, so in this current thread the proposal was to create a "dyndbg-tracefs" > > > buffer to put the dynamic debug output (including drm output from dynamic > > > debug) into. And I was saying let's just put in the 'main' trace buffer > > > (predicated on a dynamic debug specific tracepoint), since there seems > > > to be a a use-case for that and it keeps things simpler. > > > > > > But I went back to Sean's original patch, and it creates a drm specific > > > trace buffer "drm" (via trace_array_get_by_name("drm")). Here: > > > https://patchwork.freedesktop.org/patch/445549/?series=78133&rev=5 > > > > > > So I think that may be some of the confusion here? The current thread/ > > > proposal is not for a drm specific trace buffer... > > > > Hi Jason, > > > > I may very well have confused things, sorry about that. If this series > > is not superseding the idea of the DRM flight recorder, then don't mind > > me. It just sounded very similar and I also haven't seen new revisions > > of the flight recorder in a long time. > > IMO this series has clarified the requirement for a flight-recorder mode, > which seems to fit ideally in a separate instance. > > > > Having a subsystem specific trace buffer would allow subsystem specific > > > trace log permissions depending on the sensitivity of the data. But > > > doesn't drm output today go to the system log which is typically world > > > readable today? > > > > Yes, and that is exactly the problem. The DRM debug output is so high > > traffic it would make the system log both unusable due to cruft and > > slow down the whole machine. The debug output is only useful when > > something went wrong, and at that point it is too late to enable > > debugging. That's why a flight recorder with an over-written circular > > in-memory buffer is needed. > > Seans patch reuses enum drm_debug_category to split the tracing > stream into 10 sub-streams > - how much traffic from each ? > - are some sub-streams more valuable for post-mortem ? > - any value from further refinement of categories ? > - drop irrelevant callsites individually to reduce clutter, extend > buffer time/space ? I think it's hard to predict which sub-streams you are going to need before you have a bug to debug. Hence I would err on the side of enabling too much. This also means that better or more refined categorisation might not be that much of help - or if it is, then are the excluded debug messages worth having in the kernel to begin with. Well, we're probably not that interested in GPU debugs but just everything related to the KMS side, which on the existing categories is... everything except half of CORE and DRIVER, maybe? Not sure. Maybe Sean has a better idea. My feeling is that that could mean in the order of hundreds of log events at framerate (e.g. 60 times per second) per each enabled output individually. And per DRM device, of course. This is with the uninteresting GPU debugs already excluded. Still, I don't think the flight recorder buffer would need to be massive. I suspect it would be enough to hold a few frames' worth which is just a split second under active operation. When something happens, the userspace stack is likely going to stop on its tracks immediately to collect the debug information, which means the flooding should pause and the relevant messages don't get overwritten before we get them. In a multi-seat system where each device is controlled by a separate display server instance, per-device logs would help with this. OTOH, multi-seat is not a very common use case I suppose. Thanks, pq
First off, let me reiterate that this feature would be invaluable as user-space
developers. It's often pretty difficult to figure out the cause of an EINVAL,
we have to ask users to follow complicated instructions [1] to grab DRM logs.
Then have to skim through several megabytes of logs to find the error.
I have a hack [2] which just calls system("sudo dmesg") after a failed atomic
commit, it's been pretty handy. But it's really just a hack, a proper solution
would be awesome.
[1]: https://gitlab.freedesktop.org/wlroots/wlroots/-/wikis/DRM-Debugging
[2]: https://gitlab.freedesktop.org/emersion/libliftoff/-/merge_requests/61
> > > > Having a subsystem specific trace buffer would allow subsystem specific
> > > > trace log permissions depending on the sensitivity of the data. But
> > > > doesn't drm output today go to the system log which is typically world
> > > > readable today?
dmesg isn't world-readable these days, it's been changed recently-ish (last
year?) at least on my distribution (Arch). I need root to grab dmesg.
(Maybe we can we just let the DRM master process grab the logs?)
> > > Yes, and that is exactly the problem. The DRM debug output is so high
> > > traffic it would make the system log both unusable due to cruft and
> > > slow down the whole machine. The debug output is only useful when
> > > something went wrong, and at that point it is too late to enable
> > > debugging. That's why a flight recorder with an over-written circular
> > > in-memory buffer is needed.
> >
> > Seans patch reuses enum drm_debug_category to split the tracing
> > stream into 10 sub-streams
> > - how much traffic from each ?
> > - are some sub-streams more valuable for post-mortem ?
> > - any value from further refinement of categories ?
> > - drop irrelevant callsites individually to reduce clutter, extend
> > buffer time/space ?
>
> I think it's hard to predict which sub-streams you are going to need
> before you have a bug to debug. Hence I would err on the side of
> enabling too much. This also means that better or more refined
> categorisation might not be that much of help - or if it is, then are
> the excluded debug messages worth having in the kernel to begin with.
> Well, we're probably not that interested in GPU debugs but just
> everything related to the KMS side, which on the existing categories
> is... everything except half of CORE and DRIVER, maybe? Not sure.
We've been recommending drm.debug=0x19F so far (see wiki linked above).
KMS + PRIME + ATOMIC + LEASE is definitely something we want in, and
CORE + DRIVER contains other useful info. We definitely don't want VBL.
> My feeling is that that could mean in the order of hundreds of log
> events at framerate (e.g. 60 times per second) per each enabled output
> individually. And per DRM device, of course. This is with the
> uninteresting GPU debugs already excluded.
Indeed, successful KMS atomic commits already generate a lot of noise. On my
machine, setting drm.debug=0x19F and running the following command:
sudo dmesg -w | pv >/dev/null
I get 400KiB/s when idling, and 850KiB/s when wiggling the cursor.
> Still, I don't think the flight recorder buffer would need to be
> massive. I suspect it would be enough to hold a few frames' worth which
> is just a split second under active operation. When something happens,
> the userspace stack is likely going to stop on its tracks immediately
> to collect the debug information, which means the flooding should pause
> and the relevant messages don't get overwritten before we get them. In
> a multi-seat system where each device is controlled by a separate
> display server instance, per-device logs would help with this. OTOH,
> multi-seat is not a very common use case I suppose.
There's also the case of multi-GPU where GPU B's logs could clutter GPU A's,
making it harder to understand the cause of an atomic commit failure on GPU A.
So per-device logs would be useful, but not a hard requirement for me, having
*anything* at all would already be a big win.
In my experiments linked above [2], system("sudo dmesg") after atomic commit
failure worked pretty well, and the bottom of the log contained the cause of
the failure. It was pretty useful to system("sudo dmesg -C") before performing
an atomic commit, to be able to only collect the extract of the log relevant to
the atomic commit.
Having some kind of "marker" mechanism could be pretty cool. "Mark" the log
stream before performing an atomic commit (ideally that'd just return e.g. an
uint64 offset), then on failure request the logs collected after that mark.
On Fri, Nov 19, 2021 at 11:46:31PM +0100, jim.cromie@gmail.com wrote: > Vincent's code has the macro magic to define that event, which IIUC > is what makes it controllable by ftrace, and therefore acceptable in > principle to Steve. > Would there be any reason to expand his set of 2 events into dev_dbg, > pr_debug etc varieties ? > (ie any value to separating dev, !dev ?, maybe so > > Sean's code uses trace_array_printk primarily, which is EXPORTed, > which is a virtue. > > Vincents code does > +/* > + * This code is heavily based on __ftrace_trace_stack(). > + * > + * Allow 4 levels of nesting: normal, softirq, irq, NMI. > + */ > > to implement > > +static void dynamic_trace(const char *fmt, va_list args) > > Has this __ftrace_trace_stack() code been bundled into or hidden under > a supported interface ? > > would it look anything like trace_array_printk() ? > > what problem is that code solving inside dynamic-debug.c ? I'm not sure I fully understand all of your questions, but perhaps this thread with Steven's reply to the first version of my patchset will answer some of them: https://lore.kernel.org/lkml/20200723112644.7759f82f@oasis.local.home/
On Fri, Nov 12, 2021 at 4:49 AM Vincent Whitchurch <vincent.whitchurch@axis.com> wrote: > > On Thu, Nov 11, 2021 at 03:02:04PM -0700, Jim Cromie wrote: > > Dynamic-Debug can do 2nd exceedingly well: > > > > A- all work is behind jump-label's NOOP, zero off cost. > > B- exact site selectivity, precisely the useful traffic. > > can tailor enabled set interactively, at shell. > > > > Since the tracefs interface is effective for drm (the threads suggest > > so), adding that interface to dynamic-debug has real potential for > > everyone including drm. > > > > Add a new +T flag to enable tracing, independent of +p, and add and > > I posted a patchset a while ago to do something very similar, but that > got stalled for some reason and I unfortunately didn't follow it up: > > https://lore.kernel.org/lkml/20200825153338.17061-1-vincent.whitchurch@axis.com/ > > A key difference between that patchset and this patch (besides that > small fact that I used +x instead of +T) was that my patchset allowed > the dyndbg trace to be emitted to the main buffer and did not force them > to be in an instance-specific buffer. > > That feature is quite important at least for my use case since I often > use dyndbg combined with function tracing, and the latter doesn't work > on non-main instances according to Documentation/trace/ftrace.rst. > > For example, here's a random example of a bootargs from one of my recent > debugging sessions: > > trace_event=printk:* ftrace_filter=_mmc*,mmc*,sd*,dw_mci*,mci* > ftrace=function trace_buf_size=20M dyndbg="file drivers/mmc/* +x" > Hi Vincent, are you planning to dust this patchset off and resubmit it ? Ive been playing with it and learning ftrace (decade+ late), I found your boot-line example very helpful as 1st steps (still havent even tried the filtering) with these adjustments (voiced partly to test my understanding) I would support it, and rework my patchset to use it. - change flag to -e, good mnemonics for event/trace-event T is good too, but uppercase, no need to go there. - include/trace/events/dyndbg.h - separate file, not mixed with print.h dyndbg class, so trace_event=dyndbg:* - 1 event type per pr_debug, dev_dbg, netdev_dbg ? ibdev_dbg ? with the extra args: descriptor that Steven wanted, probably also struct <|net|ib>dev If youre too busy for a while, I'd eventually take a (slow) run at it.
On Wed, Dec 08, 2021 at 06:16:10AM +0100, jim.cromie@gmail.com wrote: > are you planning to dust this patchset off and resubmit it ? > > Ive been playing with it and learning ftrace (decade+ late), > I found your boot-line example very helpful as 1st steps > (still havent even tried the filtering) > > > with these adjustments (voiced partly to test my understanding) > I would support it, and rework my patchset to use it. > > - change flag to -e, good mnemonics for event/trace-event > T is good too, but uppercase, no need to go there. Any flag name works for me. > - include/trace/events/dyndbg.h - separate file, not mixed with print.h > dyndbg class, so trace_event=dyndbg:* > > - 1 event type per pr_debug, dev_dbg, netdev_dbg ? ibdev_dbg ? > with the extra args: descriptor that Steven wanted, > probably also struct <|net|ib>dev For my use cases I don't see much value in having separate events for the different debug functions, but since all of them can be easily enabled (dyndbg:*, as you noted), that works for me too. > If youre too busy for a while, I'd eventually take a (slow) run at it. You're welcome to have a go. I think you've already rebased the patchset, but here's a diff top of v5.16-rc4 for reference. I noticed a bug inside the CONFIG_JUMP_LABEL handling (also present in the last version I posted) which should be fixed as part of the diff below (I've added a comment). Proper tests for this, like the ones you are adding in your patchset, would certainly be a good idea. Thanks. 8<------------- diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst index a89cfa083155..b9c4e808befc 100644 --- a/Documentation/admin-guide/dynamic-debug-howto.rst +++ b/Documentation/admin-guide/dynamic-debug-howto.rst @@ -228,6 +228,7 @@ of the characters:: The flags are:: p enables the pr_debug() callsite. + x enables trace to the printk:dyndbg event f Include the function name in the printed message l Include line number in the printed message m Include module name in the printed message diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h index dce631e678dd..bc21bfb0fdc6 100644 --- a/include/linux/dynamic_debug.h +++ b/include/linux/dynamic_debug.h @@ -27,7 +27,7 @@ struct _ddebug { * writes commands to <debugfs>/dynamic_debug/control */ #define _DPRINTK_FLAGS_NONE 0 -#define _DPRINTK_FLAGS_PRINT (1<<0) /* printk() a message using the format */ +#define _DPRINTK_FLAGS_PRINTK (1<<0) /* printk() a message using the format */ #define _DPRINTK_FLAGS_INCL_MODNAME (1<<1) #define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2) #define _DPRINTK_FLAGS_INCL_LINENO (1<<3) @@ -37,8 +37,11 @@ struct _ddebug { (_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\ _DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID) +#define _DPRINTK_FLAGS_TRACE (1<<5) +#define _DPRINTK_FLAGS_ENABLE (_DPRINTK_FLAGS_PRINTK | \ + _DPRINTK_FLAGS_TRACE) #if defined DEBUG -#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT +#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINTK #else #define _DPRINTK_FLAGS_DEFAULT 0 #endif @@ -120,10 +123,10 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor, #ifdef DEBUG #define DYNAMIC_DEBUG_BRANCH(descriptor) \ - likely(descriptor.flags & _DPRINTK_FLAGS_PRINT) + likely(descriptor.flags & _DPRINTK_FLAGS_ENABLE) #else #define DYNAMIC_DEBUG_BRANCH(descriptor) \ - unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT) + unlikely(descriptor.flags & _DPRINTK_FLAGS_ENABLE) #endif #endif /* CONFIG_JUMP_LABEL */ diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h index 13d405b2fd8b..1f78bd237a91 100644 --- a/include/trace/events/printk.h +++ b/include/trace/events/printk.h @@ -7,7 +7,7 @@ #include <linux/tracepoint.h> -TRACE_EVENT(console, +DECLARE_EVENT_CLASS(printk, TP_PROTO(const char *text, size_t len), TP_ARGS(text, len), @@ -31,6 +31,16 @@ TRACE_EVENT(console, TP_printk("%s", __get_str(msg)) ); + +DEFINE_EVENT(printk, console, + TP_PROTO(const char *text, size_t len), + TP_ARGS(text, len) +); + +DEFINE_EVENT(printk, dyndbg, + TP_PROTO(const char *text, size_t len), + TP_ARGS(text, len) +); #endif /* _TRACE_PRINTK_H */ /* This part must be outside protection */ diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c index dd7f56af9aed..161454fa0af8 100644 --- a/lib/dynamic_debug.c +++ b/lib/dynamic_debug.c @@ -36,6 +36,7 @@ #include <linux/sched.h> #include <linux/device.h> #include <linux/netdevice.h> +#include <trace/events/printk.h> #include <rdma/ib_verbs.h> @@ -86,11 +87,12 @@ static inline const char *trim_prefix(const char *path) } static struct { unsigned flag:8; char opt_char; } opt_array[] = { - { _DPRINTK_FLAGS_PRINT, 'p' }, + { _DPRINTK_FLAGS_PRINTK, 'p' }, { _DPRINTK_FLAGS_INCL_MODNAME, 'm' }, { _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' }, { _DPRINTK_FLAGS_INCL_LINENO, 'l' }, { _DPRINTK_FLAGS_INCL_TID, 't' }, + { _DPRINTK_FLAGS_TRACE, 'x' }, { _DPRINTK_FLAGS_NONE, '_' }, }; @@ -210,11 +212,23 @@ static int ddebug_change(const struct ddebug_query *query, if (newflags == dp->flags) continue; #ifdef CONFIG_JUMP_LABEL - if (dp->flags & _DPRINTK_FLAGS_PRINT) { - if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT)) + if (dp->flags & _DPRINTK_FLAGS_ENABLE) { + /* + * The newflags check is to ensure that the + * static branch doesn't get disabled in step + * 3: + * + * (1) +pf + * (2) +x + * (3) -pf + */ + if (!(modifiers->flags & _DPRINTK_FLAGS_ENABLE) && + !(newflags & _DPRINTK_FLAGS_ENABLE)) { static_branch_disable(&dp->key.dd_key_true); - } else if (modifiers->flags & _DPRINTK_FLAGS_PRINT) + } + } else if (modifiers->flags & _DPRINTK_FLAGS_ENABLE) { static_branch_enable(&dp->key.dd_key_true); + } #endif dp->flags = newflags; v4pr_info("changed %s:%d [%s]%s =%s\n", @@ -621,6 +635,96 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf) return buf; } +/* + * This code is heavily based on __ftrace_trace_stack(). + * + * Allow 4 levels of nesting: normal, softirq, irq, NMI. + */ +#define DYNAMIC_TRACE_NESTING 4 + +struct dynamic_trace_buf { + char buf[256]; +}; + +struct dynamic_trace_bufs { + struct dynamic_trace_buf bufs[DYNAMIC_TRACE_NESTING]; +}; + +static DEFINE_PER_CPU(struct dynamic_trace_bufs, dynamic_trace_bufs); +static DEFINE_PER_CPU(int, dynamic_trace_reserve); + +static void dynamic_trace(const char *fmt, va_list args) +{ + struct dynamic_trace_buf *buf; + int bufidx; + int len; + + preempt_disable_notrace(); + + bufidx = __this_cpu_inc_return(dynamic_trace_reserve) - 1; + + if (WARN_ON_ONCE(bufidx > DYNAMIC_TRACE_NESTING)) + goto out; + + /* For the same reasons as in __ftrace_trace_stack(). */ + barrier(); + + buf = this_cpu_ptr(dynamic_trace_bufs.bufs) + bufidx; + + len = vscnprintf(buf->buf, sizeof(buf->buf), fmt, args); + trace_dyndbg(buf->buf, len); + +out: + /* As above. */ + barrier(); + __this_cpu_dec(dynamic_trace_reserve); + preempt_enable_notrace(); +} + +static void dynamic_printk(unsigned int flags, const char *fmt, ...) +{ + if (flags & _DPRINTK_FLAGS_TRACE) { + va_list args; + + va_start(args, fmt); + /* + * All callers include the KERN_DEBUG prefix to keep the + * vprintk case simple; strip it out for tracing. + */ + dynamic_trace(fmt + strlen(KERN_DEBUG), args); + va_end(args); + } + + if (flags & _DPRINTK_FLAGS_PRINTK) { + va_list args; + + va_start(args, fmt); + vprintk(fmt, args); + va_end(args); + } +} + +static void dynamic_dev_printk(unsigned int flags, const struct device *dev, + const char *fmt, ...) +{ + + if (flags & _DPRINTK_FLAGS_TRACE) { + va_list args; + + va_start(args, fmt); + dynamic_trace(fmt, args); + va_end(args); + } + + if (flags & _DPRINTK_FLAGS_PRINTK) { + va_list args; + + va_start(args, fmt); + dev_vprintk_emit(LOGLEVEL_DEBUG, dev, fmt, args); + va_end(args); + } +} + static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf) { if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY)) @@ -642,7 +746,8 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) vaf.fmt = fmt; vaf.va = &args; - printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf); + dynamic_printk(descriptor->flags, KERN_DEBUG "%s%pV", + dynamic_emit_prefix(descriptor, buf), &vaf); va_end(args); } @@ -652,6 +757,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor, const struct device *dev, const char *fmt, ...) { struct va_format vaf; + unsigned int flags; va_list args; BUG_ON(!descriptor); @@ -661,16 +767,18 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor, vaf.fmt = fmt; vaf.va = &args; + flags = descriptor->flags; if (!dev) { - printk(KERN_DEBUG "(NULL device *): %pV", &vaf); + dynamic_printk(flags, KERN_DEBUG "(NULL device *): %pV", + &vaf); } else { char buf[PREFIX_SIZE] = ""; - dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV", - dynamic_emit_prefix(descriptor, buf), - dev_driver_string(dev), dev_name(dev), - &vaf); + dynamic_dev_printk(flags, dev, "%s%s %s: %pV", + dynamic_emit_prefix(descriptor, buf), + dev_driver_string(dev), dev_name(dev), + &vaf); } va_end(args); @@ -683,6 +791,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor, const struct net_device *dev, const char *fmt, ...) { struct va_format vaf; + unsigned int flags; va_list args; BUG_ON(!descriptor); @@ -692,22 +801,24 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor, vaf.fmt = fmt; vaf.va = &args; + flags = descriptor->flags; if (dev && dev->dev.parent) { char buf[PREFIX_SIZE] = ""; - dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent, - "%s%s %s %s%s: %pV", - dynamic_emit_prefix(descriptor, buf), - dev_driver_string(dev->dev.parent), - dev_name(dev->dev.parent), - netdev_name(dev), netdev_reg_state(dev), - &vaf); + dynamic_dev_printk(flags, dev->dev.parent, + "%s%s %s %s%s: %pV", + dynamic_emit_prefix(descriptor, buf), + dev_driver_string(dev->dev.parent), + dev_name(dev->dev.parent), + netdev_name(dev), netdev_reg_state(dev), + &vaf); } else if (dev) { - printk(KERN_DEBUG "%s%s: %pV", netdev_name(dev), - netdev_reg_state(dev), &vaf); + dynamic_printk(flags, KERN_DEBUG "%s%s: %pV", + netdev_name(dev), netdev_reg_state(dev), &vaf); } else { - printk(KERN_DEBUG "(NULL net_device): %pV", &vaf); + dynamic_printk(flags, KERN_DEBUG "(NULL net_device): %pV", + &vaf); } va_end(args); @@ -722,27 +833,31 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor, const struct ib_device *ibdev, const char *fmt, ...) { struct va_format vaf; + unsigned int flags; va_list args; va_start(args, fmt); vaf.fmt = fmt; vaf.va = &args; + flags = descriptor->flags; if (ibdev && ibdev->dev.parent) { char buf[PREFIX_SIZE] = ""; - dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent, - "%s%s %s %s: %pV", - dynamic_emit_prefix(descriptor, buf), - dev_driver_string(ibdev->dev.parent), - dev_name(ibdev->dev.parent), - dev_name(&ibdev->dev), - &vaf); + dynamic_dev_printk(flags, ibdev->dev.parent, + "%s%s %s %s: %pV", + dynamic_emit_prefix(descriptor, buf), + dev_driver_string(ibdev->dev.parent), + dev_name(ibdev->dev.parent), + dev_name(&ibdev->dev), + &vaf); } else if (ibdev) { - printk(KERN_DEBUG "%s: %pV", dev_name(&ibdev->dev), &vaf); + dynamic_printk(flags, KERN_DEBUG "%s: %pV", + dev_name(&ibdev->dev), &vaf); } else { - printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf); + dynamic_printk(flags, KERN_DEBUG "(NULL ib_device): %pV", + &vaf); } va_end(args);
diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst index a89cfa083155..bf2a561cc9bc 100644 --- a/Documentation/admin-guide/dynamic-debug-howto.rst +++ b/Documentation/admin-guide/dynamic-debug-howto.rst @@ -227,7 +227,8 @@ of the characters:: The flags are:: - p enables the pr_debug() callsite. + p enables the pr_debug() callsite to syslog + T enables the pr_debug() callsite to tracefs f Include the function name in the printed message l Include line number in the printed message m Include module name in the printed message @@ -240,8 +241,8 @@ have meaning, other flags ignored. For display, the flags are preceded by ``=`` (mnemonic: what the flags are currently equal to). -Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification. -To clear all flags at once, use ``=_`` or ``-flmpt``. +Note the regexp ``^[-+=][flmptT_]+$`` matches a flags specification. +To clear all flags at once, use ``=_`` or ``-flmptT``. Debug messages during Boot Process diff --git a/MAINTAINERS b/MAINTAINERS index 5b7a13f706fa..db5513b3201b 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -6663,6 +6663,7 @@ M: Jason Baron <jbaron@akamai.com> S: Maintained F: include/linux/dynamic_debug.h F: lib/dynamic_debug.c +F: lib/test_dynamic_debug.c DYNAMIC INTERRUPT MODERATION M: Tal Gilboa <talgi@nvidia.com> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h index a9430168b072..792bcff0297e 100644 --- a/include/linux/dynamic_debug.h +++ b/include/linux/dynamic_debug.h @@ -28,15 +28,25 @@ struct _ddebug { */ #define _DPRINTK_FLAGS_NONE 0 #define _DPRINTK_FLAGS_PRINT (1<<0) /* printk() a message using the format */ +#define _DPRINTK_FLAGS_TRACE (1<<5) /* trace_printk() the message */ +#define _DPRINTK_ENABLED (_DPRINTK_FLAGS_PRINT | _DPRINTK_FLAGS_TRACE) + +/* internal, need type protection for external use */ +#define __dyndbg_site_is_enabled(desc) (!!(desc->flags & _DPRINTK_ENABLED)) +#define __dyndbg_site_is_logging(desc) (!!(desc->flags & _DPRINTK_FLAGS_PRINT)) +#define __dyndbg_site_is_tracing(desc) (!!(desc->flags & _DPRINTK_FLAGS_TRACE)) + #define _DPRINTK_FLAGS_INCL_MODNAME (1<<1) #define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2) #define _DPRINTK_FLAGS_INCL_LINENO (1<<3) #define _DPRINTK_FLAGS_INCL_TID (1<<4) -#define _DPRINTK_FLAGS_INCL_ANY \ +#define _DPRINTK_FLAGS_INCL_ANY \ (_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\ _DPRINTK_FLAGS_INCL_LINENO | _DPRINTK_FLAGS_INCL_TID) +#define __dyndbg_site_is_decorated(desc) (!!(desc->flags & _DPRINTK_FLAGS_INCL_ANY)) + #if defined DEBUG #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT #else diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index 9ef7ce18b4f5..b4a299d57c9e 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -2480,6 +2480,17 @@ config TEST_STATIC_KEYS If unsure, say N. +config TEST_DYNAMIC_DEBUG + tristate "Test DYNAMIC_DEBUG" + depends on m + depends on DYNAMIC_DEBUG + help + This module registers a tracer callback to count enabled + pr_debugs in a 'do_debugging' function, then alters their + enablements, calls the function, and compares counts. + + If unsure, say N. + config TEST_KMOD tristate "kmod stress tester" depends on m diff --git a/lib/Makefile b/lib/Makefile index 364c23f15578..5dd4cb7c02c6 100644 --- a/lib/Makefile +++ b/lib/Makefile @@ -82,6 +82,7 @@ obj-$(CONFIG_TEST_SORT) += test_sort.o obj-$(CONFIG_TEST_USER_COPY) += test_user_copy.o obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_keys.o obj-$(CONFIG_TEST_STATIC_KEYS) += test_static_key_base.o +obj-$(CONFIG_TEST_DYNAMIC_DEBUG) += test_dynamic_debug.o obj-$(CONFIG_TEST_PRINTF) += test_printf.o obj-$(CONFIG_TEST_SCANF) += test_scanf.o obj-$(CONFIG_TEST_BITMAP) += test_bitmap.o diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c index 760e1f1f09ed..d493ed6658b9 100644 --- a/lib/dynamic_debug.c +++ b/lib/dynamic_debug.c @@ -36,6 +36,7 @@ #include <linux/sched.h> #include <linux/device.h> #include <linux/netdevice.h> +#include <linux/trace.h> #include <rdma/ib_verbs.h> @@ -74,6 +75,7 @@ module_param(verbose, int, 0644); MODULE_PARM_DESC(verbose, " dynamic_debug/control processing " "( 0 = off (default), 1 = module add/rm, 2 = >control summary, 3 = parsing, 4 = per-site changes)"); + /* Return the path relative to source root */ static inline const char *trim_prefix(const char *path) { @@ -87,6 +89,7 @@ static inline const char *trim_prefix(const char *path) static struct { unsigned flag:8; char opt_char; } opt_array[] = { { _DPRINTK_FLAGS_PRINT, 'p' }, + { _DPRINTK_FLAGS_TRACE, 'T' }, { _DPRINTK_FLAGS_INCL_MODNAME, 'm' }, { _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' }, { _DPRINTK_FLAGS_INCL_LINENO, 'l' }, @@ -209,11 +212,12 @@ static int ddebug_change(const struct ddebug_query *query, newflags = (dp->flags & modifiers->mask) | modifiers->flags; if (newflags == dp->flags) continue; + #ifdef CONFIG_JUMP_LABEL - if (dp->flags & _DPRINTK_FLAGS_PRINT) { - if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT)) + if (__dyndbg_site_is_enabled(dp)) { + if (!__dyndbg_site_is_enabled(modifiers)) static_branch_disable(&dp->key.dd_key_true); - } else if (modifiers->flags & _DPRINTK_FLAGS_PRINT) + } else if (__dyndbg_site_is_enabled(modifiers)) static_branch_enable(&dp->key.dd_key_true); #endif dp->flags = newflags; @@ -431,6 +435,16 @@ static int ddebug_parse_query(char *words[], int nwords, return 0; } +static int ddebug_validate_flags(struct flag_settings *modifiers) +{ +#if !defined(CONFIG_TRACING) + if (__dyndbg_site_is_tracing(modifiers)) { + WARN_ONCE(1, "cannot enable T, CONFIG_TRACE=n\n"); + return -EINVAL; + } +#endif + return 0; +} /* * Parse `str' as a flags specification, format [-+=][p]+. * Sets up *maskp and *flagsp to be used when changing the @@ -483,7 +497,7 @@ static int ddebug_parse_flags(const char *str, struct flag_settings *modifiers) } v3pr_info("*flagsp=0x%x *maskp=0x%x\n", modifiers->flags, modifiers->mask); - return 0; + return ddebug_validate_flags(modifiers); } static int ddebug_exec_query(char *query_string, const char *modname) @@ -699,11 +713,24 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf) static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf) { - if (unlikely(desc->flags & _DPRINTK_FLAGS_INCL_ANY)) + if (unlikely(__dyndbg_site_is_enabled(desc) && + __dyndbg_site_is_decorated(desc))) return __dynamic_emit_prefix(desc, buf); return buf; } +static struct trace_array *trace_arr; + +#if !defined(CONFIG_TRACING) +/* private stub for 4 users below */ +static inline int __printf(3, 0) + trace_array_printk(struct trace_array *tr, unsigned long ip, + const char *fmt, ...) +{ + return 0; +} +#endif + void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) { va_list args; @@ -718,7 +745,13 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) vaf.fmt = fmt; vaf.va = &args; - printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf); + dynamic_emit_prefix(descriptor, buf); + + if (__dyndbg_site_is_tracing(descriptor)) + trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf); + + if (__dyndbg_site_is_logging(descriptor)) + printk(KERN_DEBUG "%s%pV", buf, &vaf); va_end(args); } @@ -729,6 +762,7 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor, { struct va_format vaf; va_list args; + char buf[PREFIX_SIZE] = ""; BUG_ON(!descriptor); BUG_ON(!fmt); @@ -738,17 +772,21 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor, vaf.fmt = fmt; vaf.va = &args; + dynamic_emit_prefix(descriptor, buf); + + if (__dyndbg_site_is_tracing(descriptor)) + trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf); + + if (!__dyndbg_site_is_logging(descriptor)) + goto out; + if (!dev) { printk(KERN_DEBUG "(NULL device *): %pV", &vaf); } else { - char buf[PREFIX_SIZE] = ""; - dev_printk_emit(LOGLEVEL_DEBUG, dev, "%s%s %s: %pV", - dynamic_emit_prefix(descriptor, buf), - dev_driver_string(dev), dev_name(dev), - &vaf); + buf, dev_driver_string(dev), dev_name(dev), &vaf); } - +out: va_end(args); } EXPORT_SYMBOL(__dynamic_dev_dbg); @@ -760,6 +798,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor, { struct va_format vaf; va_list args; + char buf[PREFIX_SIZE] = ""; BUG_ON(!descriptor); BUG_ON(!fmt); @@ -769,12 +808,17 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor, vaf.fmt = fmt; vaf.va = &args; - if (dev && dev->dev.parent) { - char buf[PREFIX_SIZE] = ""; + dynamic_emit_prefix(descriptor, buf); + + if (__dyndbg_site_is_tracing(descriptor)) + trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf); + if (!__dyndbg_site_is_logging(descriptor)) + goto out; + + if (dev && dev->dev.parent) { dev_printk_emit(LOGLEVEL_DEBUG, dev->dev.parent, - "%s%s %s %s%s: %pV", - dynamic_emit_prefix(descriptor, buf), + "%s%s %s %s%s: %pV", buf, dev_driver_string(dev->dev.parent), dev_name(dev->dev.parent), netdev_name(dev), netdev_reg_state(dev), @@ -785,7 +829,7 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor, } else { printk(KERN_DEBUG "(NULL net_device): %pV", &vaf); } - +out: va_end(args); } EXPORT_SYMBOL(__dynamic_netdev_dbg); @@ -799,18 +843,24 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor, { struct va_format vaf; va_list args; + char buf[PREFIX_SIZE] = ""; va_start(args, fmt); vaf.fmt = fmt; vaf.va = &args; - if (ibdev && ibdev->dev.parent) { - char buf[PREFIX_SIZE] = ""; + dynamic_emit_prefix(descriptor, buf); + + if (__dyndbg_site_is_tracing(descriptor)) + trace_array_printk(trace_arr, _THIS_IP_, "%s%pV", buf, &vaf); + + if (!__dyndbg_site_is_logging(descriptor)) + goto out; + if (ibdev && ibdev->dev.parent) { dev_printk_emit(LOGLEVEL_DEBUG, ibdev->dev.parent, - "%s%s %s %s: %pV", - dynamic_emit_prefix(descriptor, buf), + "%s%s %s %s: %pV", buf, dev_driver_string(ibdev->dev.parent), dev_name(ibdev->dev.parent), dev_name(&ibdev->dev), @@ -820,7 +870,7 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor, } else { printk(KERN_DEBUG "(NULL ib_device): %pV", &vaf); } - +out: va_end(args); } EXPORT_SYMBOL(__dynamic_ibdev_dbg); @@ -1132,6 +1182,35 @@ static void ddebug_remove_all_tables(void) mutex_unlock(&ddebug_lock); } +#if defined(CONFIG_TRACING) + +static void ddebug_trace_cleanup(void) +{ + if (trace_arr) { + trace_array_put(trace_arr); + trace_array_destroy(trace_arr); + trace_arr = NULL; + } +} + +static void ddebug_trace_init(void) +{ + int ret; + + trace_arr = trace_array_get_by_name("dyndbg-tracefs"); + if (!trace_arr) + return; + + ret = trace_array_init_printk(trace_arr); + if (ret) + ddebug_trace_cleanup(); +} + +#else +static inline void ddebug_trace_init(void) {} +static inline void ddebug_trace_cleanup(void) {} +#endif + static __initdata int ddebug_init_success; static int __init dynamic_debug_init_control(void) @@ -1174,6 +1253,9 @@ static int __init dynamic_debug_init(void) ddebug_init_success = 1; return 0; } + + ddebug_trace_init(); + iter = __start___dyndbg; modname = iter->modname; iter_start = iter; @@ -1215,6 +1297,7 @@ static int __init dynamic_debug_init(void) out_err: ddebug_remove_all_tables(); + ddebug_trace_cleanup(); return 0; } /* Allow early initialization for boot messages via boot param */ diff --git a/lib/test_dynamic_debug.c b/lib/test_dynamic_debug.c new file mode 100644 index 000000000000..dd41a09fd9c8 --- /dev/null +++ b/lib/test_dynamic_debug.c @@ -0,0 +1,222 @@ +// SPDX-License-Identifier: GPL-2.0-only +/* + * Kernel module for testing dynamic_debug + * + * Authors: + * Jim Cromie <jim.cromie@gmail.com> + */ + +/* + * test-setup: use trace_print attachment interface as a test harness, + * define a custom trace_printer which counts invocations, and a + * pr_debug event generator function which calls a set of categorized + * pr_debugs. + * test-run: manipulate the pr_debug's enablement, run the event + * generator, and check for the expected side effects. + */ + +#define pr_fmt(fmt) "test_dd: " fmt + +#include <linux/module.h> + +static int hit_ct; +static int test_ct; +static int errors; + +static int __verbose; +module_param_named(verbose, __verbose, int, 0444); +MODULE_PARM_DESC(verbose, "enable print from trace (output verify)"); + +static int __bad_tracer; +module_param_named(use_bad_tracer, __bad_tracer, int, 0444); +MODULE_PARM_DESC(use_bad_tracer, + "use broken tracer, recursing with pr_debug\n" + "\tonly works at modprobe time\n"); + +static void (*my_tracer)(const char *lbl, struct va_format *vaf); + +static void good_tracer(const char *lbl, struct va_format *vaf) +{ + hit_ct++; + + if (__verbose) + pr_notice("%s%pV", lbl, vaf); +} + +static void bad_tracer(const char *lbl, struct va_format *vaf) +{ + hit_ct++; + if (__verbose) + pr_notice("%s%pV", lbl, vaf); + + pr_debug("%s.%pV", lbl, vaf); +} + +static void pick_tracer(void) +{ + if (__bad_tracer) { + pr_notice("using bad tracer - fails hit count tests\n"); + my_tracer = bad_tracer; + } else + my_tracer = good_tracer; +} + +static int expect_count(int want, const char *story) +{ + test_ct++; + if (want != hit_ct) { + pr_err("nok %d: want %d, got %d: %s\n", test_ct, want, hit_ct, story); + errors++; + hit_ct = 0; + return 1; + } + pr_info("ok %d: hits %d, on <%s>\n", test_ct, want, story); + hit_ct = 0; + return 0; +} + +/* call pr_debug (4 * reps) + 2 times, for tracer side-effects */ +static void do_debugging(int reps) +{ + int i; + + pr_debug("Entry:\n"); + pr_info("%s %d time(s)\n", __func__, reps); + for (i = 0; i < reps; i++) { + pr_debug("hi: %d\n", i); + pr_debug("mid: %d\n", i); + pr_debug("low: %d\n", i); + pr_debug("low:lower: %d subcategory test\n", i); + } + pr_debug("Exit:\n"); +} + +static void expect_matches(int want, int got, const char *story) +{ + /* todo: got <0 are errors, bubbled up. no test for that */ + test_ct++; + if (got != want) { + pr_warn("nok %d: want %d matches, got %d on <%s>\n", test_ct, want, got, story); + errors++; + } else + pr_info("ok %d: %d matches on <%s>\n", test_ct, want, story); +} + +static int report(char *who) +{ + if (errors) + pr_err("%s failed %d of %d tests\n", who, errors, test_ct); + else + pr_info("%s passed %d tests\n", who, test_ct); + return errors; +} + +struct exec_test { + int matches; + int loops; + int hits; + const char *mod; + const char *qry; +}; + +static void do_exec_test(struct exec_test *tst) +{ + int match_count; + + match_count = dynamic_debug_exec_queries(tst->qry, tst->mod); + expect_matches(tst->matches, match_count, tst->qry); + do_debugging(tst->loops); + expect_count(tst->hits, tst->qry); +} + +/* these tests rely on register stuff having been done ?? */ +struct exec_test exec_tests[] = { + /* + * use original single string query style once, to test it. + * standard use is with separate module param, like: + * dynamic_debug_exec_queries("func do_debugging +_", "test_dynamic_debug"); + */ + { 6, 1, 0, NULL, "module test_dynamic_debug func do_debugging -T" }, + + /* no modification probe */ + { 6, 3, 0, KBUILD_MODNAME, "func do_debugging +_" }, + + /* enable all prdbgs in DUT */ + { 6, 4, 18, KBUILD_MODNAME, "func do_debugging +T" }, + + /* disable hi call */ + { 1, 4, 14, KBUILD_MODNAME, "format '^hi:' -T" }, + + /* disable mid call */ + { 1, 4, 10, KBUILD_MODNAME, "format '^mid:' -T" }, + + /* repeat same disable */ + { 1, 4, 10, KBUILD_MODNAME, "format '^mid:' -T" }, + + /* repeat same disable, diff run ct */ + { 1, 5, 12, KBUILD_MODNAME, "format '^mid:' -T" }, + + /* include subclass */ + { 2, 4, 2, KBUILD_MODNAME, "format '^low:' -T" }, + + /* re-disable, exclude subclass */ + { 1, 4, 2, KBUILD_MODNAME, "format '^low: ' -T" }, + + /* enable, exclude subclass */ + { 1, 4, 6, KBUILD_MODNAME, "format '^low: ' +T" }, + + /* enable the subclass */ + { 1, 4, 10, KBUILD_MODNAME, "format '^low:lower:' +T" }, + + /* enable the subclass */ + { 1, 6, 14, KBUILD_MODNAME, "format '^low:lower:' +T" }, +}; + +static int __init test_dynamic_debug_init(void) +{ + int i; + + pick_tracer(); + + pr_debug("Entry:\n"); + do_debugging(1); + expect_count(0, "nothing on"); + + //dynamic_debug_register_tracer(THIS_MODULE, my_tracer); + /* 2nd time gets a complaint */ + //dynamic_debug_register_tracer(THIS_MODULE, my_tracer); + + for (i = 0; i < ARRAY_SIZE(exec_tests); i++) + do_exec_test(&exec_tests[i]); + + //dynamic_debug_unregister_tracer(THIS_MODULE, my_tracer); + + /* this gets missing tracer warnings, cuz +T is still on */ + do_debugging(1); + expect_count(0, "unregistered, but +T still on"); + + /* reuse test 0 to turn off T */ + do_exec_test(&exec_tests[0]); + + /* this draws warning about failed deregistration */ + //dynamic_debug_unregister_tracer(THIS_MODULE, my_tracer); + + do_debugging(1); + expect_count(0, "all off"); + + report("init"); + pr_debug("Exit:\n"); + return 0; +} + +static void __exit test_dynamic_debug_exit(void) +{ + report("exit"); + pr_debug("Exit:"); +} + +module_init(test_dynamic_debug_init); +module_exit(test_dynamic_debug_exit); + +MODULE_AUTHOR("Jim Cromie <jim.cromie@gmail.com>"); +MODULE_LICENSE("GPL");
Sean Paul proposed, in: https://patchwork.freedesktop.org/series/78133/ drm/trace: Mirror DRM debug logs to tracefs His patchset's objective is to be able to independently steer some of the drm.debug stream to an alternate tracing destination, by splitting drm_debug_enabled() into syslog & trace flavors, and enabling them separately. 2 advantages were identified: 1- syslog is heavyweight, tracefs is much lighter 2- separate selection of enabled categories means less traffic Dynamic-Debug can do 2nd exceedingly well: A- all work is behind jump-label's NOOP, zero off cost. B- exact site selectivity, precisely the useful traffic. can tailor enabled set interactively, at shell. Since the tracefs interface is effective for drm (the threads suggest so), adding that interface to dynamic-debug has real potential for everyone including drm. if CONFIG_TRACING: Grab Sean's trace_init/cleanup code, use it to provide tracefs available by default to all pr_debugs. This will likely need some further per-module treatment; perhaps something reflecting hierarchy of module,file,function,line, maybe with a tuned flattening. endif CONFIG_TRACING Add a new +T flag to enable tracing, independent of +p, and add and use 3 macros: dyndbg_site_is_enabled/logging/tracing(), to encapsulate the flag checks. Existing code treats T like other flags. Add ddebug_validate_flags() as last step in ddebug_parse_flags(). Its only job is to fail on +T for non-CONFIG_TRACING builds. It only sees the new flags, and cannot validate specific state transitions. This is fine, since we have no need for that; such a test would have to be done in ddebug_change(), which actually updates the callsites. ddebug_change() adjusts the static-key-enable/disable condition to use _DPRINTK_ENABLED / abstraction macros. dynamic_emit_prefix() now gates on _DPRINTK_ENABLED too, as an optimization but mostly to allow decluttering of its users. __dynamic_pr_debug() etal get minor changes: - call dynamic_emit_prefix() 1st, _enabled() optimizes. - if (T) call trace_array_printk - if (!p) go around original printk code. done to minimize diff, goto-ectomy + reindent later/separately - share vaf across p|T WRT <net|ib>_dev, I skipped all the <T,!!dev> specific dev_emit_prefix additions for now. tracefs is a fast customer with different needs, its not clear that pretty device-ID-ish strings is useful tracefs content (on ingest), or that couldn't be done more efficiently while analysing or postprocesing the tracefs buffer. SELFTEST: test_dynamic_debug.ko: Uses the tracer facility to implement a kernel module selftest. TODO: Earlier core code had (tracerfn)() indirection, allowing a plugin side-effector we could test the results of. ATM all the tests which count +T'd callsite executions (and which expect >0) are failing. Now it needs a rethink to test from userspace, rather than the current test-once at module-load. It needs a parameters/testme button. So remainder of this is a bit stale .... - A custom tracer counts the number of calls (of T-enabled pr_debugs), - do_debugging(x) calls a set of categorized pr_debugs x times - test registers the tracer on the module then iteratively: manipulates dyndbg states via query-cmds, mostly format ^prefix runs do_debugging() counts enabled callsite executions reports mismatches - modprobe test_dynamic_debug use_bad_tracer=1 attaches a bad/recursive tracer Bad Things (did) Happen. has thrown me interesting panics. cannot replicate atm. RFC: (DONE) The "tracer" interface probably needs work and a new name. It is only 1/2 way towards a real tracefs interface; and the code I lifted from Sean Paul in the next patch could be implemented in dynamic_debug.c instead, and made available for all pr_debug users. This would also eliminate need for dynamic_debug_(un)register_tracer(), since dyndbg could just provide it when TRACING is on. NOTES: $> modprobe test_dynamic_debug dyndbg=+p it fails 3/29 tests. havent looked at why. $> modprobe test_dynamic_debug use_bad_tracer=1 Earlier in dev, bad_tracer() exploded in recursion, I havent been able to replicate that lately. Signed-off-by: Jim Cromie <jim.cromie@gmail.com> --- .../admin-guide/dynamic-debug-howto.rst | 7 +- MAINTAINERS | 1 + include/linux/dynamic_debug.h | 12 +- lib/Kconfig.debug | 11 + lib/Makefile | 1 + lib/dynamic_debug.c | 127 ++++++++-- lib/test_dynamic_debug.c | 222 ++++++++++++++++++ 7 files changed, 355 insertions(+), 26 deletions(-) create mode 100644 lib/test_dynamic_debug.c