[PATCH v3] drm: Funnel drm logs to tracepoints

[Sean Paul]

On Fri, Dec 13, 2019 at 01:34:46PM +0200, Pekka Paalanen wrote:
> On Thu, 12 Dec 2019 15:32:35 -0500
> Sean Paul <sean at poorly.run> wrote:
> 
> > From: Sean Paul <seanpaul at chromium.org>
> > 
> > For a long while now, we (ChromeOS) have been struggling getting any
> > value out of user feedback reports of display failures (notably external
> > displays not working). The problem is that all logging, even fatal
> > errors (well, fatal in the sense that a display won't light up) are
> > logged at DEBUG log level. So in order to extract these logs, users need
> > to be able to turn on logging, and reproduce the issue with debug
> > enabled. Unfortunately, this isn't really something we can ask CrOS users
> > to do. I spoke with airlied about this and RHEL has similar issues. After
> > a few more people piped up on previous versions of this patch, it is a
> > Real Issue.
> > 
> > So why don't we just enable DRM_UT_BLAH? Here are the reasons in
> > ascending order of severity:
> >  1- People aren't consistent with their categories, so we'd have to
> >     enable a bunch to get proper coverage
> >  2- We don't want to overwhelm syslog with drm spam, others have to use
> >     it too
> >  3- Console logging is slow
> > 
> > So what we really want is a ringbuffer of the most recent logs
> > (filtered by categories we're interested in) exposed via debugfs so the
> > logs can be extracted when users file feedback.
> > 
> > It just so happens that there is something which does _exactly_ this!
> > This patch dumps drm logs into tracepoints, which allows us to turn tracing
> > on and off depending on which category is useful, and pull them from
> > tracefs on demand.
> > 
> > What about trace_printk()? It doesn't give us the control we get from using
> > tracepoints and it's not meant to be left sprinkled around in code.
> > 
> > Cc: David Airlie <airlied at gmail.com>
> > Cc: Daniel Vetter <daniel.vetter at ffwll.ch>
> > Cc: Pekka Paalanen <ppaalanen at gmail.com>
> > Cc: Joonas Lahtinen <joonas.lahtinen at linux.intel.com>
> > Cc: Thomas Zimmermann <tzimmermann at suse.de>
> > Cc: Rob Clark <robdclark at gmail.com>
> > Cc: Ville Syrjälä <ville.syrjala at linux.intel.com>
> > Acked-by: Daniel Vetter <daniel.vetter at ffwll.ch>
> > Signed-off-by: Sean Paul <seanpaul at chromium.org>
> > Link: https://patchwork.freedesktop.org/patch/msgid/20191010204823.195540-1-sean@poorly.run #v1
> > 
> > Changes in v2:
> > - Went with a completely different approach: https://lists.freedesktop.org/archives/dri-devel/2019-November/243230.html
> > 
> > Changes in v3:
> > - Changed commit message to be a bit less RFC-y
> > - Make class_drm_category_log an actual trace class
> > ---
> > 
> > Even though we don't want it to be, this is UAPI. So here's some userspace
> > code which uses it:
> > https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1965562
> > 
> > 
> >  drivers/gpu/drm/drm_print.c      | 143 ++++++++++++++++++++++++++-----
> >  include/trace/events/drm_print.h | 116 +++++++++++++++++++++++++
> >  2 files changed, 239 insertions(+), 20 deletions(-)
> >  create mode 100644 include/trace/events/drm_print.h
> 
> Hi,
> 
> reading the userspace patch is very enlightening, thanks.
> 
> It uses debugfs, and it uses the generic tracing UAPI. When all
> distributions will enable this debug logging like you do in your
> userspace patch (I really want that to be the end result, since
> otherwise we are back to asking people to manually enable debug and then
> reproduce the failure), does that scale?
> 
> What if V4L2 is the next one deciding they need a similar logging
> framework to debug camera issues? If the trace log is already flooded
> with DRM messages, it will be useless for them?
> 
> Or maybe someone else wants their piece and flood it even more
> aggressively than DRM, making the DRM messages disappear before they
> can be saved?
> 
> Is there a way to pull out messages
> from /sys/kernel/debug/tracing/trace and filter them on reading instead
> of on writing?

Hi Pekka,
Yep, there's also a trace_pipe output from tracefs. So you could pipe the output
through a classifier in userspace and split off different subsystems.

I think if this type of patch proliferates this could be a problem. In that case,
we'd probably have to become better citizens and reclassify some of our log
messages such that we're not needlessly spamming the trace buffer.

I'm not too worried about this since we have a number of tools at our disposal.

Sean


> 
> 
> Thanks,
> pq



-- 
Sean Paul, Software Engineer, Google / Chromium OS