[PATCH v3 2/2] drm/xe/guc: Improve robustness of GuC log dumping to dmesg

[John Harrison]

On 5/13/2024 08:21, Dong, Zhanjun wrote:
> On 2024-05-08 6:49 p.m., John.C.Harrison at Intel.com wrote:
>> From: John Harrison <John.C.Harrison at Intel.com>
> ...
>> diff --git a/drivers/gpu/drm/xe/regs/xe_guc_regs.h 
>> b/drivers/gpu/drm/xe/regs/xe_guc_regs.h
>> index 11682e675e0f..45fb3707fabe 100644
>> --- a/drivers/gpu/drm/xe/regs/xe_guc_regs.h
>> +++ b/drivers/gpu/drm/xe/regs/xe_guc_regs.h
> ...
>> @@ -49,32 +57,79 @@ static size_t guc_log_size(void)
>>           CAPTURE_BUFFER_SIZE;
>>   }
>>   +#define BYTES_PER_WORD        sizeof(u32)
>> +#define WORDS_PER_DUMP        8
>> +#define DUMPS_PER_LINE        4
>> +#define LINES_PER_READ        4
>> +#define WORDS_PER_READ        (WORDS_PER_DUMP * DUMPS_PER_LINE * 
>> LINES_PER_READ)
>> +
>>   void xe_guc_log_print(struct xe_guc_log *log, struct drm_printer *p)
>>   {
>> +    static int g_count;
>> +    struct xe_gt *gt = log_to_gt(log);
>> +    struct xe_guc *guc = log_to_guc(log);
>> +    struct xe_uc_fw_version *ver_f = 
>> &guc->fw.versions.found[XE_UC_FW_VER_RELEASE];
>> +    struct xe_uc_fw_version *ver_w = &guc->fw.versions.wanted;
>>       struct xe_device *xe = log_to_xe(log);
>>       size_t size;
>> -    int i, j;
>> +    char line_buff[DUMPS_PER_LINE * WORDS_PER_DUMP * 9 + 1];
>> +    int l_count = g_count++;
>> +    int line = 0;
>> +    int i, j, k;
>> +    u64 ktime;
>> +    u32 stamp;
>>         xe_assert(xe, log->bo);
>>         size = log->bo->size;
>>   -#define DW_PER_READ        128
>> -    xe_assert(xe, !(size % (DW_PER_READ * sizeof(u32))));
>> -    for (i = 0; i < size / sizeof(u32); i += DW_PER_READ) {
>> -        u32 read[DW_PER_READ];
>> -
>> -        xe_map_memcpy_from(xe, read, &log->bo->vmap, i * sizeof(u32),
>> -                   DW_PER_READ * sizeof(u32));
>> -#define DW_PER_PRINT        4
>> -        for (j = 0; j < DW_PER_READ / DW_PER_PRINT; ++j) {
>> -            u32 *print = read + j * DW_PER_PRINT;
>> -
>> -            drm_printf(p, "0x%08x 0x%08x 0x%08x 0x%08x\n",
>> -                   *(print + 0), *(print + 1),
>> -                   *(print + 2), *(print + 3));
>> +    drm_printf(p, "[Capture/%d.%d] Dumping GuC log for %ps...\n",
>> +           l_count, line++, __builtin_return_address(0));
>> +
>> +    drm_printf(p, "[Capture/%d.%d] GuC version %u.%u.%u (wanted 
>> %u.%u.%u)\n",
>> +           l_count, line++,
>> +           ver_f->major, ver_f->minor, ver_f->patch,
>> +           ver_w->major, ver_w->minor, ver_w->patch);
>> +    drm_printf(p, "[Capture/%d.%d] GuC firmware: %s\n", l_count, 
>> line++, guc->fw.path);
>> +
>> +    ktime = ktime_get_boottime_ns();
>> +    drm_printf(p, "[Capture/%d.%d] Kernel timestamp: 0x%08llX 
>> [%llu]\n",
>> +           l_count, line++, ktime, ktime);
>> +
>> +    stamp = xe_mmio_read32(gt, GUC_PMTIMESTAMP);
>> +    drm_printf(p, "[Capture/%d.%d] GuC timestamp: 0x%08X [%u]\n",
>> +           l_count, line++, stamp, stamp);
>> +
>> +    drm_printf(p, "[Capture/%d.%d] CS timestamp frequency: %u Hz\n",
>> +           l_count, line++, gt->info.reference_clock);
>> +
>> +    xe_assert(xe, !(size % (WORDS_PER_READ * BYTES_PER_WORD)));
> Could we have a "start tag" print here? Make it easier for parser to 
> find dump start.
> Although we have the "[Capture/%d.%d] CS timestamp frequency:" ahead, 
> which might be an "in-explicit start tag", but if something added 
> after it in the future, this "in-explicit start tag" will causes 
> parser broken.
> A simple "[Capture/%d.%d] Dump start\n" liked tag is more easy to 
> maintain.
There is a start tag - "Capture/X.0 Dumping GuC log for...".

The parser needs all the output, not just the hex dump stream. And it 
will already cope with extra meta data being added in the future.


>
>> +    for (i = 0; i < size / BYTES_PER_WORD; i += WORDS_PER_READ) {
>> +        u32 read[WORDS_PER_READ];
>> +
>> +        xe_map_memcpy_from(xe, read, &log->bo->vmap, i * 
>> BYTES_PER_WORD,
>> +                   WORDS_PER_READ * BYTES_PER_WORD);
>> +
>> +        for (j = 0; j < WORDS_PER_READ; ) {
>> +            u32 done = 0;
>> +
>> +            for (k = 0; k < DUMPS_PER_LINE; k++) {
>> +                line_buff[done++] = ' ';
>> +                done += hex_dump_to_buffer(read + j,
>> +                               sizeof(*read) * (WORDS_PER_READ - j),
>> +                               WORDS_PER_DUMP * BYTES_PER_WORD,
>> +                               BYTES_PER_WORD,
>> +                               line_buff + done,
>> +                               sizeof(line_buff) - done,
>> +                               false);
>> +                j += WORDS_PER_DUMP;
>> +            }
>> +
>> +            drm_printf(p, "[Capture/%d.%d]%s\n", l_count, line++, 
>> line_buff);
>>           }
>>       }
>> +
>> +    drm_printf(p, "[Capture/%d.%d] Done.\n", l_count, line++);
> "End tag"
"Done" is an end tag. And it is more friendly to a human reader while 
makes no difference to a machine reader.

John.

>>   }
>>     int xe_guc_log_init(struct xe_guc_log *log)