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

John Harrison
2022-08-19T21:03:16Z

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;