[PATCH 0/2] soundwire: bus: handle errors in clock stop/start sequences

[PATCH 0/2] soundwire: bus: handle errors in clock stop/start sequences

[Bard Liao]

If a device lost sync and can no longer ACK a command, it may not be
able to enter a lower-power state but it will still be able to resync
when the clock restarts. In those cases, we want to continue with the
clock stop sequence.

This patch modifies the behavior when -ENODATA is received, with the
error level demoted to a dev_dbg() since it's a recoverable issue.

For consistency the log messages are also modified to be unique and
self-explanatory, and missing logs are also added on clock stop exit.

Pierre-Louis Bossart (2):
  soundwire: add macro to selectively change error levels
  soundwire: bus: handle errors in clock stop/start sequences

 drivers/soundwire/bus.c | 70 +++++++++++++++++++----------------------
 drivers/soundwire/bus.h |  8 +++++
 2 files changed, 40 insertions(+), 38 deletions(-)

-- 
2.17.1

[PATCH 1/2] soundwire: add macro to selectively change error levels

[Bard Liao]

From: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

We sometimes discard -ENODATA when reporting errors and lose all
traces of issues in the console log, add a macro to add use dev_dbg()
in such cases.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Reviewed-by: Rander Wang <rander.wang@intel.com>
Reviewed-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
---
 drivers/soundwire/bus.h | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/soundwire/bus.h b/drivers/soundwire/bus.h
index 40354469860a..8370216f95d4 100644
--- a/drivers/soundwire/bus.h
+++ b/drivers/soundwire/bus.h
@@ -227,4 +227,12 @@ int sdw_bwrite_no_pm_unlocked(struct sdw_bus *bus, u16 dev_num, u32 addr, u8 val
 void sdw_clear_slave_status(struct sdw_bus *bus, u32 request);
 int sdw_slave_modalias(const struct sdw_slave *slave, char *buf, size_t size);
 
+#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
+	do {								\
+		if (is_err)						\
+			dev_err(dev, fmt, __VA_ARGS__);			\
+		else							\
+			dev_dbg(dev, fmt, __VA_ARGS__);			\
+	} while (0)
+
 #endif /* __SDW_BUS_H */
-- 
2.17.1

[PATCH 2/2] soundwire: bus: handle errors in clock stop/start sequences

[Bard Liao]

From: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

If a device lost sync and can no longer ACK a command, it may not be
able to enter a lower-power state but it will still be able to resync
when the clock restarts. In those cases, we want to continue with the
clock stop sequence.

This patch modifies the behavior when -ENODATA is received, with the
error level demoted to a dev_dbg() since it's a recoverable issue.

For consistency the log messages are also modified to be unique and
self-explanatory, and missing logs are also added on clock stop exit.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Reviewed-by: Rander Wang <rander.wang@intel.com>
Reviewed-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
---
 drivers/soundwire/bus.c | 70 +++++++++++++++++++----------------------
 1 file changed, 32 insertions(+), 38 deletions(-)

diff --git a/drivers/soundwire/bus.c b/drivers/soundwire/bus.c
index 9bd83c91a873..ea54a1f02252 100644
--- a/drivers/soundwire/bus.c
+++ b/drivers/soundwire/bus.c
@@ -848,8 +848,9 @@ static int sdw_slave_clk_stop_callback(struct sdw_slave *slave,
 	if (slave->ops && slave->ops->clk_stop) {
 		ret = slave->ops->clk_stop(slave, mode, type);
 		if (ret < 0) {
-			dev_err(&slave->dev,
-				"Clk Stop type =%d failed: %d\n", type, ret);
+			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+					   "Clk Stop mode %d type =%d failed: %d\n",
+					   mode, type, ret);
 			return ret;
 		}
 	}
@@ -878,7 +879,8 @@ static int sdw_slave_clk_stop_prepare(struct sdw_slave *slave,
 	} else {
 		ret = sdw_read_no_pm(slave, SDW_SCP_SYSTEMCTRL);
 		if (ret < 0) {
-			dev_err(&slave->dev, "SDW_SCP_SYSTEMCTRL read failed:%d\n", ret);
+			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+					   "SDW_SCP_SYSTEMCTRL read failed:%d\n", ret);
 			return ret;
 		}
 		val = ret;
@@ -888,8 +890,8 @@ static int sdw_slave_clk_stop_prepare(struct sdw_slave *slave,
 	ret = sdw_write_no_pm(slave, SDW_SCP_SYSTEMCTRL, val);
 
 	if (ret < 0)
-		dev_err(&slave->dev,
-			"Clock Stop prepare failed for slave: %d", ret);
+		sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+				   "SDW_SCP_SYSTEMCTRL write ignored:%d\n", ret);
 
 	return ret;
 }
