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

[Michal Wajdeczko <michal.wajdeczko@intel.com>]

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

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

> 
>> 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

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

Michal

> 
> Regards,
> 
> Tvrtko
> 
>> drm_dbg_kms(&dev_priv->drm, "disabling %s\n", pll->info->name);
>> i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915-KMS]]
>> disabling PORT PLL B
>> But presumably that requires finishing the plan of splitting out the
>> display code into a separate driver. So for now, something like this
>> would still be a massive improvement:
>> kms_dbg(dev_priv, "disabling %s\n", pll->info->name);
>> i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] KMS:
>> disabling PORT PLL B
>>
>> John.
>>
>>>
>>> Regards,
>>>
>>> Tvrtko
>>