[Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg log.

[Anusha Srivatsa]

On Wed, Nov 01, 2017 at 02:14:33PM +0100, Michal Wajdeczko wrote:
> On Wed, 01 Nov 2017 01:11:20 +0100, Anusha Srivatsa
> <anusha.srivatsa at intel.com> wrote:
> 
> >Calculate the time that GuC takes to load using
> >jiffies. This information could be very useful in
>   ^^^^^^^
> This is no longer true.

True. Will sending an all new patch with updated 
approach(using ktime instead of jiffies) be good?
Or stick to this with change in commit message?

> >determining if GuC is taking unreasonably long time
> >to load in a certain platforms.
> >
> >v2: Calculate time before logs are collected.
> >Move the guc_load_time variable as a part of
> >intel_uc_fw struct. Store only final result
> >which is to be exported to debugfs. (Michal)
> >Add the load time in the print message as well.
> >
> >v3: Remove debugfs entry. Remove local variable
> >guc_finish_load. (Daniel, Tvrtko)
> >
> >v4: Use ktime_get() instead of jiffies. Use DRM_NOTE
> >if time taken to load is more than the threshold. On
> >load times within acceptable range, use DRM_DEBUG_DRIVER
> >(Tvrtko)
> >
> >v5: Rebased. Do not expose the load time variable in a global
> >struct (Tvrtko, Joonas)
> >
> >Cc: Chris Wilson <chris at chris-wilson.co.uk>
> >Cc: Daniel Vetter <daniel.vetter at ffwll.ch>
> >Cc: Michal Wajdeczko <michal.wajdeczko at intel.com>
> >Cc: Oscar Mateo <oscar.mateo at intel.com>
> >Cc: Sujaritha Sundaresan <sujaritha.sundaresan at intel.com>
> >Cc: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> >Signed-off-by: Anusha Srivatsa <anusha.srivatsa at intel.com>
> >---
> > drivers/gpu/drm/i915/intel_guc_fw.c | 11 +++++++++--
> > 1 file changed, 9 insertions(+), 2 deletions(-)
> >
> >diff --git a/drivers/gpu/drm/i915/intel_guc_fw.c
> >b/drivers/gpu/drm/i915/intel_guc_fw.c
> >index ef67a36..4ce9a30 100644
> >--- a/drivers/gpu/drm/i915/intel_guc_fw.c
> >+++ b/drivers/gpu/drm/i915/intel_guc_fw.c
> >@@ -133,7 +133,8 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
> >*dev_priv,
> > 	unsigned long offset;
> > 	struct sg_table *sg = vma->pages;
> > 	u32 status, rsa[UOS_RSA_SCRATCH_MAX_COUNT];
> >-	int i, ret = 0;
> >+	int i, ret = 0, load_time;
> 
> Note that ktime_ms_delta() return type is s64 not int.
> 
> >+	ktime_t start_load;
> 
> s/start_load/now ?

I think start_load is verbose. 
 
> >	/* where RSA signature starts */
> > 	offset = guc_fw->rsa_offset;
> >@@ -160,6 +161,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
> >*dev_priv,
> > 	I915_WRITE(DMA_ADDR_1_HIGH, DMA_ADDRESS_SPACE_WOPCM);
> >	/* Finally start the DMA */
> >+	start_load = ktime_get();
> 
> Maybe we should either update comment with note about taking start time
> or move ktime_get call before that comment to avoid confusion..

I prefer the latter.
 
> > 	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(UOS_MOVE | START_DMA));
> >	/*
> >@@ -172,13 +174,18 @@ static int guc_ucode_xfer_dma(struct
> >drm_i915_private *dev_priv,
> > 	 */
> > 	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
> >+	load_time = ktime_ms_delta(ktime_get(), start_load);
> >+
> > 	DRM_DEBUG_DRIVER("DMA status 0x%x, GuC status 0x%x\n",
> > 			I915_READ(DMA_CTRL), status);
> >	if ((status & GS_BOOTROM_MASK) == GS_BOOTROM_RSA_FAILED) {
> > 		DRM_ERROR("GuC firmware signature verification failed\n");
> > 		ret = -ENOEXEC;
> >-	}
> >+	} else if (load_time > 20)
> >+		DRM_NOTE("GuC load takes more than acceptable threshold\n");
> 
> Please add threshold and actual load time to the message to let user
> know that times
 
> >+	else
> >+		DRM_DEBUG_DRIVER("GuC loaded in %d ms\n", load_time);
> 
> And I'm not sure that we can rely on 'load_time' on timeout in wait_for.

Hmm.... we  are checking the DMA status right after that which means
the firmware load should have happened by then.... thats why I 
am calculating it there....

 
> >	DRM_DEBUG_DRIVER("returning %d\n", ret);

-- 
Anusha Srivatsa