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

[John Harrison <john.c.harrison@xxxxxxxxx>]

On 8/19/2022 03:45, Jani Nikula wrote:
> 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?
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@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;