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

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

[Srivatsa, Anusha]

Sending to intel-gfx.


>-----Original Message-----
>From: Ursulin, Tvrtko
>Sent: Thursday, September 21, 2017 8:16 AM
>To: Srivatsa, Anusha <anusha.srivatsa@intel.com>; intel-
>gfx@lists.freedektop.org
>Cc: Chris Wilson <chris@chris-wilson.co.uk>; Vetter, Daniel
><daniel.vetter@intel.com>; Sundaresan, Sujaritha
><sujaritha.sundaresan@intel.com>; Mateo Lozano, Oscar
><oscar.mateo@intel.com>; Wajdeczko, Michal <Michal.Wajdeczko@intel.com>
>Subject: RE: [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg log.
>
>
>Hi,
>
>For some reason this email hasn't appeared on the mailing list so apologies for a
>lame Outlook reply.

Thanks Tvrtko. I corrected the address.

>I thought we agreed to use a better time source than jiffies (ktime_get()) and also
>that DRM_NOTE would get emitted only in the case of load time being over some
>threshold. If it is in realm of normal it should be a normal DRM_DEBUG_DRIVER.

If it is over 20 ms (the threshold) wont DRM_ERROR be a better option? If it is within that limit, then the info will be in DRM_DEBUG_DRIVER from which the  QA can pick it.

Anusha 

>Tvrtko
>
>-----Original Message-----
>From: Srivatsa, Anusha
>Sent: Thursday, September 21, 2017 1:44 AM
>To: intel-gfx@lists.freedektop.org
>Cc: Srivatsa, Anusha <anusha.srivatsa@intel.com>; Chris Wilson <chris@chris-
>wilson.co.uk>; Ursulin, Tvrtko <tvrtko.ursulin@intel.com>; Vetter, Daniel
><daniel.vetter@intel.com>; Sundaresan, Sujaritha
><sujaritha.sundaresan@intel.com>; Mateo Lozano, Oscar
><oscar.mateo@intel.com>; Wajdeczko, Michal <Michal.Wajdeczko@intel.com>
>Subject: [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg log.
>
>Calculate the time that GuC takes to load using jiffies. This information could be
>very useful in 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)
>
>Cc: Chris Wilson <chris@chris-wilson.co.uk>
>Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
>Cc: Daniel Vetter <daniel.vetter@intel.com>
>Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
>Cc: Oscar Mateo <oscar.mateo@intel.com>
>Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
>Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
>---
> drivers/gpu/drm/i915/intel_guc_loader.c | 7 +++++++
> drivers/gpu/drm/i915/intel_uc.h         | 1 +
> 2 files changed, 8 insertions(+)
>
>diff --git a/drivers/gpu/drm/i915/intel_guc_loader.c
>b/drivers/gpu/drm/i915/intel_guc_loader.c
>index 8b0ae7f..4b1fc55 100644
>--- a/drivers/gpu/drm/i915/intel_guc_loader.c
>+++ b/drivers/gpu/drm/i915/intel_guc_loader.c
>@@ -199,6 +199,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
>*dev_priv,
> 	struct sg_table *sg = vma->pages;
> 	u32 status, rsa[UOS_RSA_SCRATCH_MAX_COUNT];
> 	int i, ret = 0;
>+	unsigned long guc_start_load;
>
> 	/* where RSA signature starts */
> 	offset = guc_fw->rsa_offset;
>@@ -226,6 +227,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
>*dev_priv,
>
> 	/* Finally start the DMA */
> 	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(UOS_MOVE |
>START_DMA));
>+	guc_start_load = jiffies;
>
> 	/*
> 	 * Wait for the DMA to complete & the GuC to start up.
>@@ -237,6 +239,8 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
>*dev_priv,
> 	 */
> 	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
>
>+	guc_fw->load_time = jiffies_to_msecs(jiffies - guc_start_load);
>+
> 	DRM_DEBUG_DRIVER("DMA status 0x%x, GuC status 0x%x\n",
> 			I915_READ(DMA_CTRL), status);
>
>@@ -372,6 +376,9 @@ int intel_guc_init_hw(struct intel_guc *guc)
> 		 guc->fw.path,
> 		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
>
>+	DRM_NOTE("Time taken to load GuC is %lu ms\n",
>+		 guc->fw.load_time);
>+
> 	return 0;
> }
>
>diff --git a/drivers/gpu/drm/i915/intel_uc.h b/drivers/gpu/drm/i915/intel_uc.h
>index 7703c9a..749b069 100644
>--- a/drivers/gpu/drm/i915/intel_uc.h
>+++ b/drivers/gpu/drm/i915/intel_uc.h
>@@ -136,6 +136,7 @@ struct intel_uc_fw {
> 	uint32_t rsa_offset;
> 	uint32_t ucode_size;
> 	uint32_t ucode_offset;
>+	unsigned long load_time;
> };
>
> struct intel_guc_log {
>--
>2.7.4

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Tvrtko Ursulin]

