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

Commit Message

Miquel Raynal March 5, 2025, 8:11 p.m. UTC

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 <[e-mail]>
---
 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(-)

Comments

Tudor Ambarus March 6, 2025, 9:05 a.m. UTC | #1

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?

Patch

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);