[PATCH] spi: spi-mem: Trace exec_op

[PATCH] spi: spi-mem: Trace exec_op

[Sean Anderson]

The spi subsystem has tracing, which is very convenient when debugging
problems. Add tracing for spi-mem too so that accesses that skip the spi
subsystem can still be seen.

The format is roughly based on the existing spi tracing. We don't bother
tracing the op's address because the tracing happens while the memory is
locked, so there can be no confusion about the matching of start and
stop. The conversion of cmd/addr/dummy to an array is directly analogous
to the conversion in the latter half of spi_mem_exec_op.

Signed-off-by: Sean Anderson <sean.anderson@linux.dev>
---

 MAINTAINERS                    |   1 +
 drivers/spi/spi-mem.c          |   5 ++
 include/trace/events/spi-mem.h | 106 +++++++++++++++++++++++++++++++++
 3 files changed, 112 insertions(+)
 create mode 100644 include/trace/events/spi-mem.h

diff --git a/MAINTAINERS b/MAINTAINERS
index b45db73e55df..a6c4e0f65818 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -24204,6 +24204,7 @@ T:	git git://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git
 F:	Documentation/devicetree/bindings/spi/
 F:	Documentation/spi/
 F:	drivers/spi/
+F:	include/trace/events/spi*
 F:	include/linux/spi/
 F:	include/uapi/linux/spi/
 F:	tools/spi/
diff --git a/drivers/spi/spi-mem.c b/drivers/spi/spi-mem.c
index 064b99204d9a..c8b2add2640e 100644
--- a/drivers/spi/spi-mem.c
+++ b/drivers/spi/spi-mem.c
@@ -12,6 +12,9 @@
 #include <linux/spi/spi-mem.h>
 #include <linux/sched/task_stack.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/spi-mem.h>
+
 #include "internals.h"
 
 #define SPI_MEM_MAX_BUSWIDTH		8
@@ -403,7 +406,9 @@ int spi_mem_exec_op(struct spi_mem *mem, const struct spi_mem_op *op)
 		if (ret)
 			return ret;
 
+		trace_spi_mem_start_op(mem, op);
 		ret = ctlr->mem_ops->exec_op(mem, op);
+		trace_spi_mem_stop_op(mem, op);
 
 		spi_mem_access_end(mem);
 