On 22/09/2017 21:12, Srivatsa, Anusha wrote:
> Sending to intel-gfx.
> 
> 
>> -----Original Message-----
>> From: Ursulin, Tvrtko
>> Sent: Thursday, September 21, 2017 8:16 AM
>> To: Srivatsa, Anusha <anusha.srivatsa@intel.com>; intel-
>> gfx@lists.freedektop.org
>> Cc: Chris Wilson <chris@chris-wilson.co.uk>; Vetter, Daniel
>> <daniel.vetter@intel.com>; Sundaresan, Sujaritha
>> <sujaritha.sundaresan@intel.com>; Mateo Lozano, Oscar
>> <oscar.mateo@intel.com>; Wajdeczko, Michal <Michal.Wajdeczko@intel.com>
>> Subject: RE: [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg log.
>>
>>
>> Hi,
>>
>> For some reason this email hasn't appeared on the mailing list so apologies for a
>> lame Outlook reply.
> 
> Thanks Tvrtko. I corrected the address.
> 
>> I thought we agreed to use a better time source than jiffies (ktime_get()) and also
>> that DRM_NOTE would get emitted only in the case of load time being over some
>> threshold. If it is in realm of normal it should be a normal DRM_DEBUG_DRIVER.
> 
> If it is over 20 ms (the threshold) wont DRM_ERROR be a better option? If it is within that limit, then the info will be in DRM_DEBUG_DRIVER from which the  QA can pick it.

Error only if it fails to load I think. DRM_NOTE was for cases when it 
succeeds but after taking unexpectedly long. Just so it is a level about 
informational.

Regards,

Tvrtko
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Anusha Srivatsa]

Calculate the time that GuC takes to load using
jiffies. This information could be very useful in
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)

Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
Cc: Oscar Mateo <oscar.mateo@intel.com>
Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
---
 drivers/gpu/drm/i915/intel_guc_loader.c | 10 +++++++++-
 drivers/gpu/drm/i915/intel_uc.h         |  1 +
 2 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/i915/intel_guc_loader.c b/drivers/gpu/drm/i915/intel_guc_loader.c
index c9e25be..a0b562c 100644
--- a/drivers/gpu/drm/i915/intel_guc_loader.c
+++ b/drivers/gpu/drm/i915/intel_guc_loader.c
@@ -199,6 +199,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private *dev_priv,
 	struct sg_table *sg = vma->pages;
 	u32 status, rsa[UOS_RSA_SCRATCH_MAX_COUNT];
 	int i, ret = 0;
+	ktime_t start_load;
 
 	/* where RSA signature starts */
 	offset = guc_fw->rsa_offset;
@@ -225,6 +226,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();
 	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(UOS_MOVE | START_DMA));
 
 	/*
@@ -237,13 +239,17 @@ static int guc_ucode_xfer_dma(struct drm_i915_private *dev_priv,
 	 */
 	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
 
+	guc_fw->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 (guc_fw->load_time > 20)
+		DRM_NOTE("Time taken to load GuC is more than the acceptable \
+			 threshold\n");
 
 	DRM_DEBUG_DRIVER("returning %d\n", ret);
 
@@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
 		 guc->fw.path,
 		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
 
+	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
+
 	return 0;
 }
 
