Re: [Intel-gfx] [PATCH 3/7] drm/i915/guc: Add GuC <-> kernel time stamp translation information

[John Harrison <john.c.harrison@intel.com>]

On 8/19/2022 03:45, Jani Nikula wrote:
> On Wed, 27 Jul 2022, John.C.Harrison@Intel.com wrote:
>> From: John Harrison <John.C.Harrison@Intel.com>
>>
>> It is useful to be able to match GuC events to kernel events when
>> looking at the GuC log. That requires being able to convert GuC
>> timestamps to kernel time. So, when dumping error captures and/or GuC
>> logs, include a stamp in both time zones plus the clock frequency.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
>> ---
>>   drivers/gpu/drm/i915/gt/intel_gt_regs.h    |  2 ++
>>   drivers/gpu/drm/i915/gt/uc/intel_guc.c     | 19 +++++++++++++++++++
>>   drivers/gpu/drm/i915/gt/uc/intel_guc.h     |  2 ++
>>   drivers/gpu/drm/i915/gt/uc/intel_guc_log.c |  2 ++
>>   drivers/gpu/drm/i915/i915_gpu_error.c      | 12 ++++++++++++
>>   drivers/gpu/drm/i915/i915_gpu_error.h      |  3 +++
>>   6 files changed, 40 insertions(+)
>>
>> diff --git a/drivers/gpu/drm/i915/gt/intel_gt_regs.h b/drivers/gpu/drm/i915/gt/intel_gt_regs.h
>> index 60d6eb5f245b7..fc7979bd91db5 100644
>> --- a/drivers/gpu/drm/i915/gt/intel_gt_regs.h
>> +++ b/drivers/gpu/drm/i915/gt/intel_gt_regs.h
>> @@ -1007,6 +1007,8 @@
>>   #define   GEN11_LSN_UNSLCVC_GAFS_HALF_CL2_MAXALLOC	(1 << 9)
>>   #define   GEN11_LSN_UNSLCVC_GAFS_HALF_SF_MAXALLOC	(1 << 7)
>>   
>> +#define GUCPMTIMESTAMP				_MMIO(0xc3e8)
>> +
>>   #define __GEN9_RCS0_MOCS0			0xc800
>>   #define GEN9_GFX_MOCS(i)			_MMIO(__GEN9_RCS0_MOCS0 + (i) * 4)
>>   #define __GEN9_VCS0_MOCS0			0xc900
>> diff --git a/drivers/gpu/drm/i915/gt/uc/intel_guc.c b/drivers/gpu/drm/i915/gt/uc/intel_guc.c
>> index 2706a8c650900..ab4aacc516aa4 100644
>> --- a/drivers/gpu/drm/i915/gt/uc/intel_guc.c
>> +++ b/drivers/gpu/drm/i915/gt/uc/intel_guc.c
>> @@ -389,6 +389,25 @@ void intel_guc_write_params(struct intel_guc *guc)
>>   	intel_uncore_forcewake_put(uncore, FORCEWAKE_GT);
>>   }
>>   
>> +void intel_guc_dump_time_info(struct intel_guc *guc, struct drm_printer *p)
>> +{
>> +	struct intel_gt *gt = guc_to_gt(guc);
>> +	intel_wakeref_t wakeref;
>> +	u32 stamp = 0;
>> +	u64 ktime;
>> +
>> +	intel_device_info_print_runtime(RUNTIME_INFO(gt->i915), p);
> Why does this function print runtime info alone? Seems kind of random,
> considering what intel_device_info_print_runtime() actually
> prints. Should it print both device info and runtime info, or nothing at
> all?
Hmm. That was added specifically to print the rawclk value (and only for 
the rawclk value) because that was the frequency that the GuC time stamp 
register ticks at. I think we later worked out that the CS frequency was 
more correct. Hence printing gt->clock_frequency lower down. I guess I 
forgot to go back and remove the rawclk print, though.

So yeah, it can be removed.

John.


>
> This conflicts with [1] and I don't know what to do about it. The first
> instinct is to just remove it.
>
> BR,
> Jani.
>
>
> [1] https://patchwork.freedesktop.org/patch/msgid/4be86d7a0737b2c49eee460d29d42843418536fe.1660137416.git.jani.nikula@intel.com
>
>> +
>> +	with_intel_runtime_pm(&gt->i915->runtime_pm, wakeref)
>> +		stamp = intel_uncore_read(gt->uncore, GUCPMTIMESTAMP);
>> +	ktime = ktime_get_boottime_ns();
>> +
>> +	drm_printf(p, "Kernel timestamp: 0x%08llX [%llu]\n", ktime, ktime);
>> +	drm_printf(p, "GuC timestamp: 0x%08X [%u]\n", stamp, stamp);
>> +	drm_printf(p, "CS timestamp frequency: %u Hz, %u ns\n",
>> +		   gt->clock_frequency, gt->clock_period_ns);
>> +}
>> +
>>   int intel_guc_init(struct intel_guc *guc)
>>   {
>>   	struct intel_gt *gt = guc_to_gt(guc);
>> diff --git a/drivers/gpu/drm/i915/gt/uc/intel_guc.h b/drivers/gpu/drm/i915/gt/uc/intel_guc.h
>> index a7acffbf15d1f..804133df1ac9b 100644
>> --- a/drivers/gpu/drm/i915/gt/uc/intel_guc.h
>> +++ b/drivers/gpu/drm/i915/gt/uc/intel_guc.h
>> @@ -464,4 +464,6 @@ void intel_guc_load_status(struct intel_guc *guc, struct drm_printer *p);
>>   
>>   void intel_guc_write_barrier(struct intel_guc *guc);
>>   
>> +void intel_guc_dump_time_info(struct intel_guc *guc, struct drm_printer *p);
>> +
>>   #endif
>> diff --git a/drivers/gpu/drm/i915/gt/uc/intel_guc_log.c b/drivers/gpu/drm/i915/gt/uc/intel_guc_log.c
>> index 991d4a02248dc..07d31ae32f765 100644
>> --- a/drivers/gpu/drm/i915/gt/uc/intel_guc_log.c
>> +++ b/drivers/gpu/drm/i915/gt/uc/intel_guc_log.c
>> @@ -764,6 +764,8 @@ int intel_guc_log_dump(struct intel_guc_log *log, struct drm_printer *p,
>>   	if (!obj)
>>   		return 0;
>>   
>> +	intel_guc_dump_time_info(guc, p);
>> +
>>   	map = i915_gem_object_pin_map_unlocked(obj, I915_MAP_WC);
>>   	if (IS_ERR(map)) {
>>   		DRM_DEBUG("Failed to pin object\n");
>> diff --git a/drivers/gpu/drm/i915/i915_gpu_error.c b/drivers/gpu/drm/i915/i915_gpu_error.c
>> index 32e92651ef7c2..addba75252343 100644
>> --- a/drivers/gpu/drm/i915/i915_gpu_error.c
>> +++ b/drivers/gpu/drm/i915/i915_gpu_error.c
>> @@ -678,6 +678,7 @@ static void err_print_uc(struct drm_i915_error_state_buf *m,
>>   
>>   	intel_uc_fw_dump(&error_uc->guc_fw, &p);
>>   	intel_uc_fw_dump(&error_uc->huc_fw, &p);
>> +	err_printf(m, "GuC timestamp: 0x%08x\n", error_uc->timestamp);
>>   	intel_gpu_error_print_vma(m, NULL, error_uc->guc_log);
>>   }
>>   
>> @@ -720,6 +721,8 @@ static void err_print_gt_global_nonguc(struct drm_i915_error_state_buf *m,
>>   	int i;
>>   
>>   	err_printf(m, "GT awake: %s\n", str_yes_no(gt->awake));
>> +	err_printf(m, "CS timestamp frequency: %u Hz, %d ns\n",
>> +		   gt->clock_frequency, gt->clock_period_ns);
>>   	err_printf(m, "EIR: 0x%08x\n", gt->eir);
>>   	err_printf(m, "PGTBL_ER: 0x%08x\n", gt->pgtbl_er);
>>   
>> @@ -1675,6 +1678,13 @@ gt_record_uc(struct intel_gt_coredump *gt,
>>   	 */
>>   	error_uc->guc_fw.path = kstrdup(uc->guc.fw.path, ALLOW_FAIL);
>>   	error_uc->huc_fw.path = kstrdup(uc->huc.fw.path, ALLOW_FAIL);
>> +
>> +	/*
>> +	 * Save the GuC log and include a timestamp reference for converting the
>> +	 * log times to system times (in conjunction with the error->boottime and
>> +	 * gt->clock_frequency fields saved elsewhere).
>> +	 */
>> +	error_uc->timestamp = intel_uncore_read(gt->_gt->uncore, GUCPMTIMESTAMP);
>>   	error_uc->guc_log = create_vma_coredump(gt->_gt, uc->guc.log.vma,
>>   						"GuC log buffer", compress);
>>   
>> @@ -1833,6 +1843,8 @@ static void gt_record_global_regs(struct intel_gt_coredump *gt)
>>   static void gt_record_info(struct intel_gt_coredump *gt)
>>   {
>>   	memcpy(&gt->info, &gt->_gt->info, sizeof(struct intel_gt_info));
>> +	gt->clock_frequency = gt->_gt->clock_frequency;
>> +	gt->clock_period_ns = gt->_gt->clock_period_ns;
>>   }
>>   
>>   /*
>> diff --git a/drivers/gpu/drm/i915/i915_gpu_error.h b/drivers/gpu/drm/i915/i915_gpu_error.h
>> index 55a143b92d10e..d8a8b3d529e09 100644
>> --- a/drivers/gpu/drm/i915/i915_gpu_error.h
>> +++ b/drivers/gpu/drm/i915/i915_gpu_error.h
>> @@ -150,6 +150,8 @@ struct intel_gt_coredump {
>>   	u32 gtt_cache;
>>   	u32 aux_err; /* gen12 */
>>   	u32 gam_done; /* gen12 */
>> +	u32 clock_frequency;
>> +	u32 clock_period_ns;
>>   
>>   	/* Display related */
>>   	u32 derrmr;
>> @@ -164,6 +166,7 @@ struct intel_gt_coredump {
>>   		struct intel_uc_fw guc_fw;
>>   		struct intel_uc_fw huc_fw;
>>   		struct i915_vma_coredump *guc_log;
>> +		u32 timestamp;
>>   		bool is_guc_capture;
>>   	} *uc;