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

[Dong, Zhanjun]

On 2024-05-13 1:13 p.m., John Harrison wrote:
> 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.
Oh, I'm looking for hex dump start tag, like:
"[Capture/%d.%d] Dumpping %X bytes\n"
Which contains total size info

And one more option below
> 
> 
>>
>>> +    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);
The format of
[Capture/%d.%d]%s\n", l_count, line++
l_count sounds like an ID for this dump
line is current line of this dump
For hex dump, could we have offset/total size info? Which could be used 
as an option to indicate dump start, where offset always starts with 0.

for example:
drm_printf(p, "[Capture/%d.%d]%x: %s\n", l_count, line++, j, line_buff);

Then parser could have "\[Capture/[0-9]+\.[0-9]+\]0: " to looking for 
dump start.

Another benefit is: for the whole line is all zero, we can simply skip 
it to save output size. Which is relatively easy to implement in parser 
as well. Well, for this case, the total size info is needed.

>>>           }
>>>       }
>>> +
>>> +    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)
>