Re: [PATCH] drm/i915: add more debug info for when atomic updates fail v2

From: "Ville Syrjälä" <ville.syrjala@linux.intel.com>
To: Jesse Barnes <jbarnes@virtuousgeek.org>
Cc: intel-gfx@lists.freedesktop.org
Subject: Re: [PATCH] drm/i915: add more debug info for when atomic updates fail v2
Date: Tue, 15 Sep 2015 20:47:17 +0300	[thread overview]
Message-ID: <20150915174716.GB26517@intel.com> (raw)
In-Reply-To: <1442336625-12489-1-git-send-email-jbarnes@virtuousgeek.org>

On Tue, Sep 15, 2015 at 10:03:45AM -0700, Jesse Barnes wrote:
> I used these additional fields to track down the issue I saw on HSW.
> 
> v2: move debug fields into a substruct (Ville)
> 
> References: https://bugs.freedesktop.org/show_bug.cgi?id=91579
> Signed-off-by: Jesse Barnes <jbarnes@virtuousgeek.org>
> ---
>  drivers/gpu/drm/i915/intel_drv.h    |  8 ++++++--
>  drivers/gpu/drm/i915/intel_sprite.c | 30 +++++++++++++++++++++---------
>  2 files changed, 27 insertions(+), 11 deletions(-)
> 
> diff --git a/drivers/gpu/drm/i915/intel_drv.h b/drivers/gpu/drm/i915/intel_drv.h
> index 02a755a..1df6ebf 100644
> --- a/drivers/gpu/drm/i915/intel_drv.h
> +++ b/drivers/gpu/drm/i915/intel_drv.h
> @@ -565,8 +565,12 @@ struct intel_crtc {
>  
>  	int scanline_offset;
>  
> -	unsigned start_vbl_count;
> -	ktime_t start_vbl_time;
> +	struct {
> +		unsigned start_vbl_count;
> +		ktime_t start_vbl_time;
> +		int min_vbl, max_vbl;
> +		int scanline_start;
> +	} debug;
>  
>  	struct intel_crtc_atomic_commit atomic;
>  
> diff --git a/drivers/gpu/drm/i915/intel_sprite.c b/drivers/gpu/drm/i915/intel_sprite.c
> index 4d27243..4c627c4 100644
> --- a/drivers/gpu/drm/i915/intel_sprite.c
> +++ b/drivers/gpu/drm/i915/intel_sprite.c
> @@ -94,8 +94,11 @@ void intel_pipe_update_start(struct intel_crtc *crtc)
>  	min = vblank_start - usecs_to_scanlines(mode, 100);
>  	max = vblank_start - 1;
>  
> +	crtc->debug.min_vbl = min;
> +	crtc->debug.max_vbl = max;
> +
>  	local_irq_disable();
> -	crtc->start_vbl_count = 0;
> +	crtc->debug.start_vbl_count = 0;

Could group the debug stuff together.

>  
>  	if (min <= 0 || max <= 0)
>  		return;
> @@ -114,8 +117,10 @@ void intel_pipe_update_start(struct intel_crtc *crtc)
>  		prepare_to_wait(wq, &wait, TASK_UNINTERRUPTIBLE);
>  
>  		scanline = intel_get_crtc_scanline(crtc);
> -		if (scanline < min || scanline > max)
> +		if (scanline < min || scanline > max) {
> +			crtc->debug.scanline_start = scanline;
>  			break;
> +		}

That'll leave the scanline unset if we ever hit the timeout. Shouldn't
happen of course, but would still be safer to move the assignment to
happen after the loop. It would also allow you to group the debug
assignments into one place.

>  
>  		if (timeout <= 0) {
>  			DRM_ERROR("Potential atomic update failure on pipe %c\n",
> @@ -134,11 +139,12 @@ void intel_pipe_update_start(struct intel_crtc *crtc)
>  
>  	drm_crtc_vblank_put(&crtc->base);
>  
> -	crtc->start_vbl_time = ktime_get();
> -	crtc->start_vbl_count = dev->driver->get_vblank_counter(dev, pipe);
> +	crtc->debug.start_vbl_time = ktime_get();
> +	crtc->debug.start_vbl_count =
> +		dev->driver->get_vblank_counter(dev, pipe);
>  
>  	trace_i915_pipe_update_vblank_evaded(crtc, min, max,
> -					     crtc->start_vbl_count);
> +					     crtc->debug.start_vbl_count);

Could also simplify the tracepoint calls a bit by not passing in
the debug stuff separately. 'crtc' already gets passed in so the
tracepoint can look up everything internally.

trace_i915_pipe_update_start() could some similar treatment.

>  }
>  
>  /**
> @@ -161,10 +167,16 @@ void intel_pipe_update_end(struct intel_crtc *crtc)
>  
>  	local_irq_enable();
>  
> -	if (crtc->start_vbl_count && crtc->start_vbl_count != end_vbl_count)
> -		DRM_ERROR("Atomic update failure on pipe %c (start=%u end=%u) time %lld us\n",
> -			  pipe_name(pipe), crtc->start_vbl_count, end_vbl_count,
> -			  ktime_us_delta(end_vbl_time, crtc->start_vbl_time));
> +	if (crtc->debug.start_vbl_count &&
> +	    crtc->debug.start_vbl_count != end_vbl_count) {
> +		DRM_ERROR("Atomic update failure on pipe %c (start=%u end=%u) time %lld us, min %d, max %d, scanline start %d, end %d\n",
> +			  pipe_name(pipe), crtc->debug.start_vbl_count,
> +			  end_vbl_count,
> +			  ktime_us_delta(end_vbl_time, crtc->debug.start_vbl_time),
> +			  crtc->debug.min_vbl, crtc->debug.max_vbl,
> +			  crtc->debug.scanline_start,
> +			  intel_get_crtc_scanline(crtc));
> +	}

As with the frame counter and ktime, we should do the read before
local_irq_enable() to make sure we get an accurate number. It does mean
taking a minor hit for the non-failure case, but if that's a worry we
can of course skip the ktime_get() and scanline read unless the frame
counter shows a mismatch.

>  }
>  
>  static void
> -- 
> 1.9.1
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Ville Syrjälä
Intel OTC
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx