drm/i915: Also record time difference if vblank evasion fails, v2.

This makes the error message slightly more useful.

Changes since v1:
- Use ktime_get() while irqs are still disabled. (vsyrjala)

Signed-off-by: Maarten Lankhorst <maarten.lankhorst@linux.intel.com>
Reviewed-by: Ville Syrjälä <ville.syrjala@linux.intel.com>
Signed-off-by: Daniel Vetter <daniel.vetter@ffwll.ch>
diff --git a/drivers/gpu/drm/i915/intel_drv.h b/drivers/gpu/drm/i915/intel_drv.h
index 8f8d320..090d67b 100644
--- a/drivers/gpu/drm/i915/intel_drv.h
+++ b/drivers/gpu/drm/i915/intel_drv.h
@@ -564,6 +564,8 @@
 	int scanline_offset;
 
 	unsigned start_vbl_count;
+	ktime_t start_vbl_time;
+
 	struct intel_crtc_atomic_commit atomic;
 
 	/* scalers available on this crtc */
diff --git a/drivers/gpu/drm/i915/intel_sprite.c b/drivers/gpu/drm/i915/intel_sprite.c
index c35c233..ca7e264 100644
--- a/drivers/gpu/drm/i915/intel_sprite.c
+++ b/drivers/gpu/drm/i915/intel_sprite.c
@@ -134,6 +134,7 @@
 
 	drm_crtc_vblank_put(&crtc->base);
 
+	crtc->start_vbl_time = ktime_get();
 	crtc->start_vbl_count = dev->driver->get_vblank_counter(dev, pipe);
 
 	trace_i915_pipe_update_vblank_evaded(crtc, min, max,
@@ -154,14 +155,16 @@
 	struct drm_device *dev = crtc->base.dev;
 	enum pipe pipe = crtc->pipe;
 	u32 end_vbl_count = dev->driver->get_vblank_counter(dev, pipe);
+	ktime_t end_vbl_time = ktime_get();
 
 	trace_i915_pipe_update_end(crtc, end_vbl_count);
 
 	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)\n",
-			  pipe_name(pipe), 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));
 }
 
 static void