@@ -907,7 +909,7 @@ static int sdw_bus_wait_for_clk_prep_deprep(struct sdw_bus *bus, u16 dev_num)
 		}
 		val &= SDW_SCP_STAT_CLK_STP_NF;
 		if (!val) {
-			dev_dbg(bus->dev, "clock stop prep/de-prep done slave:%d",
+			dev_dbg(bus->dev, "clock stop prep/de-prep done slave:%d\n",
 				dev_num);
 			return 0;
 		}
@@ -916,7 +918,7 @@ static int sdw_bus_wait_for_clk_prep_deprep(struct sdw_bus *bus, u16 dev_num)
 		retry--;
 	} while (retry);
 
-	dev_err(bus->dev, "clock stop prep/de-prep failed slave:%d",
+	dev_err(bus->dev, "clock stop prep/de-prep failed slave:%d\n",
 		dev_num);
 
 	return -ETIMEDOUT;
@@ -956,19 +958,18 @@ int sdw_bus_prep_clk_stop(struct sdw_bus *bus)
 		slave_mode = sdw_get_clk_stop_mode(slave);
 		slave->curr_clk_stop_mode = slave_mode;
 
-		ret = sdw_slave_clk_stop_callback(slave, slave_mode,
-						  SDW_CLK_PRE_PREPARE);
+		ret = sdw_slave_clk_stop_callback(slave, slave_mode, SDW_CLK_PRE_PREPARE);
 		if (ret < 0) {
-			dev_err(&slave->dev,
-				"pre-prepare failed:%d", ret);
+			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+					   "clock stop pre prepare cb failed:%d\n", ret);
 			return ret;
 		}
 
 		ret = sdw_slave_clk_stop_prepare(slave,
 						 slave_mode, true);
 		if (ret < 0) {
-			dev_err(&slave->dev,
-				"pre-prepare failed:%d", ret);
+			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+					   "clock stop prepare failed:%d\n", ret);
 			return ret;
 		}
 
@@ -999,13 +1000,11 @@ int sdw_bus_prep_clk_stop(struct sdw_bus *bus)
 		slave_mode = slave->curr_clk_stop_mode;
 
 		if (slave_mode == SDW_CLK_STOP_MODE1) {
-			ret = sdw_slave_clk_stop_callback(slave,
-							  slave_mode,
-							  SDW_CLK_POST_PREPARE);
-
+			ret = sdw_slave_clk_stop_callback(slave, slave_mode, SDW_CLK_POST_PREPARE);
 			if (ret < 0) {
-				dev_err(&slave->dev,
-					"post-prepare failed:%d", ret);
+				sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+						   "clock stop post-prepare cb failed:%d\n", ret);
+				return ret;
 			}
 		}
 	}
@@ -1033,12 +1032,8 @@ int sdw_bus_clk_stop(struct sdw_bus *bus)
 	ret = sdw_bwrite_no_pm(bus, SDW_BROADCAST_DEV_NUM,
 			       SDW_SCP_CTRL, SDW_SCP_CTRL_CLK_STP_NOW);
 	if (ret < 0) {
-		if (ret == -ENODATA)
-			dev_dbg(bus->dev,
-				"ClockStopNow Broadcast msg ignored %d", ret);
-		else
-			dev_err(bus->dev,
-				"ClockStopNow Broadcast msg failed %d", ret);
+		sdw_dev_dbg_or_err(bus->dev, ret != -ENODATA,
+				   "ClockStopNow Broadcast msg failed %d\n", ret);
 		return ret;
 	}
 
