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

[Jani Nikula <jani.nikula@xxxxxxxxxxxxxxx>]

On Wed, 27 Jul 2022, John.C.Harrison@xxxxxxxxx wrote:
> From: John Harrison <John.C.Harrison@xxxxxxxxx>
>
> 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@xxxxxxxxx>
> ---
>  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?

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@xxxxxxxxx

> +
> +	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;

-- 
Jani Nikula, Intel Open Source Graphics Center