Re: [PATCH 1/2] soundwire: intel: uniquify debug message

[Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>]

>>>> diff --git a/drivers/soundwire/intel.c b/drivers/soundwire/intel.c
>>>> index 505c5ef061e3..808e2f320052 100644
>>>> --- a/drivers/soundwire/intel.c
>>>> +++ b/drivers/soundwire/intel.c
>>>> @@ -1328,8 +1328,8 @@ int intel_link_startup(struct auxiliary_device *auxdev)
>>>>  
>>>>  	if (bus->prop.hw_disabled) {
>>>>  		dev_info(dev,
>>>> -			 "SoundWire master %d is disabled, ignoring\n",
>>>> -			 sdw->instance);
>>>> +			 "%s: SoundWire master %d is disabled, ignoring\n",
>>>> +			 __func__, sdw->instance);
>>>
>>> This is not a debug message, please make it such if you want to have
>>> __func__  And even then, it's not needed as you can get that from the
>>> kernel automatically.
>>
>> Sorry, I don't understand the feedback at all.
> 
> dev_info() is not a way to send debug messages.
> 
> If you want this to be only for debugging, use dev_dbg().  And when you
> use that, you get the __func__ location for free in the output already
> if you want that.
> 
>> This message was added precisely to figure out why the expected
>> programming sequence was not followed, only to discover that we have
>> devices with spurious PCI wakes handled below. Without this added
>> difference with __func__, we wouldn't know if the issue happened during
>> the expected/regular programming sequence or not.
> 
> Perhaps make the text unique then?  Why would an informational message
> need a function name.  Drivers should be quiet when all is going well.
> If something is not going well, dev_info() is not the kernel log level
> to be sending something out at.

This is not a debug message - unlike all the others. The BIOS and/or the
user may disable a specific link and it's useful to know.

The intent of __func__ was precisely to make the text unique across all
cases where we test for hw_disabled, but you have a point that this
specific info message should be clearer. The text was actually already
different from the 'disable or not-started' cases, I might have done one
too many edits in this file. Will fix.

>>>>  		return 0;
>>>>  	}
>>>>  
>>>> @@ -1489,8 +1489,8 @@ int intel_link_process_wakeen_event(struct auxiliary_device *auxdev)
>>>>  	bus = &sdw->cdns.bus;
>>>>  
>>>>  	if (bus->prop.hw_disabled || !sdw->startup_done) {
>>>> -		dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
>>>> -			bus->link_id);
>>>> +		dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
>>>> +			__func__, bus->link_id);
>>>>  		return 0;
>>>>  	}
>>>>  
>>>> @@ -1549,8 +1549,8 @@ static int __maybe_unused intel_pm_prepare(struct device *dev)
>>>>  	int ret;
>>>>  
>>>>  	if (bus->prop.hw_disabled || !sdw->startup_done) {
>>>> -		dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
>>>> -			bus->link_id);
>>>> +		dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
>>>> +			__func__, bus->link_id);
>>>
>>> Not needed, it is provided automatically if you ask the kernel for this.
>>> Same for all other instances in this patch.
>>
>> provided how? Your comment is a bit cryptic here.
> 
> the dynamic debug code in the kernel already adds the function name
> where the message was sent from, if you want to know this in userspace.
> Please read the documentation for details (I think the key is the 'f'
> flag to be enabled in userspace).
> 
> So adding __func__ to dev_dbg() calls are redundant and never needed.

Oh wow, I had no idea - and I am not the only one :-)

Here's what I get with a grep on the kernel code

git grep __func__ | grep dev_dbg | wc -l

3122


Doing this for sound/ gives me 356, and that's for single-line logs only.

There's clearly something that was missed by tons of people.

We use an 'sof-dyndbg.conf' file that we provide to users and our CI to
log what's needed for SOF debug, it's trivial to add a +f option.

options foo dyndbg=+pf

Thanks for the feedback, much appreciated.
-Pierre