@@ -1086,26 +1081,24 @@ int sdw_bus_exit_clk_stop(struct sdw_bus *bus)
 			continue;
 		}
 
-		ret = sdw_slave_clk_stop_callback(slave, mode,
-						  SDW_CLK_PRE_DEPREPARE);
+		ret = sdw_slave_clk_stop_callback(slave, mode, SDW_CLK_PRE_DEPREPARE);
 		if (ret < 0)
-			dev_warn(&slave->dev,
-				 "clk stop deprep failed:%d", ret);
-
-		ret = sdw_slave_clk_stop_prepare(slave, mode,
-						 false);
+			dev_warn(&slave->dev, "clock stop pre deprepare cb failed:%d\n", ret);
 
+		ret = sdw_slave_clk_stop_prepare(slave, mode, false);
 		if (ret < 0)
-			dev_warn(&slave->dev,
-				 "clk stop deprep failed:%d", ret);
+			dev_warn(&slave->dev, "clock stop deprepare failed:%d\n", ret);
 	}
 
 	/* Skip remaining clock stop de-preparation if no Slave is attached */
 	if (!is_slave)
 		return 0;
 
-	if (!simple_clk_stop)
-		sdw_bus_wait_for_clk_prep_deprep(bus, SDW_BROADCAST_DEV_NUM);
+	if (!simple_clk_stop) {
+		ret = sdw_bus_wait_for_clk_prep_deprep(bus, SDW_BROADCAST_DEV_NUM);
+		if (ret < 0)
+			dev_warn(&slave->dev, "clock stop deprepare wait failed:%d\n", ret);
+	}
 
 	list_for_each_entry(slave, &bus->slaves, node) {
 		if (!slave->dev_num)
@@ -1116,8 +1109,9 @@ int sdw_bus_exit_clk_stop(struct sdw_bus *bus)
 			continue;
 
 		mode = slave->curr_clk_stop_mode;
-		sdw_slave_clk_stop_callback(slave, mode,
-					    SDW_CLK_POST_DEPREPARE);
+		ret = sdw_slave_clk_stop_callback(slave, mode, SDW_CLK_POST_DEPREPARE);
+		if (ret < 0)
+			dev_warn(&slave->dev, "clock stop post deprepare cb failed:%d\n", ret);
 	}
 
 	return 0;
-- 
2.17.1

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Vinod Koul]

On 31-03-21, 09:13, Bard Liao wrote:
> From: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
> 
> We sometimes discard -ENODATA when reporting errors and lose all
> traces of issues in the console log, add a macro to add use dev_dbg()
> in such cases.
> 
> Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
> Reviewed-by: Rander Wang <rander.wang@intel.com>
> Reviewed-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
> Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
> ---
>  drivers/soundwire/bus.h | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/drivers/soundwire/bus.h b/drivers/soundwire/bus.h
> index 40354469860a..8370216f95d4 100644
> --- a/drivers/soundwire/bus.h
> +++ b/drivers/soundwire/bus.h
> @@ -227,4 +227,12 @@ int sdw_bwrite_no_pm_unlocked(struct sdw_bus *bus, u16 dev_num, u32 addr, u8 val
>  void sdw_clear_slave_status(struct sdw_bus *bus, u32 request);
>  int sdw_slave_modalias(const struct sdw_slave *slave, char *buf, size_t size);
>  
> +#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
> +	do {								\
> +		if (is_err)						\
> +			dev_err(dev, fmt, __VA_ARGS__);			\
> +		else							\
> +			dev_dbg(dev, fmt, __VA_ARGS__);			\
> +	} while (0)

I see a variant in sof code and now here, why not add in a
dev_dbg_or_err() and use everywhere?

Thanks
-- 
~Vinod

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Pierre-Louis Bossart]

On 4/1/21 2:24 AM, Vinod Koul wrote:
> On 31-03-21, 09:13, Bard Liao wrote:
>> From: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
>>
>> We sometimes discard -ENODATA when reporting errors and lose all
>> traces of issues in the console log, add a macro to add use dev_dbg()
>> in such cases.
>>
>> Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
>> Reviewed-by: Rander Wang <rander.wang@intel.com>
>> Reviewed-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
>> Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
>> ---
>>   drivers/soundwire/bus.h | 8 ++++++++
>>   1 file changed, 8 insertions(+)
>>
>> diff --git a/drivers/soundwire/bus.h b/drivers/soundwire/bus.h
>> index 40354469860a..8370216f95d4 100644
>> --- a/drivers/soundwire/bus.h
>> +++ b/drivers/soundwire/bus.h
>> @@ -227,4 +227,12 @@ int sdw_bwrite_no_pm_unlocked(struct sdw_bus *bus, u16 dev_num, u32 addr, u8 val
>>   void sdw_clear_slave_status(struct sdw_bus *bus, u32 request);
>>   int sdw_slave_modalias(const struct sdw_slave *slave, char *buf, size_t size);
>>   
>> +#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
>> +	do {								\
>> +		if (is_err)						\
>> +			dev_err(dev, fmt, __VA_ARGS__);			\
>> +		else							\
>> +			dev_dbg(dev, fmt, __VA_ARGS__);			\
>> +	} while (0)
> 
> I see a variant in sof code and now here, why not add in a
> dev_dbg_or_err() and use everywhere?

Good point, I hesitated back and forth on specific v. generic macro.

The main reason why I added this macro for SoundWire is that quite a few 
subsystems have their own debug functions (DRM, ACPI, etc), and I wasn't 
sure if there was any appetite to add more options in 
include/linux/dev_printk.h. SOF also uses a different format due to history.

If at the end of the day SoundWire and SOF are the only users the value 
of a common macro is limited.

But it's true that the macro could be used by others.

I really have no opinion here and will follow the consensus.

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Greg KH]

On Thu, Apr 01, 2021 at 09:30:27AM -0500, Pierre-Louis Bossart wrote:
> 
> 
> On 4/1/21 2:24 AM, Vinod Koul wrote:
> > On 31-03-21, 09:13, Bard Liao wrote:
> > > From: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
> > > 
> > > We sometimes discard -ENODATA when reporting errors and lose all
> > > traces of issues in the console log, add a macro to add use dev_dbg()
> > > in such cases.
> > > 
> > > Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
> > > Reviewed-by: Rander Wang <rander.wang@intel.com>
> > > Reviewed-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
> > > Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
> > > ---
> > >   drivers/soundwire/bus.h | 8 ++++++++
> > >   1 file changed, 8 insertions(+)
> > > 
> > > diff --git a/drivers/soundwire/bus.h b/drivers/soundwire/bus.h
> > > index 40354469860a..8370216f95d4 100644
> > > --- a/drivers/soundwire/bus.h
> > > +++ b/drivers/soundwire/bus.h
> > > @@ -227,4 +227,12 @@ int sdw_bwrite_no_pm_unlocked(struct sdw_bus *bus, u16 dev_num, u32 addr, u8 val
> > >   void sdw_clear_slave_status(struct sdw_bus *bus, u32 request);
> > >   int sdw_slave_modalias(const struct sdw_slave *slave, char *buf, size_t size);
> > > +#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
> > > +	do {								\
> > > +		if (is_err)						\
> > > +			dev_err(dev, fmt, __VA_ARGS__);			\
> > > +		else							\
> > > +			dev_dbg(dev, fmt, __VA_ARGS__);			\
> > > +	} while (0)
> > 
> > I see a variant in sof code and now here, why not add in a
> > dev_dbg_or_err() and use everywhere?
> 
> Good point, I hesitated back and forth on specific v. generic macro.
> 
> The main reason why I added this macro for SoundWire is that quite a few
> subsystems have their own debug functions (DRM, ACPI, etc), and I wasn't
> sure if there was any appetite to add more options in
> include/linux/dev_printk.h. SOF also uses a different format due to history.

It is better if those other subsystems move to using the common kernel
debug functions.  Historically they were all separate, there is no good
reason for them to be that way today.

So please do not create custom subsystem debug macros like this just for
this tiny set of drivers.

My bigger issue with this is that this macro is crazy.  Why do you need
debugging here at all for this type of thing?  That's what ftrace is
for, do not sprinkle code with "we got this return value from here!" all
over the place like what this does.

thanks,

greg k-h

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Pierre-Louis Bossart]

>>>> +#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
>>>> +	do {								\
>>>> +		if (is_err)						\
>>>> +			dev_err(dev, fmt, __VA_ARGS__);			\
>>>> +		else							\
>>>> +			dev_dbg(dev, fmt, __VA_ARGS__);			\
>>>> +	} while (0)
>>>
>>> I see a variant in sof code and now here, why not add in a
>>> dev_dbg_or_err() and use everywhere?
>>
>> Good point, I hesitated back and forth on specific v. generic macro.
>>
>> The main reason why I added this macro for SoundWire is that quite a few
>> subsystems have their own debug functions (DRM, ACPI, etc), and I wasn't
>> sure if there was any appetite to add more options in
>> include/linux/dev_printk.h. SOF also uses a different format due to history.
> 
> It is better if those other subsystems move to using the common kernel
> debug functions.  Historically they were all separate, there is no good
> reason for them to be that way today.
> 
> So please do not create custom subsystem debug macros like this just for
> this tiny set of drivers.
> 
> My bigger issue with this is that this macro is crazy.  Why do you need
> debugging here at all for this type of thing?  That's what ftrace is
> for, do not sprinkle code with "we got this return value from here!" all
> over the place like what this does.

We are not sprinkling the code all over the place with any new logs, 
they exist already in the SoundWire code and this patch helps filter 
them out. See e.g. patch 2/2

-			dev_err(&slave->dev,
-				"Clk Stop type =%d failed: %d\n", type, ret);
+			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
+					   "Clk Stop mode %d type =%d failed: %d\n",
+					   mode, type, ret);

If you see all my recent patches they were precisely trying to avoid 
polluting the console logs with too much information that is irrelevant 
from most users, and making sure that when a log is provided it's 
uniquely identifiable.

There are similar macros where -EPROBE_DEFER is ignored.

This addresses a very SoundWire-specific case where if we see a -ENODATA 
error code (Command Ignored), we ignore it and don't report it by 
default. We still have a rare set of cases where this -ENODATA code 
shows up unexpectedly, possibly due to problematic reset sequences, and 
we want developers to help track them down what causes this sequence 
using dynamic debug.

I am not arguing about ftrace v. dynamic debug, and that's also partly 
why I didn't feel comfortable expanding the generic set of debug functions.

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Greg KH]

On Thu, Apr 01, 2021 at 01:07:49PM -0500, Pierre-Louis Bossart wrote:
> 
> > > > > +#define sdw_dev_dbg_or_err(dev, is_err, fmt, ...)			\
> > > > > +	do {								\
> > > > > +		if (is_err)						\
> > > > > +			dev_err(dev, fmt, __VA_ARGS__);			\
> > > > > +		else							\
> > > > > +			dev_dbg(dev, fmt, __VA_ARGS__);			\
> > > > > +	} while (0)
> > > > 
> > > > I see a variant in sof code and now here, why not add in a
> > > > dev_dbg_or_err() and use everywhere?
> > > 
> > > Good point, I hesitated back and forth on specific v. generic macro.
> > > 
> > > The main reason why I added this macro for SoundWire is that quite a few
> > > subsystems have their own debug functions (DRM, ACPI, etc), and I wasn't
> > > sure if there was any appetite to add more options in
> > > include/linux/dev_printk.h. SOF also uses a different format due to history.
> > 
> > It is better if those other subsystems move to using the common kernel
> > debug functions.  Historically they were all separate, there is no good
> > reason for them to be that way today.
> > 
> > So please do not create custom subsystem debug macros like this just for
> > this tiny set of drivers.
> > 
> > My bigger issue with this is that this macro is crazy.  Why do you need
> > debugging here at all for this type of thing?  That's what ftrace is
> > for, do not sprinkle code with "we got this return value from here!" all
> > over the place like what this does.
> 
> We are not sprinkling the code all over the place with any new logs, they
> exist already in the SoundWire code and this patch helps filter them out.
> See e.g. patch 2/2
> 
> -			dev_err(&slave->dev,
> -				"Clk Stop type =%d failed: %d\n", type, ret);
> +			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
> +					   "Clk Stop mode %d type =%d failed: %d\n",
> +					   mode, type, ret);

You just added a debug log for no reason.

That's what I was referring to :)

> If you see all my recent patches they were precisely trying to avoid
> polluting the console logs with too much information that is irrelevant from
> most users, and making sure that when a log is provided it's uniquely
> identifiable.
> 
> There are similar macros where -EPROBE_DEFER is ignored.

deffered probe is a totally different beast and one that I constantly am
ashamed I accepted into the kernel as the added complexity it has caused
is crazy.

> This addresses a very SoundWire-specific case where if we see a -ENODATA
> error code (Command Ignored), we ignore it and don't report it by default.
> We still have a rare set of cases where this -ENODATA code shows up
> unexpectedly, possibly due to problematic reset sequences, and we want
> developers to help track them down what causes this sequence using dynamic
> debug.
> 
> I am not arguing about ftrace v. dynamic debug, and that's also partly why I
> didn't feel comfortable expanding the generic set of debug functions.

Great, then don't add unneeded dev_dbg() lines :)

thanks,

greg k-h

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Pierre-Louis Bossart]

>>> My bigger issue with this is that this macro is crazy.  Why do you need
>>> debugging here at all for this type of thing?  That's what ftrace is
>>> for, do not sprinkle code with "we got this return value from here!" all
>>> over the place like what this does.
>>
>> We are not sprinkling the code all over the place with any new logs, they
>> exist already in the SoundWire code and this patch helps filter them out.
>> See e.g. patch 2/2
>>
>> -			dev_err(&slave->dev,
>> -				"Clk Stop type =%d failed: %d\n", type, ret);
>> +			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
>> +					   "Clk Stop mode %d type =%d failed: %d\n",
>> +					   mode, type, ret);
> 
> You just added a debug log for no reason.

The number of logs is lower when dynamic debug is not enabled, and equal 
when it is. there's no addition.

The previous behavior was unconditional dev_err that everyone sees.

Now it's dev_err ONLY when the code is NOT -ENODATA, and dev_dgb 
otherwise, meaning it will seen ONLY be seen IF dynamic debug is enabled 
for drivers/soundwire/bus.c

Allow me to use another example from patch2:

-		if (ret == -ENODATA)
-			dev_dbg(bus->dev,
-				"ClockStopNow Broadcast msg ignored %d", ret);
-		else
-			dev_err(bus->dev,
-				"ClockStopNow Broadcast msg failed %d", ret);
+		sdw_dev_dbg_or_err(bus->dev, ret != -ENODATA,
+				   "ClockStopNow Broadcast msg failed %d\n", ret);

There's no new log, is there?

If that still gives you a heartburn, I would still like a macro that 
filters out dev_err so that we don't report an error when it's 
recoverable or harmless, and don't have spaghetti code as above.

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Greg KH]

On Thu, Apr 01, 2021 at 01:43:53PM -0500, Pierre-Louis Bossart wrote:
> 
> > > > My bigger issue with this is that this macro is crazy.  Why do you need
> > > > debugging here at all for this type of thing?  That's what ftrace is
> > > > for, do not sprinkle code with "we got this return value from here!" all
> > > > over the place like what this does.
> > > 
> > > We are not sprinkling the code all over the place with any new logs, they
> > > exist already in the SoundWire code and this patch helps filter them out.
> > > See e.g. patch 2/2
> > > 
> > > -			dev_err(&slave->dev,
> > > -				"Clk Stop type =%d failed: %d\n", type, ret);
> > > +			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
> > > +					   "Clk Stop mode %d type =%d failed: %d\n",
> > > +					   mode, type, ret);
> > 
> > You just added a debug log for no reason.
> 
> The number of logs is lower when dynamic debug is not enabled, and equal
> when it is. there's no addition.
> 
> The previous behavior was unconditional dev_err that everyone sees.
> 
> Now it's dev_err ONLY when the code is NOT -ENODATA, and dev_dgb otherwise,
> meaning it will seen ONLY be seen IF dynamic debug is enabled for
> drivers/soundwire/bus.c
> 
> Allow me to use another example from patch2:
> 
> -		if (ret == -ENODATA)
> -			dev_dbg(bus->dev,
> -				"ClockStopNow Broadcast msg ignored %d", ret);
> -		else
> -			dev_err(bus->dev,
> -				"ClockStopNow Broadcast msg failed %d", ret);
> +		sdw_dev_dbg_or_err(bus->dev, ret != -ENODATA,
> +				   "ClockStopNow Broadcast msg failed %d\n", ret);
> 
> There's no new log, is there?

No, but that is not what you showed above which was just an error
message being replaced with both a debug and an error message.

Just drop the debug messages, they are pointless, right?

thanks,

greg k-h

Re: [PATCH 1/2] soundwire: add macro to selectively change error levels

[Pierre-Louis Bossart]

On 4/1/21 3:56 PM, Greg KH wrote:
> On Thu, Apr 01, 2021 at 01:43:53PM -0500, Pierre-Louis Bossart wrote:
>>
>>>>> My bigger issue with this is that this macro is crazy.  Why do you need
>>>>> debugging here at all for this type of thing?  That's what ftrace is
>>>>> for, do not sprinkle code with "we got this return value from here!" all
>>>>> over the place like what this does.
>>>>
>>>> We are not sprinkling the code all over the place with any new logs, they
>>>> exist already in the SoundWire code and this patch helps filter them out.
>>>> See e.g. patch 2/2
>>>>
>>>> -			dev_err(&slave->dev,
>>>> -				"Clk Stop type =%d failed: %d\n", type, ret);
>>>> +			sdw_dev_dbg_or_err(&slave->dev, ret != -ENODATA,
>>>> +					   "Clk Stop mode %d type =%d failed: %d\n",
>>>> +					   mode, type, ret);
>>>
>>> You just added a debug log for no reason.
>>
>> The number of logs is lower when dynamic debug is not enabled, and equal
>> when it is. there's no addition.
>>
>> The previous behavior was unconditional dev_err that everyone sees.
>>
>> Now it's dev_err ONLY when the code is NOT -ENODATA, and dev_dgb otherwise,
>> meaning it will seen ONLY be seen IF dynamic debug is enabled for
>> drivers/soundwire/bus.c
>>
>> Allow me to use another example from patch2:
>>
>> -		if (ret == -ENODATA)
>> -			dev_dbg(bus->dev,
>> -				"ClockStopNow Broadcast msg ignored %d", ret);
>> -		else
>> -			dev_err(bus->dev,
>> -				"ClockStopNow Broadcast msg failed %d", ret);
>> +		sdw_dev_dbg_or_err(bus->dev, ret != -ENODATA,
>> +				   "ClockStopNow Broadcast msg failed %d\n", ret);
>>
>> There's no new log, is there?
> 
> No, but that is not what you showed above which was just an error
> message being replaced with both a debug and an error message.

either debug or error message, not both.

> Just drop the debug messages, they are pointless, right?

That's the primary debug tool used with our friends at RedHat and 
Canonical, and that includes remote debug where we don't have access to 
the plaforms. We also have quite a few Bugzilla or github reports from 
community users who can provide the logs of alsa-info and dmesg, but 
that's about it. Those debug messages is what we get as feedback and 
test reports, so we absolutely need them to be 'to the point'.

Maybe to reassure you on the scope of the changes I am suggesting here, 
there is a total of *13* occurrences of dev_dbg() in the SoundWire bus 
code, and they were added in very specific branches where something goes 
boink to help folks like Bard and I figure out what sequence led to the 
problem. I think it's the same on Qualcomm platforms.

In these examples related to the clock stop/restart, a message will be 
generated during pm_runtime suspend/resume sequences and only when 
unexpected behavior is detected, so the total bandwidth used by these 
messages is minimal. It has to be that way, we are currently debugging 
cases where we see those odd behaviors after thousands of suspend/resume 
cycles, the last thing we want is to be swamped with "pointless" 
messages. It's not at all like we are reporting "hello, i have this 
error code", it's rather "this error code should not happen in this 
sequence". in 99% of the cases, the error code is actually not very 
useful, it's where the error occurs that is priceless for debug.