diff --git a/drivers/gpu/drm/i915/intel_uc.h b/drivers/gpu/drm/i915/intel_uc.h
index 6966349..65b9674 100644
--- a/drivers/gpu/drm/i915/intel_uc.h
+++ b/drivers/gpu/drm/i915/intel_uc.h
@@ -136,6 +136,7 @@ struct intel_uc_fw {
 	uint32_t rsa_offset;
 	uint32_t ucode_size;
 	uint32_t ucode_offset;
+	unsigned long long load_time;
 };
 
 struct intel_guc_log {
-- 
2.7.4

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

[PATCH 2/2] drm/i915/huc: Add HuC Load time to dmesg log.

[Anusha Srivatsa]

This patch uses jiffies to calculate the huc
load time.This information can be useful for testing
to know how much time huc takes to load.

v2: Remove debugfs entry. Remove local variable
    huc_finish_load. (Daniel, Tvrtko)
v3: Use ktime_get() for more accurate timings.
    Ensure the load is successful, before load times
    is printed. (Tvrtko, Michal)

Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
Cc: Oscar Mateo Lozano <oscar.mateo@intel.com>
Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
---
 drivers/gpu/drm/i915/intel_huc.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/drivers/gpu/drm/i915/intel_huc.c b/drivers/gpu/drm/i915/intel_huc.c
index 8b4b535..972ae63 100644
--- a/drivers/gpu/drm/i915/intel_huc.c
+++ b/drivers/gpu/drm/i915/intel_huc.c
@@ -90,6 +90,7 @@ static int huc_ucode_xfer(struct drm_i915_private *dev_priv)
 	unsigned long offset = 0;
 	u32 size;
 	int ret;
+	ktime_t start_load;
 
 	ret = i915_gem_object_set_to_gtt_domain(huc_fw->obj, false);
 	if (ret) {
@@ -121,11 +122,14 @@ static int huc_ucode_xfer(struct drm_i915_private *dev_priv)
 	I915_WRITE(DMA_COPY_SIZE, size);
 
 	/* Start the DMA */
+	start_load = ktime_get();
 	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(HUC_UKERNEL | START_DMA));
 
 	/* Wait for DMA to finish */
 	ret = wait_for((I915_READ(DMA_CTRL) & START_DMA) == 0, 100);
 
+	huc_fw->load_time = ktime_ms_delta(ktime_get(), start_load);
+
 	DRM_DEBUG_DRIVER("HuC DMA transfer wait over with ret %d\n", ret);
 
 	/* Disable the bits once DMA is over */
@@ -220,6 +224,9 @@ void intel_huc_init_hw(struct intel_huc *huc)
 
 	if (huc->fw.load_status != INTEL_UC_FIRMWARE_SUCCESS)
 		DRM_ERROR("Failed to complete HuC uCode load with ret %d\n", err);
+	else
+		DRM_DEBUG_DRIVER("Time taken to load HuC %lld ms\n",
+			 huc->fw.load_time);
 
 	return;
 }
-- 
2.7.4

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.BAT: success for series starting with [1/2] drm/i915/guc: Add GuC Load time to dmesg log.

[Patchwork]

== Series Details ==

Series: series starting with [1/2] drm/i915/guc: Add GuC Load time to dmesg log.
URL   : https://patchwork.freedesktop.org/series/31363/
State : success

== Summary ==

Series 31363v1 series starting with [1/2] drm/i915/guc: Add GuC Load time to dmesg log.
https://patchwork.freedesktop.org/api/1.0/series/31363/revisions/1/mbox/

Test chamelium:
        Subgroup dp-crc-fast:
                pass       -> FAIL       (fi-kbl-7500u) fdo#102514

fdo#102514 https://bugs.freedesktop.org/show_bug.cgi?id=102514

fi-bdw-5557u     total:289  pass:268  dwarn:0   dfail:0   fail:0   skip:21  time:454s
fi-bdw-gvtdvm    total:289  pass:265  dwarn:0   dfail:0   fail:0   skip:24  time:472s
fi-blb-e6850     total:289  pass:224  dwarn:1   dfail:0   fail:0   skip:64  time:397s
fi-bsw-n3050     total:289  pass:243  dwarn:0   dfail:0   fail:0   skip:46  time:569s
fi-bwr-2160      total:289  pass:184  dwarn:0   dfail:0   fail:0   skip:105 time:287s
fi-bxt-dsi       total:289  pass:259  dwarn:0   dfail:0   fail:0   skip:30  time:528s
fi-bxt-j4205     total:289  pass:260  dwarn:0   dfail:0   fail:0   skip:29  time:531s
fi-byt-j1900     total:289  pass:254  dwarn:1   dfail:0   fail:0   skip:34  time:542s
fi-byt-n2820     total:289  pass:250  dwarn:1   dfail:0   fail:0   skip:38  time:534s
fi-cfl-s         total:289  pass:256  dwarn:1   dfail:0   fail:0   skip:32  time:552s
fi-cnl-y         total:289  pass:261  dwarn:1   dfail:0   fail:0   skip:27  time:615s
fi-elk-e7500     total:289  pass:230  dwarn:0   dfail:0   fail:0   skip:59  time:434s
fi-glk-1         total:289  pass:261  dwarn:0   dfail:0   fail:0   skip:28  time:590s
fi-hsw-4770      total:289  pass:263  dwarn:0   dfail:0   fail:0   skip:26  time:437s
fi-hsw-4770r     total:289  pass:263  dwarn:0   dfail:0   fail:0   skip:26  time:418s
fi-ilk-650       total:289  pass:229  dwarn:0   dfail:0   fail:0   skip:60  time:470s
fi-ivb-3520m     total:289  pass:261  dwarn:0   dfail:0   fail:0   skip:28  time:510s
fi-ivb-3770      total:289  pass:261  dwarn:0   dfail:0   fail:0   skip:28  time:475s
fi-kbl-7500u     total:289  pass:263  dwarn:1   dfail:0   fail:1   skip:24  time:496s
fi-kbl-7560u     total:289  pass:270  dwarn:0   dfail:0   fail:0   skip:19  time:581s
fi-kbl-7567u     total:289  pass:265  dwarn:4   dfail:0   fail:0   skip:20  time:489s
fi-kbl-r         total:289  pass:262  dwarn:0   dfail:0   fail:0   skip:27  time:595s
fi-pnv-d510      total:289  pass:223  dwarn:1   dfail:0   fail:0   skip:65  time:655s
fi-skl-6260u     total:289  pass:269  dwarn:0   dfail:0   fail:0   skip:20  time:478s
fi-skl-6700k     total:289  pass:265  dwarn:0   dfail:0   fail:0   skip:24  time:534s
fi-skl-6770hq    total:289  pass:269  dwarn:0   dfail:0   fail:0   skip:20  time:524s
fi-skl-gvtdvm    total:289  pass:266  dwarn:0   dfail:0   fail:0   skip:23  time:476s
fi-snb-2520m     total:289  pass:251  dwarn:0   dfail:0   fail:0   skip:38  time:578s
fi-snb-2600      total:289  pass:250  dwarn:0   dfail:0   fail:0   skip:39  time:432s

