[PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Miquel Raynal]

Many spi-mem controller drivers have a very similar debug log at the
beginning of their ->exec_op() callback implementation. This debug log is
effectively useful, so let's create one that is complete and concise
enough, so developers no longer need to write their own.

Remove the debug log from individual drivers and propose a common one.

Signed-off-by: Miquel Raynal <miquel.raynal@bootlin.com>
---
 drivers/spi/spi-aspeed-smc.c   |  7 -------
 drivers/spi/spi-mem.c          | 11 +++++++++++
 drivers/spi/spi-mtk-snfi.c     |  3 ---
 drivers/spi/spi-npcm-fiu.c     |  5 -----
 drivers/spi/spi-stm32-qspi.c   |  5 -----
 drivers/spi/spi-zynq-qspi.c    |  4 ----
 drivers/spi/spi-zynqmp-gqspi.c |  4 ----
 7 files changed, 11 insertions(+), 28 deletions(-)

diff --git a/drivers/spi/spi-aspeed-smc.c b/drivers/spi/spi-aspeed-smc.c
index e9beae95dded..62a11142bd63 100644
--- a/drivers/spi/spi-aspeed-smc.c
+++ b/drivers/spi/spi-aspeed-smc.c
@@ -303,13 +303,6 @@ static int do_aspeed_spi_exec_op(struct spi_mem *mem, const struct spi_mem_op *o
 	u32 ctl_val;
 	int ret = 0;
 
-	dev_dbg(aspi->dev,
-		"CE%d %s OP %#x mode:%d.%d.%d.%d naddr:%#x ndummies:%#x len:%#x",
-		chip->cs, op->data.dir == SPI_MEM_DATA_IN ? "read" : "write",
-		op->cmd.opcode, op->cmd.buswidth, op->addr.buswidth,
-		op->dummy.buswidth, op->data.buswidth,
-		op->addr.nbytes, op->dummy.nbytes, op->data.nbytes);
-
 	addr_mode = readl(aspi->regs + CE_CTRL_REG);
 	addr_mode_backup = addr_mode;
 
diff --git a/drivers/spi/spi-mem.c b/drivers/spi/spi-mem.c
index a9f0f47f4759..dc51fe23d2a6 100644
--- a/drivers/spi/spi-mem.c
+++ b/drivers/spi/spi-mem.c
@@ -377,6 +377,17 @@ int spi_mem_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
 	/* Make sure the operation frequency is correct before going futher */
 	spi_mem_adjust_op_freq(mem, (struct spi_mem_op *)op);
 
+	dev_dbg(&mem->spi->dev, "[cmd: 0x%02x][%dB addr: %#8llx][%dB dummy][%4dB data %s] %d%c-%d%c-%d%c-%d%c @ %uHz\n",
+		op->cmd.opcode,
+		op->addr.nbytes, (op->addr.nbytes ? op->addr.val : 0),
+		op->dummy.nbytes,
+		op->data.nbytes, (op->data.nbytes ? (op->data.dir == SPI_MEM_DATA_IN ? " read" : "write") : "     "),
+		op->cmd.buswidth, op->cmd.dtr ? 'D' : 'S',
+		op->addr.buswidth, op->addr.dtr ? 'D' : 'S',
+		op->dummy.buswidth, op->dummy.dtr ? 'D' : 'S',
+		op->data.buswidth, op->data.dtr ? 'D' : 'S',
+		op->max_freq ? op->max_freq : mem->spi->max_speed_hz);
+
 	ret = spi_mem_check_op(op);
 	if (ret)
 		return ret;
diff --git a/drivers/spi/spi-mtk-snfi.c b/drivers/spi/spi-mtk-snfi.c
index fdbea9dffb62..e82ee6dcf498 100644
--- a/drivers/spi/spi-mtk-snfi.c
+++ b/drivers/spi/spi-mtk-snfi.c
@@ -1284,9 +1284,6 @@ static int mtk_snand_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
 {
 	struct mtk_snand *ms = spi_controller_get_devdata(mem->spi->controller);
 
-	dev_dbg(ms->dev, "OP %02x ADDR %08llX@%d:%u DATA %d:%u", op->cmd.opcode,
-		op->addr.val, op->addr.buswidth, op->addr.nbytes,
-		op->data.buswidth, op->data.nbytes);
 	if (mtk_snand_is_page_ops(op)) {
 		if (op->data.dir == SPI_MEM_DATA_IN)
 			return mtk_snand_read_page_cache(ms, op);
diff --git a/drivers/spi/spi-npcm-fiu.c b/drivers/spi/spi-npcm-fiu.c
index 958bab27a081..67cc1d86de42 100644
--- a/drivers/spi/spi-npcm-fiu.c
+++ b/drivers/spi/spi-npcm-fiu.c
@@ -550,11 +550,6 @@ static int npcm_fiu_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
 	int ret = 0;
 	u8 *buf;
 
-	dev_dbg(fiu->dev, "cmd:%#x mode:%d.%d.%d.%d addr:%#llx len:%#x\n",
-		op->cmd.opcode, op->cmd.buswidth, op->addr.buswidth,
-		op->dummy.buswidth, op->data.buswidth, op->addr.val,
-		op->data.nbytes);
-
 	if (fiu->spix_mode || op->addr.nbytes > 4)
 		return -EOPNOTSUPP;
 
diff --git a/drivers/spi/spi-stm32-qspi.c b/drivers/spi/spi-stm32-qspi.c
index 540b6948b24d..9691197bbf5a 100644
--- a/drivers/spi/spi-stm32-qspi.c
+++ b/drivers/spi/spi-stm32-qspi.c
@@ -362,11 +362,6 @@ static int stm32_qspi_send(struct spi_device *spi, const struct spi_mem_op *op)
 	u32 ccr, cr;
 	int timeout, err = 0, err_poll_status = 0;
 
-	dev_dbg(qspi->dev, "cmd:%#x mode:%d.%d.%d.%d addr:%#llx len:%#x\n",
-		op->cmd.opcode, op->cmd.buswidth, op->addr.buswidth,
-		op->dummy.buswidth, op->data.buswidth,
-		op->addr.val, op->data.nbytes);
-
 	cr = readl_relaxed(qspi->io_base + QSPI_CR);
 	cr &= ~CR_PRESC_MASK & ~CR_FSEL;
 	cr |= FIELD_PREP(CR_PRESC_MASK, flash->presc);
diff --git a/drivers/spi/spi-zynq-qspi.c b/drivers/spi/spi-zynq-qspi.c
index 2bd25c75f881..5232483c4a3a 100644
--- a/drivers/spi/spi-zynq-qspi.c
+++ b/drivers/spi/spi-zynq-qspi.c
@@ -540,10 +540,6 @@ static int zynq_qspi_exec_mem_op(struct spi_mem *mem,
 	int err = 0, i;
 	u8 *tmpbuf;
 
-	dev_dbg(xqspi->dev, "cmd:%#x mode:%d.%d.%d.%d\n",
-		op->cmd.opcode, op->cmd.buswidth, op->addr.buswidth,
-		op->dummy.buswidth, op->data.buswidth);
-
 	zynq_qspi_chipselect(mem->spi, true);
 	zynq_qspi_config_op(xqspi, mem->spi, op);
 
diff --git a/drivers/spi/spi-zynqmp-gqspi.c b/drivers/spi/spi-zynqmp-gqspi.c
index d800d79f62a7..1c78713ad61a 100644
--- a/drivers/spi/spi-zynqmp-gqspi.c
+++ b/drivers/spi/spi-zynqmp-gqspi.c
@@ -1067,10 +1067,6 @@ static int zynqmp_qspi_exec_op(struct spi_mem *mem,
 	u16 opcode = op->cmd.opcode;
 	u64 opaddr;
 
-	dev_dbg(xqspi->dev, "cmd:%#x mode:%d.%d.%d.%d\n",
-		op->cmd.opcode, op->cmd.buswidth, op->addr.buswidth,
-		op->dummy.buswidth, op->data.buswidth);
-
 	mutex_lock(&xqspi->op_lock);
 	zynqmp_qspi_config_op(xqspi, op);
 	zynqmp_qspi_chipselect(mem->spi, false);
-- 
2.48.1


______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: [PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Tudor Ambarus]

On 3/5/25 8:11 PM, Miquel Raynal wrote:
> --- a/drivers/spi/spi-mem.c
> +++ b/drivers/spi/spi-mem.c
> @@ -377,6 +377,17 @@ int spi_mem_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
>  	/* Make sure the operation frequency is correct before going futher */
>  	spi_mem_adjust_op_freq(mem, (struct spi_mem_op *)op);
>  
> +	dev_dbg(&mem->spi->dev, "[cmd: 0x%02x][%dB addr: %#8llx][%dB dummy][%4dB data %s] %d%c-%d%c-%d%c-%d%c @ %uHz\n",

Isn't this too "chatty", especially on page program ops? I wouldn't be
surprised if the prints introduce timings that change controller's
behavior. How about using dev_vdbg?

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: [PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Mark Brown]

[-- Attachment #1.1: Type: text/plain, Size: 875 bytes --]

On Thu, Mar 06, 2025 at 09:05:39AM +0000, Tudor Ambarus wrote:
> On 3/5/25 8:11 PM, Miquel Raynal wrote:

> > --- a/drivers/spi/spi-mem.c
> > +++ b/drivers/spi/spi-mem.c
> > @@ -377,6 +377,17 @@ int spi_mem_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
> >  	/* Make sure the operation frequency is correct before going futher */
> >  	spi_mem_adjust_op_freq(mem, (struct spi_mem_op *)op);
> >  
> > +	dev_dbg(&mem->spi->dev, "[cmd: 0x%02x][%dB addr: %#8llx][%dB dummy][%4dB data %s] %d%c-%d%c-%d%c-%d%c @ %uHz\n",

> Isn't this too "chatty", especially on page program ops? I wouldn't be
> surprised if the prints introduce timings that change controller's
> behavior. How about using dev_vdbg?

That, or covert to trace_printk() or even better a trace event - with a
trace event you get really fine grained control and extremely low
overhead.

[-- Attachment #1.2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

[-- Attachment #2: Type: text/plain, Size: 144 bytes --]

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: [PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Miquel Raynal]

Hello Mark & Tudor,

On 13/03/2025 at 22:27:54 GMT, Mark Brown <broonie@kernel.org> wrote:

> On Thu, Mar 06, 2025 at 09:05:39AM +0000, Tudor Ambarus wrote:
>> On 3/5/25 8:11 PM, Miquel Raynal wrote:
>
>> > --- a/drivers/spi/spi-mem.c
>> > +++ b/drivers/spi/spi-mem.c
>> > @@ -377,6 +377,17 @@ int spi_mem_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
>> >  	/* Make sure the operation frequency is correct before going futher */
>> >  	spi_mem_adjust_op_freq(mem, (struct spi_mem_op *)op);
>> >  
>> > + dev_dbg(&mem->spi->dev, "[cmd: 0x%02x][%dB addr: %#8llx][%dB
>> > dummy][%4dB data %s] %d%c-%d%c-%d%c-%d%c @ %uHz\n",
>
>> Isn't this too "chatty", especially on page program ops? I wouldn't be
>> surprised if the prints introduce timings that change controller's
>> behavior. How about using dev_vdbg?
>
> That, or covert to trace_printk() or even better a trace event - with a
> trace event you get really fine grained control and extremely low
> overhead.

I do not think it is too chatty, this is typically a trace that is used
when writing the basic parts of a spi-mem controller. Myself I already
wrote something like that twice, just because during the initial
writing, performance simply does not matter.

Regarding the fear that the chatty log could have an impact: if it does,
it is likely a bug of the driver or a severe controller limitation
IMO. Anyway, the point of having a _dbg call is to allow
enabling/disabling the log if it is too time consuming.

I'd say that for this particular purpose I do not thing that trace
printks or events would really fit. As a developer, I'd definitely
always change the function calls to some direct printk calls in this
case. The verbose debug alternative seduced me though, so if that's okay
for you, I'll switch to dev_vdgb() as suggested by Tudor, which honestly
feels like a seducing alternative.

Cheers,
Miquèl

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: [PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Mark Brown]

[-- Attachment #1.1: Type: text/plain, Size: 729 bytes --]

On Wed, Mar 19, 2025 at 05:56:28PM +0100, Miquel Raynal wrote:

> I'd say that for this particular purpose I do not thing that trace
> printks or events would really fit. As a developer, I'd definitely
> always change the function calls to some direct printk calls in this
> case. The verbose debug alternative seduced me though, so if that's okay
> for you, I'll switch to dev_vdgb() as suggested by Tudor, which honestly
> feels like a seducing alternative.

That's fine for me.  I do have to say that I tend to end up doing the
opposite of you and adding tracepoints to code I'm doing much with, they
work so much better so long as you can get the buffer off the device.
Low overhead, much bigger lookback and better tooling.

[-- Attachment #1.2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

[-- Attachment #2: Type: text/plain, Size: 144 bytes --]

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: [PATCH] spi: spi-mem: Introduce a default ->exec_op() debug log

[Miquel Raynal]

On 19/03/2025 at 17:39:50 GMT, Mark Brown <broonie@kernel.org> wrote:

> On Wed, Mar 19, 2025 at 05:56:28PM +0100, Miquel Raynal wrote:
>
>> I'd say that for this particular purpose I do not thing that trace
>> printks or events would really fit. As a developer, I'd definitely
>> always change the function calls to some direct printk calls in this
>> case. The verbose debug alternative seduced me though, so if that's okay
>> for you, I'll switch to dev_vdgb() as suggested by Tudor, which honestly
>> feels like a seducing alternative.
>
> That's fine for me.  I do have to say that I tend to end up doing the
> opposite of you and adding tracepoints to code I'm doing much with, they
> work so much better so long as you can get the buffer off the device.
> Low overhead, much bigger lookback and better tooling.

Interesting. Maybe I should consider playing a bit more with those. It's
true that the fact that you need to load the trace buffer off is always
a bit painful, but as long as network works, that should not be that
much of a burden once it's been set up.

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/