Re: [PATCH v4 2/7] drm/xe/guc: Copy GuC log prior to dumping

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

On 6/11/2024 15:30, Michal Wajdeczko wrote:
> On 11.06.2024 03:20, John.C.Harrison@Intel.com wrote:
>> From: John Harrison <John.C.Harrison@Intel.com>
>>
>> Refactor the hexdump code into a separate function ready to be used
> maybe this separate function shall be promoted to drm_print_blob() ?
Maybe. That can happen as a follow up if people see a need for it from 
outside of the Xe driver. But see below about this being only a stop gap 
solution.


>
>> for dumps of other objects. Also change to dumping a host memory copy
>> rather than the live GPU buffer object. Doing so helps prevent
>> inconsistencies due to the log being updated as it is being dumped. It
>> also paves the way for decoupling the save from the print to allow
>> inclusion in error reports such as the devcoredump.
>>
>> Switch to use the dedicated kernel hexdump helper rather than printf.
>> The helper makes it easier to print out much wider lines which can
>> dramatically reduce the total line count of the dump (useful when
>> dumping to dmesg).
> as you are changing the format of the output, did you consider switching
> over to base64 ?
I don't see it as being worth the effort. The current changes are the 
low hanging fruit. Switching to base64 encoding seems like a lot more 
effort. There is not just the encoding effort in the KMD but also the 
decoding effort in user land to consider. And the ultimate aim is to 
move to compression. That's the only thing that really makes it feasible 
to dump BLOBs via dmesg. Moving to compression is definitely worth the 
effort in both the KMD and the user sides. But that ideally involves 
also moving to use devcoredump as the unified collection and dumping 
mechanism. That way only one set of tools need updating to support new 
formats. But devcoredump support is also not trivial for various reasons 
beyond simply adding the GuC log buffer to the dump.

>
>> Another issue with dumping such a large buffer is that it can be slow,
>> especially if dumping to dmesg over a serial port. So add a yield to
>> prevent the 'task has been stuck for 120s' kernel hang check feature
>> from firing.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
>> ---
>>   drivers/gpu/drm/xe/xe_guc_debugfs.c |   2 +-
>>   drivers/gpu/drm/xe/xe_guc_log.c     | 119 ++++++++++++++++++++++++----
>>   drivers/gpu/drm/xe/xe_guc_log.h     |   2 +-
>>   3 files changed, 106 insertions(+), 17 deletions(-)
>>
>> diff --git a/drivers/gpu/drm/xe/xe_guc_debugfs.c b/drivers/gpu/drm/xe/xe_guc_debugfs.c
>> index d3822cbea273..68f1f728c22c 100644
>> --- a/drivers/gpu/drm/xe/xe_guc_debugfs.c
>> +++ b/drivers/gpu/drm/xe/xe_guc_debugfs.c
>> @@ -41,7 +41,7 @@ static int guc_log(struct seq_file *m, void *data)
>>   	struct drm_printer p = drm_seq_file_printer(m);
>>   
>>   	xe_pm_runtime_get(xe);
>> -	xe_guc_log_print(&guc->log, &p);
>> +	xe_guc_log_print(&guc->log, &p, false);
>>   	xe_pm_runtime_put(xe);
>>   
>>   	return 0;
>> diff --git a/drivers/gpu/drm/xe/xe_guc_log.c b/drivers/gpu/drm/xe/xe_guc_log.c
>> index a37ee3419428..a35309926271 100644
>> --- a/drivers/gpu/drm/xe/xe_guc_log.c
>> +++ b/drivers/gpu/drm/xe/xe_guc_log.c
>> @@ -9,6 +9,7 @@
>>   
>>   #include "xe_bo.h"
>>   #include "xe_gt.h"
>> +#include "xe_gt_printk.h"
>>   #include "xe_map.h"
>>   #include "xe_module.h"
>>   
>> @@ -49,32 +50,120 @@ static size_t guc_log_size(void)
>>   		CAPTURE_BUFFER_SIZE;
>>   }
>>   
>> -void xe_guc_log_print(struct xe_guc_log *log, struct drm_printer *p)
>> +#define BYTES_PER_WORD		sizeof(u32)
> by WORD isn't we usually mean u16 ? u32 is DWORD
It is in Windows land. I'm not aware of the Linux kernel using DWORD as 
a type. And strictly speaking, isn't 'word' meant to be the native size 
of the architecture, i.e. 'int'?

>
>> +#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)
>> +
>> +static void xe_hexdump_blob(struct xe_device *xe, const void *blob, size_t size,
>> +			    struct drm_printer *p, bool atomic)
>> +{
>> +	char line_buff[DUMPS_PER_LINE * WORDS_PER_DUMP * 9 + 1];
> and magic "9" is from ...
That is the length of the ASCII string - 8 hex digits and one space. 
With a +1 for the null terminator. I suppose it could be wrapped up as 
ASCII_LENGTH_PER_WORD.

>
>> +	const u32 *blob32 = (const u32 *)blob;
>> +	int i, j, k;
>> +
>> +	if (size % (WORDS_PER_READ * BYTES_PER_WORD)) {
>> +		u32 remain = size % (WORDS_PER_READ * BYTES_PER_WORD);
>> +
>> +		drm_err(&xe->drm, "Invalid size for hexdump: 0x%lX vs 0x%lX (%d * %ld) -> 0x%X\n",
>> +			size, WORDS_PER_READ * BYTES_PER_WORD,
>> +			WORDS_PER_READ, BYTES_PER_WORD, remain);
> hmm, all this seems to be due to bad coding by the caller
> maybe just
>
> 	if (WARN_ON(size % (WORDS_PER_READ * BYTES_PER_WORD)))
> 		return;
>
> as this should never happen
It could just be a WARN and bail. But given that this is all about 
getting debug output for hard to debug situations, it seems prudent to 
get what we can out than to just abort and get nothing.

>
>> +
>> +		size -= remain;
>> +		if (!size)
>> +			return;
>> +	}
>> +
>> +	for (i = 0; i < size / BYTES_PER_WORD; i += WORDS_PER_READ) {
>> +		const u32 *src = ((const u32 *)blob32) + i;
> no need to cast, blob32 is already const u32*
Hmm. I think the intention was to get rid of blob32 and just cast blob 
here given that this is the only use of blob32.

>
>> +
>> +		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(src + j,
>> +							   sizeof(*src) * (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, "%s\n", line_buff);
>> +
>> +			/*
>> +			 * If spewing large amounts of data via a serial console,
>> +			 * this can be a very slow process. So be friendly and try
>> +			 * not to cause 'softlockup on CPU' problems.
>> +			 */
>> +			if (!atomic)
>> +				cond_resched();
>> +		}
>> +	}
>> +}
>> +
>> +#define GUC_LOG_CHUNK_SIZE	SZ_2M
>> +
> missing kernel-doc
Yup.