654360cf73feea27f7ed5bfa2e5b2fa5ede2e8ec drm-tip: 2017y-10m-03d-17h-55m-08s UTC integration manifest
a62859b3af32 drm/i915/huc: Add HuC Load time to dmesg log.
09abcf680851 drm/i915/guc: Add GuC Load time to dmesg log.

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_5892/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.IGT: success for series starting with [1/2] drm/i915/guc: Add GuC Load time to dmesg log.

[Patchwork]

== Series Details ==

Series: series starting with [1/2] drm/i915/guc: Add GuC Load time to dmesg log.
URL   : https://patchwork.freedesktop.org/series/31363/
State : success

== Summary ==

Test kms_setmode:
        Subgroup basic:
                pass       -> FAIL       (shard-hsw) fdo#99912
Test perf:
        Subgroup polling:
                pass       -> FAIL       (shard-hsw) fdo#102252

fdo#99912 https://bugs.freedesktop.org/show_bug.cgi?id=99912
fdo#102252 https://bugs.freedesktop.org/show_bug.cgi?id=102252

shard-hsw        total:2429 pass:1314 dwarn:7   dfail:0   fail:25  skip:1083 time:9971s

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_5892/shards.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Tvrtko Ursulin]

On 04/10/2017 01:41, Anusha Srivatsa wrote:
> Calculate the time that GuC takes to load using
> jiffies. This information could be very useful in
> 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)
> 
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
> Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
> Cc: Oscar Mateo <oscar.mateo@intel.com>
> Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
> Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
> ---
>   drivers/gpu/drm/i915/intel_guc_loader.c | 10 +++++++++-
>   drivers/gpu/drm/i915/intel_uc.h         |  1 +
>   2 files changed, 10 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/gpu/drm/i915/intel_guc_loader.c b/drivers/gpu/drm/i915/intel_guc_loader.c
> index c9e25be..a0b562c 100644
> --- a/drivers/gpu/drm/i915/intel_guc_loader.c
> +++ b/drivers/gpu/drm/i915/intel_guc_loader.c
> @@ -199,6 +199,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private *dev_priv,
>   	struct sg_table *sg = vma->pages;
>   	u32 status, rsa[UOS_RSA_SCRATCH_MAX_COUNT];
>   	int i, ret = 0;
> +	ktime_t start_load;
>   
>   	/* where RSA signature starts */
>   	offset = guc_fw->rsa_offset;
> @@ -225,6 +226,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();
>   	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(UOS_MOVE | START_DMA));
>   
>   	/*
> @@ -237,13 +239,17 @@ static int guc_ucode_xfer_dma(struct drm_i915_private *dev_priv,
>   	 */
>   	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
>   
> +	guc_fw->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 (guc_fw->load_time > 20)
> +		DRM_NOTE("Time taken to load GuC is more than the acceptable \
> +			 threshold\n");
>   
>   	DRM_DEBUG_DRIVER("returning %d\n", ret);
>   
> @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
>   		 guc->fw.path,
>   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
>   
> +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
> +

If you move this debug to where the DRM_NOTE is you don't have to store 
the load time in the global structure. Unless there will be a reason in 
the future to have the value stored?

Also, where ever it is (global or local) unsigned int is enough since 
you picked ms as the resolution.

Regards,

Tvrtko

>   	return 0;
>   }
>   
> diff --git a/drivers/gpu/drm/i915/intel_uc.h b/drivers/gpu/drm/i915/intel_uc.h
> index 6966349..65b9674 100644
> --- a/drivers/gpu/drm/i915/intel_uc.h
> +++ b/drivers/gpu/drm/i915/intel_uc.h
> @@ -136,6 +136,7 @@ struct intel_uc_fw {
>   	uint32_t rsa_offset;
>   	uint32_t ucode_size;
>   	uint32_t ucode_offset;
> +	unsigned long long load_time;
>   };
>   
>   struct intel_guc_log {
> 
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Joonas Lahtinen]

