[PATCH 0/6] drm: trace: Introduce drm_trace() and instrument drm_atomic.c

Fri Nov 8 16:49:17 UTC 2019

On Fri, Nov 08, 2019 at 11:23:27AM -0500, Sean Paul wrote:
> On Fri, Nov 08, 2019 at 09:59:19AM +0100, Daniel Vetter wrote:
> > On Fri, Nov 08, 2019 at 09:46:48AM +0100, Daniel Vetter wrote:
> > > On Fri, Nov 08, 2019 at 10:16:59AM +0200, Pekka Paalanen wrote:
> > > > On Thu,  7 Nov 2019 16:02:59 -0500
> > > > Sean Paul <sean at poorly.run> wrote:
> > > > 
> > > > > From: Sean Paul <seanpaul at chromium.org>
> > > > > 
> > > > > Hey all,
> > > > > I'm back with another trace events patchset. My first attempt [1] went
> > > > > better than expected, with enthusiasm for the idea and distain for the
> > > > > implementation.
> > > > > 
> > > > > As promised, I went through and added proper trace events.
> > > > > 
> > > > > Before I get _too_ far, I wanted to post this set to get feedback on the
> > > > > direction I'm going. I've gone back and forth on whether to introduce a
> > > > > bunch of trace systems vs using the trace class enum. I've settled on
> > > > > the trace class enum since it seems more extensible and easier to use in
> > > > > production that just having the blunt "enable this system", or
> > > > > the tedious "enable each event I'm interested in individually" methods.
> > > > > 
> > > > > So, consider this one an RFC unless we're all in agreement, in which
> > > > > case we should apply it :)
> > > > >
> > > > 
> > > > Hi Sean,
> > > > 
> > > > thanks for working on this. I'm not at all familiar with the trace
> > > > infrastructure, so I'd like to know how flight recorder type of
> > > > behaviour (a continuously written fixed size ring buffer) can be
> > > > achieved. Let us have a display server in userspace which in production
> > > > hits an unexpected condition with DRM and needs to record information
> > > > for post-mortem debugging. What should it do to have a trace log after
> > > > the fact to attach with a bug report?
> > > 
> > > Yeah I think this has the uapi smell, so would need the userspace side
> > > too, once we agree on something.
> > > 
> 
> For our (Chrome OS) use, the uapi is pretty simple:
> 
> #! /usr/bin/env
> 
> mask=$1
> 
> pushd /sys/kernel/tracing
> echo "event_class & $mask" > events/drm/filter
> echo 1 > events/drm/enable
> echo 1 > tracing_on
> popd
> 
> 
> Then when we need to log something:
> 
> cat /sys/kernel/tracing/trace_pipe
> 
> 
> 
> > > > I assume that is a major use case for this new feature. Is performance
> > > > profiling another use case?
> 
> Not at the present.
> 
> 
> > > > 
> > > > Is it ok to build userspace to rely on these trace events during normal
> > > > operations, e.g. for continuous adjustment of timings/timers?
> > > 
> > > Yeah I'm kinda freaked out about this. In the old thread we discussed the
> > > question of whether dumping dmesg into tracepoints would make them uapi,
> > > but no conclusion was reached.
> > > 
> > > Now instead we're going to duplicate a lot of these debug outputs, with
> > > specific trace events, which is going to make them even more uapi. And a
> > > lot of these are very much implementation details (drivers might change
> > > their opinion on which other states they need for check/commit, e.g. if
> > > they move a bunch of global state from crtcs into a new driver private
> > > internal object). Explicit tracepoints with symbol value imo will have a
> > > much higher chance that someone starts relying on them.
> > > 
> > > Also, dmesg is uapi too. Except there's a gentlemen's agreement that you
> > > should depend upon it because it will make kernel engineers really pissed
> > > if they can't change/move a specific string. So from that point I think
> > > just dumping the existing debug strings as unstructured strings into trace
> > > buffers is a much better idea. Plus no need to have the same information
> > > duplicated in both a debug output and a tracepoint.
> > > 
> > > I think even slightly structured debug tracepoints (e.g. a simple
> > > (drm_object_id, string) pair) would be too structured since then userspace
> > > could start watching for events on specific things and maybe use that for
> > > their retry loops after TEST_ONLY failures. Even though we have a lot of
> > > debug output strings where that bit of structure is essentially there
> > > already.
> > > 
> > > Aside from this a question on process ... I re-read the old thread and I'm
> > > not sure how you concluded we've reached consensus on this here, seemed
> > > all pretty inconclusive on the details and discussions died out?
> > 
> > Reading the thread again I guess it was Joonas comment that tracepoints
> > are also uapi, and you concluded we can't do this at all.
> > 
> > The trouble is, _everything_ that's observeable from userspace is uapi. So
> > dmesg, timing of the code, ... For a real funky example of this look at
> > the ext4 regression, where better code resulted in less entropy generated
> > and the system hung at boot-up.
> > 
> > But on the flip side, it's only uapi we can't change if someone depends
> > upon it. For dmesg most people understand that parsing dmesg is bad taste,
> > so generally not a big problem. For tracepoints, especially if they come
> > with lots of structured uapi, it's a lot more "this is baked in forever".
> > But it doesn't have to be, with changed them quite a few times. But as a
> > rule of thumb, the more structured the data is you present to userspace,
> > the more likely they'll use it in actual control flow, and the more likely
> > a change will break userspace in a meaningful way.
> > 
> > Hence for debugging I think least amount of structure is best, plus huge
> > warnings that you really shouldn't use this for anything else than
> > debug logs. Anything more that leaks all these implementation details
> > gives me the chillies. And Pekka's question right off the bat with "can I
> > use this for tuning timers" kinda proves my point. If it loosk like
> > intentional uapi userspace will treat it like intentional uapi.
> 
> So the more useful the data, the less desirable it is to surface :-)
> 
> Playing devil's advocate for a second (and probably exposing my naivity),
> would it be _so_ bad if userspace inspected the traces for check failure
> cause? If we remove a check in the core, the trace event just never
> fires (no u/s breakage), if we change a check, we introduce a new trace
> event to reflect reality and the old event goes quiet.

