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

John Harrison john.c.harrison at intel.com
Tue May 14 18:18:36 UTC 2024


On 5/14/2024 10:32, Dong, Zhanjun wrote:
> 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
But it is not necessary. There is already sufficient information for a 
parser to extract everything it needs.


>
> 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.
But that is adding unnecessary complication for no particular advantage.

>
> 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.
But you only get large chunks of zeros if the log has not been filled 
yet. Once it has been filled, the savings would be minimal. Which 
basically means you only get a benefit if saving the log immediately 
after loading the driver. And if you are specifically trying to debug a 
module load issue, then just use a smaller log buffer size in the first 
place.

For actual genuine savings in real world usage, what we need to add is 
compression as we had in i915. That would add significant size 
reduction. But it is more effort to add in the support.

John.

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



More information about the Intel-xe mailing list