On Wed, 2017-10-04 at 09:16 +0100, Tvrtko Ursulin wrote:
> On 04/10/2017 01:41, Anusha Srivatsa wrote:
> > Calculate the time that GuC takes to load using
> > jiffies. This information could be very useful in
> > 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)
> > 
> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
> > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> > Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
> > Cc: Oscar Mateo <oscar.mateo@intel.com>
> > Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
> > Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>

<SNIP>

> > @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
> >   		 guc->fw.path,
> >   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
> >   
> > +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
> > +
> 
> If you move this debug to where the DRM_NOTE is you don't have to store 
> the load time in the global structure. Unless there will be a reason in 
> the future to have the value stored?

We decided not to expose it through debugfs, so let's try to avoid a
variable, too.

Regards, Joonas

PS. Also, lets try to get to the habit of having the S-o-b: and Cc:s in
chronological order. Less fixing for committers when applying patches.
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Srivatsa, Anusha]

>-----Original Message-----
>From: Tvrtko Ursulin [mailto:tvrtko.ursulin@linux.intel.com]
>Sent: Wednesday, October 4, 2017 1:17 AM
>To: Srivatsa, Anusha <anusha.srivatsa@intel.com>; intel-
>gfx@lists.freedesktop.org
>Cc: Sundaresan, Sujaritha <sujaritha.sundaresan@intel.com>; Daniel Vetter
><daniel.vetter@ffwll.ch>
>Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg
>log.
>
>
>On 04/10/2017 01:41, Anusha Srivatsa wrote:
>> Calculate the time that GuC takes to load using jiffies. This
>> information could be very useful in 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)
>>
>> Cc: Chris Wilson <chris@chris-wilson.co.uk>
>> Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
>> Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
>> Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
>> Cc: Oscar Mateo <oscar.mateo@intel.com>
>> Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
>> Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
>> ---
>>   drivers/gpu/drm/i915/intel_guc_loader.c | 10 +++++++++-
>>   drivers/gpu/drm/i915/intel_uc.h         |  1 +
>>   2 files changed, 10 insertions(+), 1 deletion(-)
>>
>> diff --git a/drivers/gpu/drm/i915/intel_guc_loader.c
>> b/drivers/gpu/drm/i915/intel_guc_loader.c
>> index c9e25be..a0b562c 100644
>> --- a/drivers/gpu/drm/i915/intel_guc_loader.c
>> +++ b/drivers/gpu/drm/i915/intel_guc_loader.c
>> @@ -199,6 +199,7 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
>*dev_priv,
>>   	struct sg_table *sg = vma->pages;
>>   	u32 status, rsa[UOS_RSA_SCRATCH_MAX_COUNT];
>>   	int i, ret = 0;
>> +	ktime_t start_load;
>>
>>   	/* where RSA signature starts */
>>   	offset = guc_fw->rsa_offset;
>> @@ -225,6 +226,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();
>>   	I915_WRITE(DMA_CTRL, _MASKED_BIT_ENABLE(UOS_MOVE |
>START_DMA));
>>
>>   	/*
>> @@ -237,13 +239,17 @@ static int guc_ucode_xfer_dma(struct
>drm_i915_private *dev_priv,
>>   	 */
>>   	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
>>
>> +	guc_fw->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 (guc_fw->load_time > 20)
>> +		DRM_NOTE("Time taken to load GuC is more than the
>acceptable \
>> +			 threshold\n");
>>
>>   	DRM_DEBUG_DRIVER("returning %d\n", ret);
>>
>> @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
>>   		 guc->fw.path,
>>   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
>>
>> +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
>> +
>
>If you move this debug to where the DRM_NOTE is you don't have to store the
>load time in the global structure. Unless there will be a reason in the future to
>have the value stored?

We can have an IGT that checks the load time and fails if its greater than the threshold.... for that it could be useful to have load time this way?

>Also, where ever it is (global or local) unsigned int is enough since you picked ms
>as the resolution.

Unsigned int is a better approach. 
Will change to unsigned int Tvrtko, thanks for suggestion.

Anusha 
>Regards,
>
>Tvrtko
>
>>   	return 0;
>>   }
>>
>> diff --git a/drivers/gpu/drm/i915/intel_uc.h
>> b/drivers/gpu/drm/i915/intel_uc.h index 6966349..65b9674 100644
>> --- a/drivers/gpu/drm/i915/intel_uc.h
>> +++ b/drivers/gpu/drm/i915/intel_uc.h
>> @@ -136,6 +136,7 @@ struct intel_uc_fw {
>>   	uint32_t rsa_offset;
>>   	uint32_t ucode_size;
>>   	uint32_t ucode_offset;
>> +	unsigned long long load_time;
>>   };
>>
>>   struct intel_guc_log {
>>
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Srivatsa, Anusha]

