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

[Tvrtko Ursulin]

On 07/09/2017 18:07, Srivatsa, Anusha wrote:
>> -----Original Message-----
>> From: Tvrtko Ursulin [mailto:tvrtko.ursulin at linux.intel.com]
>> Sent: Thursday, September 7, 2017 1:49 AM
>> To: Srivatsa, Anusha <anusha.srivatsa at intel.com>; intel-
>> gfx at lists.freedesktop.org
>> Cc: Sundaresan, Sujaritha <sujaritha.sundaresan at intel.com>
>> Subject: Re: [Intel-gfx] [PATCH 1/2] drm/i915/guc: Add GuC Load time to debugfs
>>
>>
>> On 07/09/2017 01:37, Anusha Srivatsa wrote:
>>> Calculate the time that GuC takes to load.
>>> This information could be very useful in determining if GuC is taking
>>> unreasonably long time to load in a certain platforms.
>>
>> Do we need this in debugfs or a DRM_NOTE or something would be sufficient if
>> the load time is above certain threshold?
> 
> The intention was to have debug related info in a debugfs. DRM_NOTE will also be useful, we can do both. The load time can be as an entry in debugfs and if it's beyond a threshold - 20ms I assume, we can have a DRM_NOTE.
> Does that sound good?

I'd rather avoid adding code (for debugfs) if the only purpose is to 
detect when the load takes too long. But maybe there is a different 
reason to have it, which I am not aware off so I don't know.

>> Also, what are the typical times here? Are jiffies precise enough? Could be only
>> 10ms granularity on some kernels.
> 
> Usually guc load times are around 8ms to 10ms....
> That’s a very good point. I thought jiffies are a good approach for this purpose, but if there is a better or more accurate way, I will be happy to go that direction.

ktime_get(_ns) I think.

Regards,

Tvrtko

>> Depending on the above, more or less applicable comments below:
>>
>>> 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.
>>>
>>> Cc: Sujaritha Sundaresan <sujaritha.sundaresan at intel.com>
>>> Cc: Oscar Mateo <oscar.mateo at intel.com>
>>> Cc: Michal Wajdeczko <michal.wajdeczko at intel.com>
>>> Signed-off-by: Anusha Srivatsa <anusha.srivatsa at intel.com>
>>> ---
>>>    drivers/gpu/drm/i915/i915_debugfs.c     | 3 +++
>>>    drivers/gpu/drm/i915/intel_guc_loader.c | 8 ++++++++
>>>    drivers/gpu/drm/i915/intel_uc.h         | 1 +
>>>    3 files changed, 12 insertions(+)
>>>
>>> diff --git a/drivers/gpu/drm/i915/i915_debugfs.c
>>> b/drivers/gpu/drm/i915/i915_debugfs.c
>>> index 48572b157222..e0b99dbc6608 100644
>>> --- a/drivers/gpu/drm/i915/i915_debugfs.c
>>> +++ b/drivers/gpu/drm/i915/i915_debugfs.c
>>> @@ -2379,6 +2379,9 @@ static int i915_guc_load_status_info(struct seq_file
>> *m, void *data)
>>>    		guc_fw->major_ver_wanted, guc_fw->minor_ver_wanted);
>>>    	seq_printf(m, "\tversion found: %d.%d\n",
>>>    		guc_fw->major_ver_found, guc_fw->minor_ver_found);
>>> +	seq_printf(m, "\tGuC Load time is %lu ms\n",
>>> +		   jiffies_to_msecs(guc_fw->guc_load_time));
>>
>> OCD: "GuC load time: %lums" to make it more consistent with the other entries
>> here?
>>
>>> +
>>>    	seq_printf(m, "\theader: offset is %d; size = %d\n",
>>>    		guc_fw->header_offset, guc_fw->header_size);
>>>    	seq_printf(m, "\tuCode: offset is %d; size = %d\n", diff --git
>>> a/drivers/gpu/drm/i915/intel_guc_loader.c
>>> b/drivers/gpu/drm/i915/intel_guc_loader.c
>>> index 8b0ae7fce7f2..da917f84c471 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, guc_finish_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,9 @@ static int guc_ucode_xfer_dma(struct drm_i915_private
>> *dev_priv,
>>>    	 */
>>>    	ret = wait_for(guc_ucode_response(dev_priv, &status), 100);
>>>
>>> +	guc_finish_load = jiffies;
>>> +	guc_fw->guc_load_time = guc_finish_load - guc_start_load;
>>
>> Strictly speaking you don't need the guc_finish_load local.
>>
>>> +
>>>    	DRM_DEBUG_DRIVER("DMA status 0x%x, GuC status 0x%x\n",
>>>    			I915_READ(DMA_CTRL), status);
>>>
>>> @@ -372,6 +377,9 @@ 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("Time taken to load GuC is %lu\n",
>>> +			 guc->fw.guc_load_time);
>>> +
>>>    	return 0;
>>>    }
>>>
>>> diff --git a/drivers/gpu/drm/i915/intel_uc.h
>>> b/drivers/gpu/drm/i915/intel_uc.h index 22ae52b17b0f..52aa05d13863
>>> 100644
>>> --- a/drivers/gpu/drm/i915/intel_uc.h
>>> +++ b/drivers/gpu/drm/i915/intel_uc.h
>>> @@ -154,6 +154,7 @@ struct intel_uc_fw {
>>>    	uint32_t rsa_offset;
>>>    	uint32_t ucode_size;
>>>    	uint32_t ucode_offset;
>>> +	unsigned long guc_load_time;
>>
>> Looks wrong to add guc_ (and later huc_) prefixed members in the common
>> struct since both intel_guc and intel_huc encapsulate it. If you just had a single
>> field and called it load_time, wouldn't you get separate copies for guc and huc
>> automatically?
> 
> That’s a good point.
> Neater approach too. Thanks Tvrtko!
> 
> Anusha
>> Regards,
>>
>> Tvrtko
>>
>>>    };
>>>
>>>    struct intel_guc_log {
>>>