diff --git a/include/trace/events/spi-mem.h b/include/trace/events/spi-mem.h
new file mode 100644
index 000000000000..e97c2c417233
--- /dev/null
+++ b/include/trace/events/spi-mem.h
@@ -0,0 +1,106 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM spi-mem
+
+#undef TRACE_SYSTEM_VAR
+#define TRACE_SYSTEM_VAR spi_mem
+
+#if !defined(_TRACE_SPI_MEM_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SPI_MEM_H
+
+#include <linux/tracepoint.h>
+#include <linux/spi/spi-mem.h>
+
+#define decode_dtr(dtr) \
+	__print_symbolic(dtr, \
+		{ 0, "S" }, \
+		{ 1, "D" })
+
+TRACE_EVENT(spi_mem_start_op,
+	TP_PROTO(struct spi_mem *mem, const struct spi_mem_op *op),
+	TP_ARGS(mem, op),
+
+	TP_STRUCT__entry(
+		__string(name, mem->name)
+		__dynamic_array(u8, op, 1 + op->addr.nbytes + op->dummy.nbytes)
+		__dynamic_array(u8, data, op->data.dir == SPI_MEM_DATA_OUT ?
+					  min(op->data.nbytes, 64) : 0)
+		__field(u32, data_len)
+		__field(u32, max_freq)
+		__field(u8, cmd_buswidth)
+		__field(bool, cmd_dtr)
+		__field(u8, addr_buswidth)
+		__field(bool, addr_dtr)
+		__field(u8, dummy_nbytes)
+		__field(u8, data_buswidth)
+		__field(bool, data_dtr)
+	),
+
+	TP_fast_assign(
+		int i;
+
+		__assign_str(name, mem->name);
+		__entry->max_freq = op->max_freq ?: mem->spi->max_speed_hz;
+
+		__entry->cmd_buswidth = op->cmd.buswidth;
+		__entry->cmd_dtr = op->cmd.dtr;
+		*((u8 *)__get_dynamic_array(op)) = op->cmd.opcode;
+
+		__entry->addr_buswidth = op->addr.buswidth;
+		__entry->addr_dtr = op->addr.dtr;
+		for (i = 0; i < op->addr.nbytes; i++)
+			((u8 *)__get_dynamic_array(op))[i + 1] =
+				op->addr.val >> (8 * (op->addr.nbytes - i - 1));
+
+		memset(((u8 *)__get_dynamic_array(op)) + op->addr.nbytes + 1,
+		       0xff, op->dummy.nbytes);
+
+		__entry->data_len = op->data.nbytes;
+		__entry->data_buswidth = op->data.buswidth;
+		__entry->data_dtr = op->data.dtr;
+		if (op->data.dir == SPI_MEM_DATA_OUT)
+			memcpy(__get_dynamic_array(data), op->data.buf.out,
+			       __get_dynamic_array_len(data));
+	),
+
+	TP_printk("%s %u%s-%u%s-%u%s @%u Hz op=[%*phD] len=%u tx=[%*phD]",
+		__get_str(name),
+		__entry->cmd_buswidth, decode_dtr(__entry->cmd_dtr),
+		__entry->addr_buswidth, decode_dtr(__entry->addr_dtr),
+		__entry->data_buswidth, decode_dtr(__entry->data_dtr),
+		__entry->max_freq,
+		__get_dynamic_array_len(op), __get_dynamic_array(op),
+		__entry->data_len,
+		__get_dynamic_array_len(data), __get_dynamic_array(data))
+);
+
+TRACE_EVENT(spi_mem_stop_op,
+	TP_PROTO(struct spi_mem *mem, const struct spi_mem_op *op),
+	TP_ARGS(mem, op),
+
+	TP_STRUCT__entry(
+		__string(name, mem->name)
+		__dynamic_array(u8, data, op->data.dir == SPI_MEM_DATA_IN ?
+					  min(op->data.nbytes, 64) : 0)
+		__field(u32, data_len)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, mem->name);
+		__entry->data_len = op->data.nbytes;
+		if (op->data.dir == SPI_MEM_DATA_IN)
+			memcpy(__get_dynamic_array(data), op->data.buf.in,
+			       __get_dynamic_array_len(data));
+	),
+
+	TP_printk("%s len=%u rx=[%*phD]",
+		__get_str(name),
+		__entry->data_len,
+		__get_dynamic_array_len(data), __get_dynamic_array(data))
+);
+
+
+#endif /* _TRACE_SPI_MEM_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.35.1.1320.gc452695387.dirty

Re: [PATCH] spi: spi-mem: Trace exec_op

[kernel test robot]

Hi Sean,

kernel test robot noticed the following build errors:

