[PATCH v2 01/10] spi: dw: Convert calls to debug to log_*

[Sean Anderson]

On 8/8/20 1:14 AM, Heinrich Schuchardt wrote:
> On 8/7/20 4:43 PM, Sean Anderson wrote:
>> This allows different log levels to be enabled or disabled depending on the
>> desired level of verbosity. In particular, it allows for general debug
>> information to be printed while excluding more verbose logging which may
>> interfere with timing.
>>
>> Signed-off-by: Sean Anderson <seanga2 at gmail.com>
>> ---/
>>
>> Changes in v2:
>> - New
>>
>>  drivers/spi/designware_spi.c | 33 ++++++++++++++++-----------------
>>  1 file changed, 16 insertions(+), 17 deletions(-)
>>
>> diff --git a/drivers/spi/designware_spi.c b/drivers/spi/designware_spi.c
>> index c9b14f9029..f7ea3edaab 100644
>> --- a/drivers/spi/designware_spi.c
>> +++ b/drivers/spi/designware_spi.c
>> @@ -9,6 +9,7 @@
>>   * Copyright (c) 2009, Intel Corporation.
>>   */
>>
>> +#define LOG_CATEGORY UCLASS_SPI
>>  #include <common.h>
>>  #include <log.h>
>>  #include <asm-generic/gpio.h>
>> @@ -139,7 +140,7 @@ static int request_gpio_cs(struct udevice *bus)
>>  		return 0;
>>
>>  	if (ret < 0) {
>> -		printf("Error: %d: Can't get %s gpio!\n", ret, bus->name);
>> +		log_err("Error: %d: Can't get %s gpio!\n", ret, bus->name);
> 
> Thanks for caring to convert this to the more flexible logging.

It was quite difficult to debug without these changes, since turning on
debug statements caused the fifos to over/underflow.

> 
> 	Error: -23: Can't get spi at 53000000 gpio!
> 
> Shouldn't we remove one colon:
> 
> 	Error -23: Can't get spi at 53000000 gpio!

Sure.

>>  		return ret;
>>  	}
>>
>> @@ -148,7 +149,7 @@ static int request_gpio_cs(struct udevice *bus)
>>  				      GPIOD_IS_OUT | GPIOD_IS_OUT_ACTIVE);
>>  	}
>>
>> -	debug("%s: used external gpio for CS management\n", __func__);
>> +	log_info("Using external gpio for CS management\n");
> 
> On systems with CONFIG_LOG=n log_info() messages are always printed. By
> default the function name is not printed in log messages.
> 
> Showing this message to the end-user of the device on every boot
> provides no benefit.
> 
> log_debug() seems more adequate.

Ok. I was generally unsure what log level to default to. README.log
doesn't really make it clear semantically which log levels should be
used.

>>  #endif
>>  	return 0;
>>  }
>> @@ -162,8 +163,7 @@ static int dw_spi_ofdata_to_platdata(struct udevice *bus)
>>  	/* Use 500KHz as a suitable default */
>>  	plat->frequency = dev_read_u32_default(bus, "spi-max-frequency",
>>  					       500000);
>> -	debug("%s: regs=%p max-frequency=%d\n", __func__, plat->regs,
>> -	      plat->frequency);
>> +	log_info("regs=%p max-frequency=%d\n", plat->regs, plat->frequency);
> 
> The output will look like this:
> 
> 	regs=0x1234 max-frequency=2000000
> 
> Such a message appearing on every boot will be irritating for end-users.
> 
> Please, use log_debug() here.

Ok.

> Can we replace 'regs=' by 'SPI@' for all messages?

Sure.

>>
>>  	return request_gpio_cs(bus);
>>  }
>> @@ -196,7 +196,7 @@ static void spi_hw_init(struct dw_spi_priv *priv)
>>  		priv->fifo_len = (fifo == 1) ? 0 : fifo;
>>  		dw_write(priv, DW_SPI_TXFLTR, 0);
>>  	}
>> -	debug("%s: fifo_len=%d\n", __func__, priv->fifo_len);
>> +	log_debug("fifo_len=%d\n", priv->fifo_len);
>>  }
>>
>>  /*
>> @@ -221,8 +221,7 @@ __weak int dw_spi_get_clk(struct udevice *bus, ulong *rate)
>>  	if (!*rate)
>>  		goto err_rate;
>>
>> -	debug("%s: get spi controller clk via device tree: %lu Hz\n",
>> -	      __func__, *rate);
>> +	log_debug("Got spi controller clk via device tree: %lu Hz\n", *rate);
> 
> %s/spi/SPI/

Ok.

>>
>>  	return 0;
>>
>> @@ -247,14 +246,14 @@ static int dw_spi_reset(struct udevice *bus)
>>  		if (ret == -ENOENT || ret == -ENOTSUPP)
>>  			return 0;
>>
>> -		dev_warn(bus, "Can't get reset: %d\n", ret);
>> +		log_warning("Can't get reset: %d\n", ret);
> 
> This message does not tell me that there is a problem with SPI. Please,
> provide a useful text.

Perhaps "Couldn't find or assert reset device configured for SPI"?

>>  		return ret;
>>  	}
>>
>>  	ret = reset_deassert_bulk(&priv->resets);
>>  	if (ret) {
>>  		reset_release_bulk(&priv->resets);
>> -		dev_err(bus, "Failed to reset: %d\n", ret);
>> +		log_err("Failed to reset: %d\n", ret);
> 
> What shall I do when reading a message like:
> 
> 	"Failed to reset: -23".
> 
> Please, provide a more informative text.

Perhaps "SPI: failed to deassert reset (error %d)"?

>>  		return ret;
>>  	}
>>
>> @@ -333,7 +332,7 @@ static void dw_writer(struct dw_spi_priv *priv)
>>  				txw = *(u16 *)(priv->tx);
>>  		}
>>  		dw_write(priv, DW_SPI_DR, txw);
>> -		debug("%s: tx=0x%02x\n", __func__, txw);
>> +		log_content("tx=0x%02x\n", txw);
>>  		priv->tx += priv->bits_per_word >> 3;
>>  	}
>>  }
>> @@ -345,7 +344,7 @@ static void dw_reader(struct dw_spi_priv *priv)
>>
>>  	while (max--) {
>>  		rxw = dw_read(priv, DW_SPI_DR);
>> -		debug("%s: rx=0x%02x\n", __func__, rxw);
>> +		log_content("rx=0x%02x\n", rxw);
>>
>>  		/* Care about rx if the transfer's original "rx" is not null */
>>  		if (priv->rx_end - priv->len) {
>> @@ -400,7 +399,7 @@ static int dw_spi_xfer(struct udevice *dev, unsigned int bitlen,
>>
>>  	/* spi core configured to do 8 bit transfers */
>>  	if (bitlen % 8) {
>> -		debug("Non byte aligned SPI transfer.\n");
>> +		log_err("Non byte aligned SPI transfer.\n");
>>  		return -1;
>>  	}
>>
>> @@ -427,7 +426,7 @@ static int dw_spi_xfer(struct udevice *dev, unsigned int bitlen,
>>  	cr0 |= (priv->tmode << SPI_TMOD_OFFSET);
>>
>>  	priv->len = bitlen >> 3;
>> -	debug("%s: rx=%p tx=%p len=%d [bytes]\n", __func__, rx, tx, priv->len);
>> +	log_debug("rx=%p tx=%p len=%d [bytes]\n", rx, tx, priv->len);
> 
> Please, use log_debug_io() here.

When should log_content/log_io be used? Here, we only log metadata about
the transfer. I would expect this to be a higher log level than (for
example) the actual log of the content as done in dw_reader/writer. In
addition, I am confused as to when log_io should be used over
log_content. The only clear-cut case I can see is perhaps that replacing
dw_write with something like

static inline void dw_write(struct dw_spi_priv *priv, u32 offset, u32 val)
{
	log_io("%x = %x", offset, val);
	__raw_writel(val, priv->regs + offset);
}

Is log_content intended for higher-level interfaces?

>>
>>  	priv->tx = (void *)tx;
>>  	priv->tx_end = priv->tx + priv->len;
>> @@ -437,7 +436,7 @@ static int dw_spi_xfer(struct udevice *dev, unsigned int bitlen,
>>  	/* Disable controller before writing control registers */
>>  	spi_enable_chip(priv, 0);
>>
>> -	debug("%s: cr0=%08x\n", __func__, cr0);
>> +	log_debug("cr0=%08x\n", cr0);
> 
> log_debug_io()

Same comments/questions as above.

--Sean