Re: [Intel-gfx] [PATCH v2 4/5] drm/i915/guc: Add GuC CT specific debug print wrappers

[Tvrtko Ursulin <tvrtko.ursulin@linux.intel.com>]

On 05/12/2022 18:44, Michal Wajdeczko wrote:
> On 05.12.2022 14:16, Tvrtko Ursulin wrote:
>>
>> On 02/12/2022 20:14, John Harrison wrote:
>>
>>>>> and while for dbg level messages it doesn't matter, I assume we should
>>>>> be consistent for err/warn/info messages (as those will eventually show
>>>>> up to the end user) so let maintainers decide here what is
>>>>> expectation here
>>>>
>>>> Could we have some examples pasted here, of the end result of this
>>>> series, for all message "categories" (origins, macros, whatever)?
>>>
>>> GT initialisation:
>>> gt_err(gt, "Failed to allocate scratch page\n");
>>> i915 0000:00:02.0: [drm] GT0: Failed to allocate scratch page
>>>
>>> G2H notification handler:
>>> guc_err(guc, "notification: Invalid length %u for deregister done\n",
>>> len);
>>> i915 0000:00:02.0: [drm] GT0: GuC notification: Invalid length 0 for
>>> deregister done
> 
> please note that today this message is coded as:
> 
> drm_err(&guc_to_gt(guc)->i915->drm, "Invalid length %u\n", len);
> -> i915 0000:00:02.0: [drm] Invalid length %u
> 
> which makes this rather an example of meaningless log

Okay, so log text needs improving anyway which is orthogonal.

>> I'm not liking the inconsistency between gt_err and guc_err where with
>> latter callers either need to start the message with lower case because
>> of the unstructured "GuC " prefix added. Which then reads bad if callers
>> do guc_err(guc, "Error X happend").
>>
>> Looks like Michal was pointing out the same thing, AFAIU at least when
>> re-reading the thread now.
>>
>> Why wouldn't this work:
>>
>> guc_err(guc, "Invalid length %u for deregister done notification\n", len);
>> i915 0000:00:02.0: [drm] GT0: GuC: Invalid length 0 for deregister done
>> notification
> 
> +1
> 
>>
>> Or if the use case for adding custom prefixes is strong then maybe
>> consider:
>>
>> guc_err(guc, "notification", "Invalid length 0 for deregister done");
>> i915 0000:00:02.0: [drm] GT0: GuC notification: Invalid length 0 for
>> deregister done
>>
>> guc_err(guc, "", "Error X");
>> i915 0000:00:02.0: [drm] GT0: GuC: Error X
> 
> -1
> 
> this will make logging macros too different from others (unless we
> hide/use prefixes inside macros only, but I'm not sure there is any ROI)

Yeah I said if the use case is strong, no strong opinion either way.

>>> CTB initialisation:
>>> ct_probe_error(ct, "Failed to control/%s CTB (%pe)\n",
>>> str_enable_disable(enable), ERR_PTR(err));
>>> i915 0000:00:02.0: [drm] GT0: GuC CT Failed to control/enable CTB
>>> (EINVAL)
>>
>> Okay same as above.
>>
>>> Random meaningless (to me) message that is apparently a display thing:
>>> drm_dbg_kms(&dev_priv->drm, "disabling %s\n", pll->info->name);
>>> i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling
>>> PORT PLL B
>>
>> Plan is to not touch outside gt/.
>>
>>> I'm sure you can extrapolate to all other forms of dbg, notice, info,
>>> etc. without me having to manually type each one out, given that they
>>> are all identical.
>>>
>>> Personally, I think the above should be just:
>>> gt_err(gt, "Failed to allocate scratch page\n");
>>> i915 0000:00:02.0: [drm] GT0: Failed to allocate scratch page
>>>
>>> gt_err(guc_to_gt(guc), "G2H: Invalid length for deregister done:
>>> %u\n", len);
>>> i915 0000:00:02.0: [drm] GT0: G2H: Invalid length for deregister done: 0
> 
> that's probably should be:
> 
> 	"Invalid length for G2H deregister done: %u\n
> 
> and it will still just look fine if we auto append the 'GuC' prefix:
> 
> i915 0000:00:02.0: [drm] GT0: GuC: Invalid length for G2H deregister
> 
>>>
>>> gt_probe_error(ct_to_gt(ct), "Failed to %s CT %d buffer (%pe)\n",
>>> str_enable_disable(enable), send ? "SEND" : "RECV", ERR_PTR(err));
>>> i915 0000:00:02.0: [drm] GT0: Failed to enable CT SEND buffer (EINVAL)
> 
> having "GuC/CT" prefix here will also look fine:
> 
> i915 0000:00:02.0: [drm] GT0: GuC: Failed to enable CT SEND buffer
> i915 0000:00:02.0: [drm] GT0: GuC: CT: Failed to enable SEND buffer
> i915 0000:00:02.0: [drm] GT0: CT: Failed to enable SEND buffer

Works for me.

>> We could but it seems we agreed some weeks ago to consolidate the
>> existing CT_ERROR macros and such in this exercise. At least no
>> objections were raised to that plan.
>>
>> If now we want to go back on that, and if you want to have
>> guc_to_gt(guc) in all gt/uc/ call sites that's fine by me, but please
>> get some acks and consensus from people who work in that area. And under
>> that option someone would also need to convert the CT code to new macros.
> 
> while the main goal of this series was to have GT# appended to the log
> messages but we also wanted to simplify the use of the logging macros by
> passing the component pointer directly (with extra *bonus* that allows
> to auto append component specific prefix, if any, like CT macros do)
> 
> IMHO adding guc_xxx() macros with "GuC:" prefix will do the trick and
> since many of the existing GuC related logs are already broken or
> incomplete, we might fix them accordingly.
> 
> In other words in addition to gt_xxx() I still want additional guc_xxx()
> macros (as it will allow us to fix related messages) and ct_xxx() macros
> (as we already have CT_xxx so no need to change anything)

Both approaches are fine by me as long as it's logical and consistent 
and we manage not to leave the conversion half-done for too long.

Maybe as a way forward work could be split? If John wants to deal with 
gt_xxx macros, avoid touching GuC (putting his original motivation 
aside) and you want to convert the gt/uc folder? Assuming John you are 
okay with "GuC:" and "CT:" prefixes.

Regards,

Tvrtko