>-----Original Message-----
>From: Joonas Lahtinen [mailto:joonas.lahtinen@linux.intel.com]
>Sent: Wednesday, October 4, 2017 5:52 AM
>To: Tvrtko Ursulin <tvrtko.ursulin@linux.intel.com>; Srivatsa, Anusha
><anusha.srivatsa@intel.com>; intel-gfx@lists.freedesktop.org
>Cc: Daniel Vetter <daniel.vetter@ffwll.ch>; Sundaresan, Sujaritha
><sujaritha.sundaresan@intel.com>
>Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg
>log.
>
>On Wed, 2017-10-04 at 09:16 +0100, Tvrtko Ursulin wrote:
>> On 04/10/2017 01:41, Anusha Srivatsa wrote:
>> > Calculate the time that GuC takes to load using jiffies. This
>> > information could be very useful in 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)
>> >
>> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
>> > Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
>> > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
>> > Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
>> > Cc: Oscar Mateo <oscar.mateo@intel.com>
>> > Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
>> > Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
>
><SNIP>
>
>> > @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
>> >   		 guc->fw.path,
>> >   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
>> >
>> > +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
>> > +
>>
>> If you move this debug to where the DRM_NOTE is you don't have to
>> store the load time in the global structure. Unless there will be a
>> reason in the future to have the value stored?
>
>We decided not to expose it through , so let's try to avoid a variable, too.
 Hi Joonas,

The order of prints will then be:
GuC firmware status: fetch SUCCESS load PENDING
GuC loaded in x ms
GuC loaded/submission enabled  firmware <path_to_firmware>_major.minor.bin version major.minor

Compared to

GuC firmware status: fetch SUCCESS load PENDING
GuC loaded/submission enabled  firmware <path_to_firmware>_platform_major.minor.bin version major.minor
GuC loaded in x ms

I felt the second one looked a better sequence, but I will change if that’s the majority.

Thanks,
Anusha
>Regards, Joonas
>
>PS. Also, lets try to get to the habit of having the S-o-b: and Cc:s in chronological
>order. Less fixing for committers when applying patches.

Will keep in mind, thanks

Anusha
>Joonas Lahtinen
>Open Source Technology Center
>Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Joonas Lahtinen]

On Fri, 2017-10-06 at 00:56 +0000, Srivatsa, Anusha wrote:
> > -----Original Message-----
> > From: Joonas Lahtinen [mailto:joonas.lahtinen@linux.intel.com]
> > Sent: Wednesday, October 4, 2017 5:52 AM
> > To: Tvrtko Ursulin <tvrtko.ursulin@linux.intel.com>; Srivatsa, Anusha
> > <anusha.srivatsa@intel.com>; intel-gfx@lists.freedesktop.org
> > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>; Sundaresan, Sujaritha
> > <sujaritha.sundaresan@intel.com>
> > Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg
> > log.
> > 
> > On Wed, 2017-10-04 at 09:16 +0100, Tvrtko Ursulin wrote:
> > > On 04/10/2017 01:41, Anusha Srivatsa wrote:
> > > > Calculate the time that GuC takes to load using jiffies. This
> > > > information could be very useful in 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)
> > > > 
> > > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > > > Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
> > > > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> > > > Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
> > > > Cc: Oscar Mateo <oscar.mateo@intel.com>
> > > > Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
> > > > Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
> > 
> > <SNIP>
> > 
> > > > @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
> > > >   		 guc->fw.path,
> > > >   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
> > > > 
> > > > +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld ms\n",guc->fw.load_time);
> > > > +
> > > 
> > > If you move this debug to where the DRM_NOTE is you don't have to
> > > store the load time in the global structure. Unless there will be a
> > > reason in the future to have the value stored?
> > 
> > We decided not to expose it through , so let's try to avoid a variable, too.
> 
>  Hi Joonas,
> 
> The order of prints will then be:
> GuC firmware status: fetch SUCCESS load PENDING
> GuC loaded in x ms
> GuC loaded/submission enabled  firmware <path_to_firmware>_major.minor.bin version major.minor

But is not this the more logical one, too? Say we would enable the
asynchronous loading of GuC firmware, and we could simultaneously
fallback to ELSP and start using the system. So there could be
considerable time between GuC being loaded and GuC submission being
enabled. So I might tie the firmware path information to the GuC loaded
message.

Also, if we have printk timestamping available, would not the
information be readable from there, just calculate delta between
firmware status changing from PENDING to LOADED? It won't hurt to
explicitly compute it for the user, of course.

Regards, Joonas

> 
> Compared to
> 
> GuC firmware status: fetch SUCCESS load PENDING
> GuC loaded/submission enabled  firmware <path_to_firmware>_platform_major.minor.bin version major.minor
> GuC loaded in x ms
> 
> I felt the second one looked a better sequence, but I will change if that’s the majority.
> 
> Thanks,
> Anusha
> > Regards, Joonas
> > 
> > PS. Also, lets try to get to the habit of having the S-o-b: and Cc:s in chronological
> > order. Less fixing for committers when applying patches.
> 
> Will keep in mind, thanks
> 
> Anusha
> > Joonas Lahtinen
> > Open Source Technology Center
> > Intel Corporation
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Srivatsa, Anusha]

>-----Original Message-----
>From: Joonas Lahtinen [mailto:joonas.lahtinen@linux.intel.com]
>Sent: Thursday, October 5, 2017 11:30 PM
>To: Srivatsa, Anusha <anusha.srivatsa@intel.com>; Tvrtko Ursulin
><tvrtko.ursulin@linux.intel.com>; intel-gfx@lists.freedesktop.org
>Cc: Daniel Vetter <daniel.vetter@ffwll.ch>; Sundaresan, Sujaritha
><sujaritha.sundaresan@intel.com>
>Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to dmesg
>log.
>
>On Fri, 2017-10-06 at 00:56 +0000, Srivatsa, Anusha wrote:
>> > -----Original Message-----
>> > From: Joonas Lahtinen [mailto:joonas.lahtinen@linux.intel.com]
>> > Sent: Wednesday, October 4, 2017 5:52 AM
>> > To: Tvrtko Ursulin <tvrtko.ursulin@linux.intel.com>; Srivatsa,
>> > Anusha <anusha.srivatsa@intel.com>; intel-gfx@lists.freedesktop.org
>> > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>; Sundaresan, Sujaritha
>> > <sujaritha.sundaresan@intel.com>
>> > Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time
>> > to dmesg log.
>> >
>> > On Wed, 2017-10-04 at 09:16 +0100, Tvrtko Ursulin wrote:
>> > > On 04/10/2017 01:41, Anusha Srivatsa wrote:
>> > > > Calculate the time that GuC takes to load using jiffies. This
>> > > > information could be very useful in 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)
>> > > >
>> > > > Cc: Chris Wilson <chris@chris-wilson.co.uk>
>> > > > Cc: Tvrtko ursulin <tvrtko.ursulin@intel.com>
>> > > > Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
>> > > > Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
>> > > > Cc: Oscar Mateo <oscar.mateo@intel.com>
>> > > > Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
>> > > > Signed-off-by: Anusha Srivatsa <anusha.srivatsa@intel.com>
>> >
>> > <SNIP>
>> >
>> > > > @@ -373,6 +379,8 @@ int intel_guc_init_hw(struct intel_guc *guc)
>> > > >   		 guc->fw.path,
>> > > >   		 guc->fw.major_ver_found, guc->fw.minor_ver_found);
>> > > >
>> > > > +	DRM_DEBUG_DRIVER("GuC is loaded in: %lld
>> > > > +ms\n",guc->fw.load_time);
>> > > > +
>> > >
>> > > If you move this debug to where the DRM_NOTE is you don't have to
>> > > store the load time in the global structure. Unless there will be
>> > > a reason in the future to have the value stored?
>> >
>> > We decided not to expose it through , so let's try to avoid a variable, too.
>>
>>  Hi Joonas,
>>
>> The order of prints will then be:
>> GuC firmware status: fetch SUCCESS load PENDING GuC loaded in x ms GuC
>> loaded/submission enabled  firmware <path_to_firmware>_major.minor.bin
>> version major.minor
>
>But is not this the more logical one, too? Say we would enable the asynchronous
>loading of GuC firmware, and we could simultaneously fallback to ELSP and start
>using the system. So there could be considerable time between GuC being loaded
>and GuC submission being enabled. So I might tie the firmware path information
>to the GuC loaded message.
>
>Also, if we have printk timestamping available, would not the information be
>readable from there, just calculate delta between firmware status changing from
>PENDING to LOADED? It won't hurt to explicitly compute it for the user, of
>course.


Agreed. Will remove the variable altogether.

Thanks a lot Joonas.
Anusha

>Regards, Joonas
>
>>
>> Compared to
>>
>> GuC firmware status: fetch SUCCESS load PENDING GuC loaded/submission
>> enabled  firmware <path_to_firmware>_platform_major.minor.bin version
>> major.minor GuC loaded in x ms
>>
>> I felt the second one looked a better sequence, but I will change if that’s the
>majority.
>>
>> Thanks,
>> Anusha
>> > Regards, Joonas
>> >
>> > PS. Also, lets try to get to the habit of having the S-o-b: and Cc:s
>> > in chronological order. Less fixing for committers when applying patches.
>>
>> Will keep in mind, thanks
>>
>> Anusha
>> > Joonas Lahtinen
>> > Open Source Technology Center
>> > Intel Corporation
>--
>Joonas Lahtinen
>Open Source Technology Center
>Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Anusha Srivatsa]

Calculate the time that GuC takes to load using
jiffies. This information could be very useful in
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@chris-wilson.co.uk>
Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
Cc: Oscar Mateo <oscar.mateo@intel.com>
Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Signed-off-by: Anusha Srivatsa <anusha.srivatsa@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;
+	ktime_t start_load;
 
 	/* 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();
 	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");
+	else
+		DRM_DEBUG_DRIVER("GuC loaded in %d ms\n", load_time);
 
 	DRM_DEBUG_DRIVER("returning %d\n", ret);
 
-- 
2.7.4

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Michal Wajdeczko]

On Wed, 01 Nov 2017 01:11:20 +0100, Anusha Srivatsa  
<anusha.srivatsa@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.

> 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@chris-wilson.co.uk>
> Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
> Cc: Oscar Mateo <oscar.mateo@intel.com>
> Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Signed-off-by: Anusha Srivatsa <anusha.srivatsa@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 ?

> 	/* 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..

>  	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.

> 	DRM_DEBUG_DRIVER("returning %d\n", ret);
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Chris Wilson]

Quoting Michal Wajdeczko (2017-11-01 13:14:33)
> On Wed, 01 Nov 2017 01:11:20 +0100, Anusha Srivatsa  
> > @@ -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

The more important question is why are we telling the user this at all;
a significant but normal condition. What do we expect them to do? It
doesn't impair any functionality of the driver, it just took longer than
you expected -- which may be simply because the system was doing
something else and we slept for longer.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[David Weinehall]

On Tue, Oct 31, 2017 at 05:11:20PM -0700, Anusha Srivatsa wrote:
> Calculate the time that GuC takes to load using
> jiffies. This information could be very useful in
> 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)

From my point of view (measuring suspend/resume times) knowing
how much time is spent loading GuC & HuC is really useful,
so it's definitely useful information.


Kind regards, David Weinehall
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Chris Wilson]

Quoting David Weinehall (2017-11-01 13:38:48)
> On Tue, Oct 31, 2017 at 05:11:20PM -0700, Anusha Srivatsa wrote:
> > Calculate the time that GuC takes to load using
> > jiffies. This information could be very useful in
> > 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)
> 
> From my point of view (measuring suspend/resume times) knowing
> how much time is spent loading GuC & HuC is really useful,
> so it's definitely useful information.

This information could be gleaned from ftrace...
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [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@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@chris-wilson.co.uk>
> >Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
> >Cc: Michal Wajdeczko <michal.wajdeczko@intel.com>
> >Cc: Oscar Mateo <oscar.mateo@intel.com>
> >Cc: Sujaritha Sundaresan <sujaritha.sundaresan@intel.com>
> >Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> >Signed-off-by: Anusha Srivatsa <anusha.srivatsa@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
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Anusha Srivatsa]

On Wed, Nov 01, 2017 at 01:24:15PM +0000, Chris Wilson wrote:
> Quoting Michal Wajdeczko (2017-11-01 13:14:33)
> > On Wed, 01 Nov 2017 01:11:20 +0100, Anusha Srivatsa  
> > > @@ -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
> 
> The more important question is why are we telling the user this at all;
> a significant but normal condition. What do we expect them to do? It
> doesn't impair any functionality of the driver, it just took longer than
> you expected -- which may be simply because the system was doing
> something else and we slept for longer.

Chris, I am inclining to have this info more for us than the user. It is more of
a debug print to give us some data. We can see if firmware takes peculiarly
long time to load. We know its normal to be within 20ms range. So, alert
if it takes longer than that...

> -Chris

-- 
Anusha Srivatsa
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

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

[Chris Wilson]

Quoting Anusha Srivatsa (2017-11-02 20:28:10)
> On Wed, Nov 01, 2017 at 01:24:15PM +0000, Chris Wilson wrote:
> > Quoting Michal Wajdeczko (2017-11-01 13:14:33)
> > > On Wed, 01 Nov 2017 01:11:20 +0100, Anusha Srivatsa  
> > > > @@ -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
> > 
> > The more important question is why are we telling the user this at all;
> > a significant but normal condition. What do we expect them to do? It
> > doesn't impair any functionality of the driver, it just took longer than
> > you expected -- which may be simply because the system was doing
> > something else and we slept for longer.
> 
> Chris, I am inclining to have this info more for us than the user. It is more of
> a debug print to give us some data. We can see if firmware takes peculiarly
> long time to load. We know its normal to be within 20ms range. So, alert
> if it takes longer than that...

Sure, but the impact is that this is a user facing message, even marked
as a significant message. We are quite capable of parsing debug
messages; even capable of setting up ftrace to extract this timing info
without adding the dmesg in the first place...
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx