2022-06-10 02:56:15

by Bard Liao

[permalink] [raw]
Subject: [PATCH 1/2] soundwire: intel: uniquify debug message

From: Pierre-Louis Bossart <[email protected]>

The same debug message is replicated multiple time, add __func__ to
figure out what link is ignored.

Signed-off-by: Pierre-Louis Bossart <[email protected]>
Reviewed-by: Ranjani Sridharan <[email protected]>
Reviewed-by: Péter Ujfalusi <[email protected]>
Signed-off-by: Bard Liao <[email protected]>
---
drivers/soundwire/intel.c | 28 ++++++++++++++--------------
1 file changed, 14 insertions(+), 14 deletions(-)

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);
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);
return 0;
}

@@ -1609,8 +1609,8 @@ static int __maybe_unused intel_suspend(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);
return 0;
}

@@ -1662,8 +1662,8 @@ static int __maybe_unused intel_suspend_runtime(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);
return 0;
}

@@ -1727,8 +1727,8 @@ static int __maybe_unused intel_resume(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);
return 0;
}

@@ -1825,8 +1825,8 @@ static int __maybe_unused intel_resume_runtime(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);
return 0;
}

--
2.17.1


2022-06-10 06:02:05

by Greg Kroah-Hartman

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

On Fri, Jun 10, 2022 at 10:35:36AM +0800, Bard Liao wrote:
> From: Pierre-Louis Bossart <[email protected]>
>
> The same debug message is replicated multiple time, add __func__ to
> figure out what link is ignored.
>
> Signed-off-by: Pierre-Louis Bossart <[email protected]>
> Reviewed-by: Ranjani Sridharan <[email protected]>
> Reviewed-by: P?ter Ujfalusi <[email protected]>
> Signed-off-by: Bard Liao <[email protected]>
> ---
> drivers/soundwire/intel.c | 28 ++++++++++++++--------------
> 1 file changed, 14 insertions(+), 14 deletions(-)
>
> 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.

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

thanks,

greg k-h

2022-06-10 16:58:43

by Pierre-Louis Bossart

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



On 6/10/22 00:25, Greg KH wrote:
> On Fri, Jun 10, 2022 at 10:35:36AM +0800, Bard Liao wrote:
>> From: Pierre-Louis Bossart <[email protected]>
>>
>> The same debug message is replicated multiple time, add __func__ to
>> figure out what link is ignored.
>>
>> Signed-off-by: Pierre-Louis Bossart <[email protected]>
>> Reviewed-by: Ranjani Sridharan <[email protected]>
>> Reviewed-by: Péter Ujfalusi <[email protected]>
>> Signed-off-by: Bard Liao <[email protected]>
>> ---
>> drivers/soundwire/intel.c | 28 ++++++++++++++--------------
>> 1 file changed, 14 insertions(+), 14 deletions(-)
>>
>> 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.

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.

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

2022-06-11 09:33:02

by Greg Kroah-Hartman

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

On Fri, Jun 10, 2022 at 10:06:58AM -0500, Pierre-Louis Bossart wrote:
>
>
> On 6/10/22 00:25, Greg KH wrote:
> > On Fri, Jun 10, 2022 at 10:35:36AM +0800, Bard Liao wrote:
> >> From: Pierre-Louis Bossart <[email protected]>
> >>
> >> The same debug message is replicated multiple time, add __func__ to
> >> figure out what link is ignored.
> >>
> >> Signed-off-by: Pierre-Louis Bossart <[email protected]>
> >> Reviewed-by: Ranjani Sridharan <[email protected]>
> >> Reviewed-by: P?ter Ujfalusi <[email protected]>
> >> Signed-off-by: Bard Liao <[email protected]>
> >> ---
> >> drivers/soundwire/intel.c | 28 ++++++++++++++--------------
> >> 1 file changed, 14 insertions(+), 14 deletions(-)
> >>
> >> 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.

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

thanks,

greg k-h

2022-06-13 16:40:05

by Pierre-Louis Bossart

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



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

2022-06-13 20:09:42

by Greg Kroah-Hartman

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

On Mon, Jun 13, 2022 at 07:48:32AM -0500, Pierre-Louis Bossart wrote:
>
>
> >>>> 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.

Ok, but that's not what your subject and changelog said you were
modifying here. Hence my confusion :)

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

Yes, it's not commonly known so cleanups are always welcome. Perhaps
some of those usages predate the feature being added as well.

thanks,

greg k-h

2022-06-13 21:21:55

by Pierre-Louis Bossart

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


>>>>>> @@ -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.
>
> Yes, it's not commonly known so cleanups are always welcome. Perhaps
> some of those usages predate the feature being added as well.

Yep, looks like no one in our team knew about this. We've changed our
scripts and I started cleaning this up, changes will be posted upstream
soon.

https://github.com/thesofproject/linux/pull/3695

This patch will be reverted in our tree, completely unnecessary indeed.