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

[John Harrison <john.c.harrison@intel.com>]

On 4/30/2024 16:44, Matthew Brost wrote:
> On Tue, Apr 30, 2024 at 04:34:36PM -0700, John.C.Harrison@Intel.com wrote:
>> From: John Harrison <John.C.Harrison@Intel.com>
>>
>> There is a debug mechanism for dumping the GuC log as an ASCII hex
>> stream via dmesg. This is extremely useful for situations where it is
>> not possibe to query the log from debugfs (self tests, bugs that cause
>> the driver to fail to load, system hangs, etc.). However, dumping via
>> dmesg is not the most reliable. The dmesg buffer is limited in size,
>> can be rate limited and a simple hex stream is hard to parse by tools.
>>
>> So add extra information to the dump to make it more robust and
>> parsable. This includes adding start and end tags to delimit the dump,
>> using longer lines to reduce the per line overhead, adding a rolling
>> count to check for missing lines and interleaved concurrent dumps and
>> adding other important information such as the GuC version number and
>> timestamp offset.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
>> ---
>>   drivers/gpu/drm/xe/regs/xe_guc_regs.h |  1 +
>>   drivers/gpu/drm/xe/xe_guc_log.c       | 78 ++++++++++++++++++++++-----
>>   2 files changed, 66 insertions(+), 13 deletions(-)
>>
>> 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
>> @@ -82,6 +82,7 @@
>>   #define   HUC_LOADING_AGENT_GUC			REG_BIT(1)
>>   #define   GUC_WOPCM_OFFSET_VALID		REG_BIT(0)
>>   #define GUC_MAX_IDLE_COUNT			XE_REG(0xc3e4)
>> +#define GUC_PMTIMESTAMP				XE_REG(0xc3e8)
>>   
>>   #define GUC_SEND_INTERRUPT			XE_REG(0xc4c8)
>>   #define   GUC_SEND_TRIGGER			REG_BIT(0)
>> diff --git a/drivers/gpu/drm/xe/xe_guc_log.c b/drivers/gpu/drm/xe/xe_guc_log.c
>> index a37ee3419428..ea269efd9c21 100644
>> --- a/drivers/gpu/drm/xe/xe_guc_log.c
>> +++ b/drivers/gpu/drm/xe/xe_guc_log.c
>> @@ -7,10 +7,19 @@
>>   
>>   #include <drm/drm_managed.h>
>>   
>> +#include "regs/xe_guc_regs.h"
>>   #include "xe_bo.h"
>>   #include "xe_gt.h"
>>   #include "xe_map.h"
>> +#include "xe_mmio.h"
>>   #include "xe_module.h"
>> +#include "xe_pm.h"
>> +
>> +static struct xe_guc *
>> +log_to_guc(struct xe_guc_log *log)
>> +{
>> +	return container_of(log, struct xe_guc, log);
>> +}
>>   
>>   static struct xe_gt *
>>   log_to_gt(struct xe_guc_log *log)
>> @@ -49,32 +58,75 @@ 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_uc_fw_version *ver = &log_to_guc(log)->fw.versions.found[XE_UC_FW_VER_RELEASE];
>>   	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];
>> +	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\n",
>> +		   l_count, line++, ver->major, ver->minor, ver->patch);
>> +
>> +	ktime = ktime_get_boottime_ns();
>> +	drm_printf(p, "[Capture/%d.%d] Kernel timestamp: 0x%08llX [%llu]\n",
>> +		   l_count, line++, ktime, ktime);
>>   
>> -		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;
>> +	xe_pm_runtime_get(xe);
>> +	stamp = xe_mmio_read32(log_to_gt(log), GUC_PMTIMESTAMP);
>> +	xe_pm_runtime_put(xe);
> Just a quick drive by comment, fine grained PM control like this frowned
> upon in Xe or maybe even not allowed. Rodrigo / Matt Auld would would be
> the experts here.
>
> Presumbly all the callers should already have a PM ref.
It wasn't clear that this would be the case.

And the whole pm_runtime interface is exceedingly confusing. _get calls 
get_noresume then does a task ownership test and calls resume, 
_resume_and_get does exactly the same but in a different order, plus 
there is _get_if_active and _get_if_in_use. Plus _get_ioctl which is for 
calling *before* making an IOCTL (where an IOCTL is a call from the user 
into the kernel!). And none of these have any documentation beyond a 
single sentence that is simply re-writing the function name with with 
prepositions added.

So I am unsurprised if this is not the correct way to do it but I have 
no idea what would be the correct method.

>
>> +	drm_printf(p, "[Capture/%d.%d] GuC timestamp: 0x%08X [%u]\n",
>> +		   l_count, line++, stamp, stamp);
>>   
>> -			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] CS timestamp frequency: %u Hz\n",
>> +		   l_count, line++, log_to_gt(log)->info.reference_clock);
>> +
>> +	xe_assert(xe, !(size % (WORDS_PER_READ * BYTES_PER_WORD)));
>> +	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);
>> +
> Also I think the above pukes without a PM ref too.
If that is the case, should there not have been an assert about having a 
PM reference at the start of the function?

Although I don't see why a PM reference would be required to read from 
system memory on an integrated part? Maybe for a discrete part. But I 
would assume that having a vmap in existence would mean the memory is 
locked and accessible. Either that, or a vmap is only allowed to be used 
by accessor functions which themselves do whatever is required to make 
the access work.

John.

>
> Matt
>
>> +		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++);
>>   }
>>   
>>   int xe_guc_log_init(struct xe_guc_log *log)
>> -- 
>> 2.43.2
>>