On 8/8/20 1:07 PM, Sean Anderson wrote:
> 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 <sean...@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@53000000 gpio!
>>
>> Shouldn't we remove one colon:
>>
>> Error -23: Can't get spi@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"?
or
"Failed to find reset for SPI"
if you want to keep it short.
>
>>> 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)"?
or
Failed to reset SPI (err %d)
to keep it short.
>
>>> 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
>
When debugging you can easily be overwhelmed by thousands of messages
when a message is written per sector read from a device.
So I think log_debug() is fine for messages occurring only once during
initialization. But for messages that would otherwise flood the screen
log_content() or log_io() should be used. Cf. drivers/mtd/spi/sandbox.c.
LOGL_DEBUG, /* Basic debug-level message */
LOGL_DEBUG_CONTENT, /* Debug message showing full message content */
LOGL_DEBUG_IO, /* Debug message showing hardware I/O access */
Sounds like log_content() would be fine if written once per read.
Best regards
Heinrich
> 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
>
