Re: [PATCH 7/7] drm/i915: Add pipe update trace points

["Ville Syrjälä" <ville.syrjala@linux.intel.com>]

On Thu, Dec 12, 2013 at 01:08:16PM -0800, Jesse Barnes wrote:
> On Thu, 17 Oct 2013 22:53:19 +0300
> ville.syrjala@linux.intel.com wrote:
> 
> > From: Ville Syrjälä <ville.syrjala@linux.intel.com>
> > 
> > Add trace points for observing the atomic pipe update mechanism.
> > 
> > Signed-off-by: Ville Syrjälä <ville.syrjala@linux.intel.com>
> > ---
> >  drivers/gpu/drm/i915/i915_trace.h   | 77 +++++++++++++++++++++++++++++++++++++
> >  drivers/gpu/drm/i915/intel_sprite.c |  6 +++
> >  2 files changed, 83 insertions(+)
> > 
> > diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
> > index 6e580c9..9ffb232 100644
> > --- a/drivers/gpu/drm/i915/i915_trace.h
> > +++ b/drivers/gpu/drm/i915/i915_trace.h
> > @@ -7,6 +7,7 @@
> >  
> >  #include <drm/drmP.h>
> >  #include "i915_drv.h"
> > +#include "intel_drv.h"
> >  #include "intel_ringbuffer.h"
> >  
> >  #undef TRACE_SYSTEM
> > @@ -14,6 +15,82 @@
> >  #define TRACE_SYSTEM_STRING __stringify(TRACE_SYSTEM)
> >  #define TRACE_INCLUDE_FILE i915_trace
> >  
> > +/* pipe updates */
> > +
> > +TRACE_EVENT(i915_pipe_update_start,
> > +	    TP_PROTO(struct drm_crtc *crtc, u32 min, u32 max),
> > +	    TP_ARGS(crtc, min, max),
> > +
> > +	    TP_STRUCT__entry(
> > +			     __field(enum pipe, pipe)
> > +			     __field(u32, frame)
> > +			     __field(u32, scanline)
> > +			     __field(u32, min)
> > +			     __field(u32, max)
> > +			     ),
> > +
> > +	    TP_fast_assign(
> > +			   __entry->pipe = to_intel_crtc(crtc)->pipe;
> > +			   __entry->frame = crtc->dev->driver->get_vblank_counter(crtc->dev,
> > +										  to_intel_crtc(crtc)->pipe);
> > +			   __entry->scanline = i915_get_crtc_scanline(crtc);
> > +			   __entry->min = min;
> > +			   __entry->max = max;
> > +			   ),
> > +
> > +	    TP_printk("pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > +		      pipe_name(__entry->pipe), __entry->frame,
> > +		       __entry->scanline, __entry->min, __entry->max)
> > +);
> > +
> > +TRACE_EVENT(i915_pipe_update_vblank_evaded,
> > +	    TP_PROTO(struct drm_crtc *crtc, u32 min, u32 max),
> > +	    TP_ARGS(crtc, min, max),
> > +
> > +	    TP_STRUCT__entry(
> > +			     __field(enum pipe, pipe)
> > +			     __field(u32, frame)
> > +			     __field(u32, scanline)
> > +			     __field(u32, min)
> > +			     __field(u32, max)
> > +			     ),
> > +
> > +	    TP_fast_assign(
> > +			   __entry->pipe = to_intel_crtc(crtc)->pipe;
> > +			   __entry->frame = crtc->dev->driver->get_vblank_counter(crtc->dev,
> > +										  to_intel_crtc(crtc)->pipe);
> > +			   __entry->scanline = i915_get_crtc_scanline(crtc);
> > +			   __entry->min = min;
> > +			   __entry->max = max;
> > +			   ),
> > +
> > +	    TP_printk("pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > +		      pipe_name(__entry->pipe), __entry->frame,
> > +		       __entry->scanline, __entry->min, __entry->max)
> > +);
> > +
> > +TRACE_EVENT(i915_pipe_update_end,
> > +	    TP_PROTO(struct drm_crtc *crtc),
> > +	    TP_ARGS(crtc),
> > +
> > +	    TP_STRUCT__entry(
> > +			     __field(enum pipe, pipe)
> > +			     __field(u32, frame)
> > +			     __field(u32, scanline)
> > +			     ),
> > +
> > +	    TP_fast_assign(
> > +			   __entry->pipe = to_intel_crtc(crtc)->pipe;
> > +			   __entry->frame = crtc->dev->driver->get_vblank_counter(crtc->dev,
> > +										  to_intel_crtc(crtc)->pipe);
> > +			   __entry->scanline = i915_get_crtc_scanline(crtc);
> > +			   ),
> > +
> > +	    TP_printk("pipe %c, frame=%u, scanline=%u",
> > +		      pipe_name(__entry->pipe), __entry->frame,
> > +		      __entry->scanline)
> > +);
> > +
> >  /* object tracking */
> >  
> >  TRACE_EVENT(i915_gem_object_create,
> > diff --git a/drivers/gpu/drm/i915/intel_sprite.c b/drivers/gpu/drm/i915/intel_sprite.c
> > index f871b8f..874ffc1 100644
> > --- a/drivers/gpu/drm/i915/intel_sprite.c
> > +++ b/drivers/gpu/drm/i915/intel_sprite.c
> > @@ -63,6 +63,8 @@ static void intel_pipe_update_start(struct drm_crtc *crtc)
> >  
> >  	local_irq_disable();
> >  
> > +	trace_i915_pipe_update_start(crtc, min, max);
> > +
> >  	intel_crtc->vbl_received = false;
> >  	scanline = i915_get_crtc_scanline(crtc);
> >  
> > @@ -78,10 +80,14 @@ static void intel_pipe_update_start(struct drm_crtc *crtc)
> >  	}
> >  
> >  	drm_vblank_put(dev, pipe);
> > +
> > +	trace_i915_pipe_update_vblank_evaded(crtc, min, max);
> >  }
> >  
> >  static void intel_pipe_update_end(struct drm_crtc *crtc)
> >  {
> > +	trace_i915_pipe_update_end(crtc);
> > +
> >  	local_irq_enable();
> >  }
> >  
> 
> Not sure about the "vblank_evaded" one.  Seems like you'd have enough
> info from the start/end to figure out if you missed, since you'd have
> the time and vblank seqno, right?   But that's really no biggie.

The evaded tracepoint is quite important since it allows us to verify
that the evaded->end sequence really took place during one frame.
start->end doesn't really tell us much because when the vblank gets
evaded those two tracepoints land on alternate frames.

> 
> It does make me think we should start documenting these events though...
> 
> Reviewed-by: Jesse Barnes <jbarnes@virtuousgeek.org>
> 
> -- 
> Jesse Barnes, Intel Open Source Technology Center

-- 
Ville Syrjälä
Intel OTC