>
>> +void xe_guc_log_print(struct xe_guc_log *log, struct drm_printer *p, bool atomic)
>>   {
>>   	struct xe_device *xe = log_to_xe(log);
>> -	size_t size;
>> -	int i, j;
>> +	size_t size, remain;
>> +	void **copy;
>> +	int num_chunks, i;
>>   
>>   	xe_assert(xe, log->bo);
>>   
>> +	/*
>> +	 * NB: kmalloc has a hard limit well below the maximum GuC log buffer size.
>> +	 * Also, can't use vmalloc as might be called from atomic context. So need
>> +	 * to break the buffer up into smaller chunks that can be allocated.
>> +	 */
>>   	size = log->bo->size;
>> +	num_chunks = (size + GUC_LOG_CHUNK_SIZE - 1) / GUC_LOG_CHUNK_SIZE;
> DIV_ROUND_UP ?
Yup.

>
>>   
>> -#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];
>> +	copy = kcalloc(num_chunks, sizeof(*copy), atomic ? GFP_ATOMIC : GFP_KERNEL);
>> +	if (!copy) {
>> +		drm_printf(p, "Failed to allocate array x%d", num_chunks);
> I'm not sure that caller wants this message in it's printer output
It's better than having no output at all. Which is what you get otherwise.

>
>> +		return;
>> +	}
>>   
>> -		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;
>> +	remain = size;
>> +	for (i = 0; i < num_chunks; i++) {
>> +		size_t size = min(GUC_LOG_CHUNK_SIZE, remain);
> it's usually bad idea to overlap variable names
Yeah, but the outer size becomes snapshot->size in the next patch. I 
could rename the outer one total_size.

>
>>   
>> -			drm_printf(p, "0x%08x 0x%08x 0x%08x 0x%08x\n",
>> -				   *(print + 0), *(print + 1),
>> -				   *(print + 2), *(print + 3));
>> +		copy[i] = kmalloc(size, atomic ? GFP_ATOMIC : GFP_KERNEL);
>> +		if (!copy[i]) {
>> +			drm_printf(p, "Failed to allocate %ld at chunk %d of %d",
>> +				   size, i, num_chunks);
> ditto
Ditto to what? Printing an error message in the output file? As above, 
it is better than having an empty file with no explanation as to why.

>
>> +			goto out;
>>   		}
>> +		remain -= size;
>>   	}
>> +
>> +	remain = size;
>> +	for (i = 0; i < num_chunks; i++) {
>> +		size_t size = min(GUC_LOG_CHUNK_SIZE, remain);
> ditto
>
>> +
>> +		xe_map_memcpy_from(xe, copy[i], &log->bo->vmap, i * GUC_LOG_CHUNK_SIZE, size);
>> +		remain -= size;
>> +	}
>> +
>> +	remain = size;
>> +	for (i = 0; i < num_chunks; i++) {
>> +		size_t size = min(GUC_LOG_CHUNK_SIZE, remain);
> ditto
As above, the outer size is only a temporary thing until the next patch. 
Whereas these stick around forever.

John.

>
>> +
>> +		xe_hexdump_blob(xe, copy[i], size, p, atomic);
>> +		remain -= size;
>> +	}
>> +
>> +out:
>> +	for (i = 0; i < num_chunks; i++)
>> +		kfree(copy[i]);
>> +	kfree(copy);
>>   }
>>   
>>   int xe_guc_log_init(struct xe_guc_log *log)
>> diff --git a/drivers/gpu/drm/xe/xe_guc_log.h b/drivers/gpu/drm/xe/xe_guc_log.h
>> index 2d25ab28b4b3..5149b492c3b8 100644
>> --- a/drivers/gpu/drm/xe/xe_guc_log.h
>> +++ b/drivers/gpu/drm/xe/xe_guc_log.h
>> @@ -37,7 +37,7 @@ struct drm_printer;
>>   #define GUC_LOG_LEVEL_MAX GUC_VERBOSITY_TO_LOG_LEVEL(GUC_LOG_VERBOSITY_MAX)
>>   
>>   int xe_guc_log_init(struct xe_guc_log *log);
>> -void xe_guc_log_print(struct xe_guc_log *log, struct drm_printer *p);
>> +void xe_guc_log_print(struct xe_guc_log *log, struct drm_printer *p, bool atomic);
>>   
>>   static inline u32
>>   xe_guc_log_get_level(struct xe_guc_log *log)