At that point you've broken userspace if you're unlucky. Scenario.

1. userspace does a TEST_ONLY
2. it fails, but userspace sees the magic trace event, and does a Magic
Fallback (tm)
3. everyone is happy

2a. it still fails, but now the exact tracepoint is gone, or move
sufficiently that userspace doesn't spot it anymore.
3. userspace falls back to something dumb, maybe single fullscreen untiled
plane, resulting in a slide show
4. user is seriously pissed at the slideshow
5. one grumpy kernel maintainer gets to apply a few reverts

So yeah if we create a few nicely structured tracepoints "for debugging"
and compositor people spot then and go all "oh cool, I can use this",
we're screwed.

> We could accrue some debt if a state variable changes since we'd have to keep
> the structure of the trace event and tack on the end. To combat this we could
> scrutinize the information exposed for each state and make sure that we're
> choosing stable values (in the extreme we could limit the info to only
> property-backed values). Additionally, we can always expose new trace events
> if things change too dramatically and lean on the event classes/filtering for
> versioning.

You can't just expose new trace events, if userspace relies on the old
ones they have to keep working. Some subsystems are sufficiently paranoid
about that that the answer is "no tracepoint, sry". Which then results in
people doing dynamic tracing, which ofc is even worse from a "will it
break?" pov.

It's all a tradeoff, and at least personally I figured the debug dump
without any structure at all seemed like the least risky. Most reasonable
people already agree that enabling debugging and parsing dmesg is not a
good idea. Hopefully they'll have the same feeling about unstructured
debug crap dumped into tracepoints.

The only part that _will_ become uapi for that is the exact name of the
tracepoint, since userspace will need to know that one to be able to
enable it.
-Daniel

> 
> Sean
> 
> 
> > -Daniel
> > 
> > 
> > > -Daniel
> > > 
> > > 
> > > > 
> > > > 
> > > > Thanks,
> > > > pq
> > > > 
> > > > 
> > > > > 
> > > > > [1]- https://patchwork.freedesktop.org/patch/335350/
> > > > > 
> > > > > Sean Paul (6):
> > > > >   drm: trace: Make the vblank queued/delivered events classed
> > > > >   drm: trace: Introduce drm_trace() and trace event classes
> > > > >   drm: trace: Add trace events for atomic state lifetime
> > > > >   drm: trace: Add crtc state trace events
> > > > >   drm: trace: Add connector state tracing
> > > > >   drm: trace: Add plane state tracing
> > > > > 
> > > > >  Documentation/gpu/drm-internals.rst |   9 +
> > > > >  drivers/gpu/drm/drm_atomic.c        |  61 ++-
> > > > >  drivers/gpu/drm/drm_trace.h         | 563 ++++++++++++++++++++++++++--
> > > > >  drivers/gpu/drm/drm_vblank.c        |   8 +-
> > > > >  4 files changed, 609 insertions(+), 32 deletions(-)
> > > > > 
> > > > 
> > > 
> > > 
> > > 
> > > -- 
> > > Daniel Vetter
> > > Software Engineer, Intel Corporation
> > > http://blog.ffwll.ch
> > 
> > -- 
> > Daniel Vetter
> > Software Engineer, Intel Corporation
> > http://blog.ffwll.ch
> 
> -- 
> Sean Paul, Software Engineer, Google / Chromium OS

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch