| Message ID | 20200807144317.282868-2-seanga2@gmail.com |
|---|---|
| State | Superseded |
| Delegated to: | Jagannadha Sutradharudu Teki |
| Headers | show |
| Series | riscv: Add SPI support for Kendryte K210 | expand |
On 8/7/20 4:43 PM, Sean Anderson wrote: [...] > +#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); Can't we use dev_info() / pr_info() , same as the linux kernel does ?
On 8/7/20 10:49 AM, Marek Vasut wrote: > On 8/7/20 4:43 PM, Sean Anderson wrote: > [...] >> +#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); > > Can't we use dev_info() / pr_info() , same as the linux kernel does ? > We can. It doesn't matter much to me. Simon, does U-Boot prefer a particular log style for new code? --Sean
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@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. Error: -23: Can't get spi@53000000 gpio! Shouldn't we remove one colon: Error -23: Can't get spi@53000000 gpio! > 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. > #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. Can we replace 'regs=' by 'SPI@' for all messages? > > 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/ > > 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. > 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. > 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. > > 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() Best regards Heinrich > /* Reprogram cr0 only if changed */ > if (dw_read(priv, DW_SPI_CTRL0) != cr0) > dw_write(priv, DW_SPI_CTRL0, cr0); > @@ -497,8 +496,8 @@ static int dw_spi_set_speed(struct udevice *bus, uint speed) > spi_enable_chip(priv, 1); > > priv->freq = speed; > - debug("%s: regs=%p speed=%d clk_div=%d\n", __func__, priv->regs, > - priv->freq, clk_div); > + log_debug("regs=%p speed=%d clk_div=%d\n", priv->regs, priv->freq, > + clk_div); > > return 0; > } > @@ -513,7 +512,7 @@ static int dw_spi_set_mode(struct udevice *bus, uint mode) > * real transfer function. > */ > priv->mode = mode; > - debug("%s: regs=%p, mode=%d\n", __func__, priv->regs, priv->mode); > + log_debug("regs=%p, mode=%d\n", priv->regs, priv->mode); > > return 0; > } >
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@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"? >> 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
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 <seanga2@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 >
On Fri, 7 Aug 2020 at 08:43, Sean Anderson <seanga2@gmail.com> 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@gmail.com> > --- > > Changes in v2: > - New > > drivers/spi/designware_spi.c | 33 ++++++++++++++++----------------- > 1 file changed, 16 insertions(+), 17 deletions(-) > Reviewed-by: Simon Glass <sjg@chromium.org>
On 8/20/20 3:26 PM, Simon Glass wrote: > On Fri, 7 Aug 2020 at 08:43, Sean Anderson <seanga2@gmail.com> 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@gmail.com> >> --- >> >> Changes in v2: >> - New >> >> drivers/spi/designware_spi.c | 33 ++++++++++++++++----------------- >> 1 file changed, 16 insertions(+), 17 deletions(-) >> > > Reviewed-by: Simon Glass <sjg@chromium.org> NAK, please use dev_dbg() instead.
On Thu, Aug 20, 2020 at 03:36:31PM +0200, Marek Vasut wrote: > On 8/20/20 3:26 PM, Simon Glass wrote: > > On Fri, 7 Aug 2020 at 08:43, Sean Anderson <seanga2@gmail.com> 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@gmail.com> > >> --- > >> > >> Changes in v2: > >> - New > >> > >> drivers/spi/designware_spi.c | 33 ++++++++++++++++----------------- > >> 1 file changed, 16 insertions(+), 17 deletions(-) > >> > > > > Reviewed-by: Simon Glass <sjg@chromium.org> > > NAK, please use dev_dbg() instead. For the record, Marek and I (and Sean) had talked a bit on IRC. These messages being log_xxx() and not dev_xx() instead make the more functionally useful as dev_xxx() converts to printf() and messes with the timing. log_xxx() puts them in the buffer and will not break the timing. Marek objects to the fundamentals that dev_xxx() does not function like it does in Linux (and please correct me if you feel I'm mis-representing your views). This could be solved by plumbing dev_xxx() to use log_xxx() if LOG is enabled automagically. I don't see transitions like that as blocking for this patch, Marek does.
On 8/21/20 2:08 AM, Tom Rini wrote: > On Thu, Aug 20, 2020 at 03:36:31PM +0200, Marek Vasut wrote: >> On 8/20/20 3:26 PM, Simon Glass wrote: >>> On Fri, 7 Aug 2020 at 08:43, Sean Anderson <seanga2@gmail.com> 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@gmail.com> >>>> --- >>>> >>>> Changes in v2: >>>> - New >>>> >>>> drivers/spi/designware_spi.c | 33 ++++++++++++++++----------------- >>>> 1 file changed, 16 insertions(+), 17 deletions(-) >>>> >>> >>> Reviewed-by: Simon Glass <sjg@chromium.org> >> >> NAK, please use dev_dbg() instead. > > For the record, Marek and I (and Sean) had talked a bit on IRC. These > messages being log_xxx() and not dev_xx() instead make the more > functionally useful as dev_xxx() converts to printf() and messes with > the timing. The ones which were printf() before are not impacted, since nothing changes there. The ones which were debug() were compiled out anyway or turned into printf(), so nothing changes there either. In this case , the timing argument simply does not apply. > log_xxx() puts them in the buffer and will not break the > timing. Marek objects to the fundamentals that dev_xxx() does not > function like it does in Linux (and please correct me if you feel I'm > mis-representing your views). I do NOT object to the way dev_err() works, see below. > This could be solved by plumbing > dev_xxx() to use log_xxx() if LOG is enabled automagically. I don't see > transitions like that as blocking for this patch, Marek does. My objection is to yet another new logging facility, which is incompatible with any of the Linux ones. Both pr_() and dev_() we already have in U-Boot, and there is already ongoing conversion attempt to move drivers to dev_(), but now another log_() one appears out of nowhere and starts adding to the already bad mess. Moreover, there is zero information or guideline on which logging primitive to use where. It is likely others are used to those Linux logging facilities, because embedded systems developers likely develop both U-Boot and Linux, likely at the same time. So making the U-Boot more and more incompatible does not help at all. What I do propose is to put the new logging facility underneath the existing logging primitives -- pr_() and dev_() -- if applicable and make the dynamic logging configurable. That way the current mess will be cleaned up. The use of log_() should then only be limited to where no other logging primitives apply.
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); 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"); #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); 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); 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); 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); 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); 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); /* Reprogram cr0 only if changed */ if (dw_read(priv, DW_SPI_CTRL0) != cr0) dw_write(priv, DW_SPI_CTRL0, cr0); @@ -497,8 +496,8 @@ static int dw_spi_set_speed(struct udevice *bus, uint speed) spi_enable_chip(priv, 1); priv->freq = speed; - debug("%s: regs=%p speed=%d clk_div=%d\n", __func__, priv->regs, - priv->freq, clk_div); + log_debug("regs=%p speed=%d clk_div=%d\n", priv->regs, priv->freq, + clk_div); return 0; } @@ -513,7 +512,7 @@ static int dw_spi_set_mode(struct udevice *bus, uint mode) * real transfer function. */ priv->mode = mode; - debug("%s: regs=%p, mode=%d\n", __func__, priv->regs, priv->mode); + log_debug("regs=%p, mode=%d\n", priv->regs, priv->mode); return 0; }
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@gmail.com> --- Changes in v2: - New drivers/spi/designware_spi.c | 33 ++++++++++++++++----------------- 1 file changed, 16 insertions(+), 17 deletions(-)