[auto build test ERROR on broonie-spi/for-next]
[also build test ERROR on linus/master v6.18-rc2 next-20251021]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Sean-Anderson/spi-spi-mem-Trace-exec_op/20251021-030524
base:   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git for-next
patch link:    https://lore.kernel.org/r/20251020190333.1431664-1-sean.anderson%40linux.dev
patch subject: [PATCH] spi: spi-mem: Trace exec_op
config: x86_64-buildonly-randconfig-003-20251021 (https://download.01.org/0day-ci/archive/20251021/202510211959.kVCWipPy-lkp@intel.com/config)
compiler: clang version 20.1.8 (https://github.com/llvm/llvm-project 87f0227cb60147a26a1eeb4fb06e3b505e9c7261)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20251021/202510211959.kVCWipPy-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202510211959.kVCWipPy-lkp@intel.com/

All errors (new ones prefixed by >>):

   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:132:
   In file included from include/trace/trace_events.h:468:
>> include/trace/events/spi-mem.h:42:22: error: too many arguments provided to function-like macro invocation
      42 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:132:
   In file included from include/trace/trace_events.h:468:
>> include/trace/events/spi-mem.h:42:3: error: use of undeclared identifier '__assign_str'
      42 |                 __assign_str(name, mem->name);
         |                 ^
   include/trace/events/spi-mem.h:89:22: error: too many arguments provided to function-like macro invocation
      89 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:132:
   In file included from include/trace/trace_events.h:468:
   include/trace/events/spi-mem.h:89:3: error: use of undeclared identifier '__assign_str'
      89 |                 __assign_str(name, mem->name);
         |                 ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:132:
   In file included from include/trace/trace_events.h:523:
>> include/trace/events/spi-mem.h:42:22: error: too many arguments provided to function-like macro invocation
      42 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:132:
   In file included from include/trace/trace_events.h:523:
   include/trace/events/spi-mem.h:89:22: error: too many arguments provided to function-like macro invocation
      89 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:133:
   In file included from include/trace/perf.h:110:
>> include/trace/events/spi-mem.h:42:22: error: too many arguments provided to function-like macro invocation
      42 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:133:
   In file included from include/trace/perf.h:110:
>> include/trace/events/spi-mem.h:42:3: error: use of undeclared identifier '__assign_str'
      42 |                 __assign_str(name, mem->name);
         |                 ^
   include/trace/events/spi-mem.h:89:22: error: too many arguments provided to function-like macro invocation
      89 |                 __assign_str(name, mem->name);
         |                                    ^
   include/trace/stages/stage6_event_callback.h:34:9: note: macro '__assign_str' defined here
      34 | #define __assign_str(dst)                                               \
         |         ^
   In file included from drivers/spi/spi-mem.c:16:
   In file included from include/trace/events/spi-mem.h:106:
   In file included from include/trace/define_trace.h:133:
   In file included from include/trace/perf.h:110:
   include/trace/events/spi-mem.h:89:3: error: use of undeclared identifier '__assign_str'
      89 |                 __assign_str(name, mem->name);
         |                 ^
   10 errors generated.


vim +42 include/trace/events/spi-mem.h

    13	
    14	#define decode_dtr(dtr) \
    15		__print_symbolic(dtr, \
    16			{ 0, "S" }, \
    17			{ 1, "D" })
    18	
    19	TRACE_EVENT(spi_mem_start_op,
    20		TP_PROTO(struct spi_mem *mem, const struct spi_mem_op *op),
    21		TP_ARGS(mem, op),
    22	
    23		TP_STRUCT__entry(
    24			__string(name, mem->name)
    25			__dynamic_array(u8, op, 1 + op->addr.nbytes + op->dummy.nbytes)
    26			__dynamic_array(u8, data, op->data.dir == SPI_MEM_DATA_OUT ?
    27						  min(op->data.nbytes, 64) : 0)
    28			__field(u32, data_len)
    29			__field(u32, max_freq)
    30			__field(u8, cmd_buswidth)
    31			__field(bool, cmd_dtr)
    32			__field(u8, addr_buswidth)
    33			__field(bool, addr_dtr)
    34			__field(u8, dummy_nbytes)
    35			__field(u8, data_buswidth)
    36			__field(bool, data_dtr)
    37		),
    38	
    39		TP_fast_assign(
    40			int i;
    41	
  > 42			__assign_str(name, mem->name);
    43			__entry->max_freq = op->max_freq ?: mem->spi->max_speed_hz;
    44	
    45			__entry->cmd_buswidth = op->cmd.buswidth;
    46			__entry->cmd_dtr = op->cmd.dtr;
    47			*((u8 *)__get_dynamic_array(op)) = op->cmd.opcode;
    48	
    49			__entry->addr_buswidth = op->addr.buswidth;
    50			__entry->addr_dtr = op->addr.dtr;
    51			for (i = 0; i < op->addr.nbytes; i++)
    52				((u8 *)__get_dynamic_array(op))[i + 1] =
    53					op->addr.val >> (8 * (op->addr.nbytes - i - 1));
    54	
    55			memset(((u8 *)__get_dynamic_array(op)) + op->addr.nbytes + 1,
    56			       0xff, op->dummy.nbytes);
    57	
    58			__entry->data_len = op->data.nbytes;
    59			__entry->data_buswidth = op->data.buswidth;
    60			__entry->data_dtr = op->data.dtr;
    61			if (op->data.dir == SPI_MEM_DATA_OUT)
    62				memcpy(__get_dynamic_array(data), op->data.buf.out,
    63				       __get_dynamic_array_len(data));
    64		),
    65	
    66		TP_printk("%s %u%s-%u%s-%u%s @%u Hz op=[%*phD] len=%u tx=[%*phD]",
    67			__get_str(name),
    68			__entry->cmd_buswidth, decode_dtr(__entry->cmd_dtr),
    69			__entry->addr_buswidth, decode_dtr(__entry->addr_dtr),
    70			__entry->data_buswidth, decode_dtr(__entry->data_dtr),
    71			__entry->max_freq,
    72			__get_dynamic_array_len(op), __get_dynamic_array(op),
    73			__entry->data_len,
    74			__get_dynamic_array_len(data), __get_dynamic_array(data))
    75	);
    76	
    77	TRACE_EVENT(spi_mem_stop_op,
    78		TP_PROTO(struct spi_mem *mem, const struct spi_mem_op *op),
    79		TP_ARGS(mem, op),
    80	
    81		TP_STRUCT__entry(
    82			__string(name, mem->name)
    83			__dynamic_array(u8, data, op->data.dir == SPI_MEM_DATA_IN ?
    84						  min(op->data.nbytes, 64) : 0)
    85			__field(u32, data_len)
    86		),
    87	
    88		TP_fast_assign(
    89			__assign_str(name, mem->name);
    90			__entry->data_len = op->data.nbytes;
    91			if (op->data.dir == SPI_MEM_DATA_IN)
    92				memcpy(__get_dynamic_array(data), op->data.buf.in,
    93				       __get_dynamic_array_len(data));
    94		),
    95	
    96		TP_printk("%s len=%u rx=[%*phD]",
    97			__get_str(name),
    98			__entry->data_len,
    99			__get_dynamic_array_len(data), __get_dynamic_array(data))
   100	);
   101	
   102	
   103	#endif /* _TRACE_SPI_MEM_H */
   104	
   105	/* This part must be outside protection */
 > 106	#include <trace/define_trace.h>

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH] spi: spi-mem: Trace exec_op

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 282 bytes --]

On Mon, Oct 20, 2025 at 03:03:33PM -0400, Sean Anderson wrote:
> The spi subsystem has tracing, which is very convenient when debugging
> problems. Add tracing for spi-mem too so that accesses that skip the spi
> subsystem can still be seen.

The change here looks reasonable FWIW.

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

Re: [PATCH] spi: spi-mem: Trace exec_op

[Mark Brown]

On Mon, 20 Oct 2025 15:03:33 -0400, Sean Anderson wrote:
> The spi subsystem has tracing, which is very convenient when debugging
> problems. Add tracing for spi-mem too so that accesses that skip the spi
> subsystem can still be seen.
> 
> The format is roughly based on the existing spi tracing. We don't bother
> tracing the op's address because the tracing happens while the memory is
> locked, so there can be no confusion about the matching of start and
> stop. The conversion of cmd/addr/dummy to an array is directly analogous
> to the conversion in the latter half of spi_mem_exec_op.
> 
> [...]

Applied to

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git for-next

Thanks!

[1/1] spi: spi-mem: Trace exec_op
      commit: 77a58ba7c64ccca20616aa03599766ccb0d1a330

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark