[PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[Jonathan Cormier]

Add trace events to help debug and measure the speed of the
communication channel.

Add parsing of the messages types but I am not sure how to parse the
flags, since the REQ and RESP flags conflict. Left as seperate commit to
make it easier to drop or make changes depending on comments.  The two
commits should squash easily.

Nishanth Menon and Vignesh Raghavendra requested I send this patch
upstream.

Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
---
Jonathan Cormier (2):
      firmware: ti_sci: Add trace events
      firmware: ti_sci: trace: Decode message types

 MAINTAINERS                     |   1 +
 drivers/firmware/Makefile       |   3 +
 drivers/firmware/ti_sci.c       |  11 +++
 drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
 4 files changed, 161 insertions(+)
---
base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca

Best regards,
-- 
Jonathan Cormier <jcormier@criticallink.com>

[PATCH 1/2] firmware: ti_sci: Add trace events

[Jonathan Cormier]

Add TI sci trace events to help to debug and measure the speed of the
communication channel. The xfer_begin and xfer_end calls can be used
to time how long a transfer takes. The rx_callback and msg_dump trace
events help track the data that gets returned.

Based on tracing done in ARM SCMI

Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
---
 MAINTAINERS                     |  1 +
 drivers/firmware/Makefile       |  3 ++
 drivers/firmware/ti_sci.c       | 11 ++++++
 drivers/firmware/ti_sci_trace.h | 87 +++++++++++++++++++++++++++++++++++++++++
 4 files changed, 102 insertions(+)

diff --git a/MAINTAINERS b/MAINTAINERS
index fad6cb025a1918beec113b576cf28b76151745ef..a6fac706feceedfc5039ec07de954ac35a9af848 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -24631,6 +24631,7 @@ F:	drivers/pmdomain/ti/ti_sci_pm_domains.c
 F:	include/dt-bindings/soc/ti,sci_pm_domain.h
 F:	include/linux/soc/ti/ti_sci_inta_msi.h
 F:	include/linux/soc/ti/ti_sci_protocol.h
+F:	include/trace/events/ti_sci.h
 
 TEXAS INSTRUMENTS' TMP117 TEMPERATURE SENSOR DRIVER
 M:	Puranjay Mohan <puranjay@kernel.org>
diff --git a/drivers/firmware/Makefile b/drivers/firmware/Makefile
index 4ddec2820c96fa9be012e89dac3038968bb67039..a055c53bdfa9e5c64adb4e20a9ca6c6661d80297 100644
--- a/drivers/firmware/Makefile
+++ b/drivers/firmware/Makefile
@@ -2,6 +2,9 @@
 #
 # Makefile for the linux kernel.
 #
+
+ccflags-y += -I$(src)			# needed for trace events
+
 obj-$(CONFIG_ARM_SCPI_PROTOCOL)	+= arm_scpi.o
 obj-$(CONFIG_ARM_SDE_INTERFACE)	+= arm_sdei.o
 obj-$(CONFIG_DMI)		+= dmi_scan.o
diff --git a/drivers/firmware/ti_sci.c b/drivers/firmware/ti_sci.c
index ae5fd1936ad322e5e3a94897cc042f6548f919e6..87b1330305939bb6b19bbdaa594b17b266092a34 100644
--- a/drivers/firmware/ti_sci.c
+++ b/drivers/firmware/ti_sci.c
@@ -127,6 +127,9 @@ struct ti_sci_info {
 #define cl_to_ti_sci_info(c)	container_of(c, struct ti_sci_info, cl)
 #define handle_to_ti_sci_info(h) container_of(h, struct ti_sci_info, handle)
 
+#define CREATE_TRACE_POINTS
+#include "ti_sci_trace.h"
+
 #ifdef CONFIG_DEBUG_FS
 
 /**
@@ -269,6 +272,9 @@ static void ti_sci_rx_callback(struct mbox_client *cl, void *m)
 		return;
 	}
 
+	trace_ti_sci_rx_callback(hdr, 0);
+	trace_ti_sci_msg_dump(hdr, xfer);
+
 	ti_sci_dump_header_dbg(dev, hdr);
 	/* Take a copy to the rx buffer.. */
 	memcpy(xfer->xfer_buf, mbox_msg->buf, xfer->rx_len);
@@ -402,6 +408,9 @@ static inline int ti_sci_do_xfer(struct ti_sci_info *info,
 	int timeout;
 	struct device *dev = info->dev;
 	bool done_state = true;
+	struct ti_sci_msg_hdr *hdr = (struct ti_sci_msg_hdr *)xfer->tx_message.buf;
+
+	trace_ti_sci_xfer_begin(hdr, 0);
 
 	ret = mbox_send_message(info->chan_tx, &xfer->tx_message);
 	if (ret < 0)
@@ -437,6 +446,8 @@ static inline int ti_sci_do_xfer(struct ti_sci_info *info,
 	 */
 	mbox_client_txdone(info->chan_tx, ret);
 
+	trace_ti_sci_xfer_end(hdr, ret);
+
 	return ret;
 }
 
diff --git a/drivers/firmware/ti_sci_trace.h b/drivers/firmware/ti_sci_trace.h
new file mode 100644
index 0000000000000000000000000000000000000000..7f99c41ea08aec6cf64d601576cad29b14c6ad5b
--- /dev/null
+++ b/drivers/firmware/ti_sci_trace.h
@@ -0,0 +1,87 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM ti_sci
+
+#if !defined(_TRACE_TI_SCI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_TI_SCI_H
+
+#include <linux/tracepoint.h>
+
+
+DECLARE_EVENT_CLASS(ti_sci_hdr_event_class,
+	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
+	TP_ARGS(hdr, status),
+
+	TP_STRUCT__entry(
+		__field(u16, type)
+		__field(u8, host)
+		__field(u8, seq)
+		__field(u32, flags)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->type = hdr->type;
+		__entry->host = hdr->host;
+		__entry->seq = hdr->seq;
+		__entry->flags = hdr->flags;
+		__entry->status = status;
+	),
+
+	TP_printk("type=%04X host=%02X seq=%02X flags=%08X status=%d",
+		__entry->type, __entry->host, __entry->seq, __entry->flags, __entry->status)
+);
+
+DEFINE_EVENT(ti_sci_hdr_event_class,
+	ti_sci_xfer_begin,
+	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
+	TP_ARGS(hdr, status)
+);
+
+DEFINE_EVENT(ti_sci_hdr_event_class,
+	ti_sci_rx_callback,
+	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
+	TP_ARGS(hdr, status)
+);
+
+DEFINE_EVENT(ti_sci_hdr_event_class,
+	ti_sci_xfer_end,
+	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
+	TP_ARGS(hdr, status)
+);
+
+
+TRACE_EVENT(ti_sci_msg_dump,
+	TP_PROTO(struct ti_sci_msg_hdr *hdr, struct ti_sci_xfer *xfer),
+	TP_ARGS(hdr, xfer),
+
+	TP_STRUCT__entry(
+		__field(u16, type)
+		__field(u8, host)
+		__field(u8, seq)
+		__field(u32, flags)
+		__field(size_t, len)
+		__dynamic_array(unsigned char, cmd, xfer->rx_len)
+	),
+
+	TP_fast_assign(
+		__entry->type = hdr->type;
+		__entry->host = hdr->host;
+		__entry->seq = hdr->seq;
+		__entry->flags = hdr->flags;
+		__entry->len = xfer->rx_len;
+		memcpy(__get_dynamic_array(cmd), xfer->xfer_buf, __entry->len);
+	),
+
+	TP_printk("type=%04X host=%02X seq=%02X flags=%08X data=%s",
+		__entry->type, __entry->host, __entry->seq, __entry->flags,
+		__print_hex_str(__get_dynamic_array(cmd), __entry->len))
+);
+#endif /* _TRACE_TI_SCI_H */
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE ti_sci_trace
+#include <trace/define_trace.h>

-- 
2.43.0

[PATCH 2/2] firmware: ti_sci: trace: Decode message types

[Jonathan Cormier]

Make debugging easier by decoding the ti_sci message types

Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
---
 drivers/firmware/ti_sci_trace.h | 69 ++++++++++++++++++++++++++++++++++++++---
 1 file changed, 64 insertions(+), 5 deletions(-)

diff --git a/drivers/firmware/ti_sci_trace.h b/drivers/firmware/ti_sci_trace.h
index 7f99c41ea08aec6cf64d601576cad29b14c6ad5b..88a159e13907d7d7806b312a2ad3103c106d1972 100644
--- a/drivers/firmware/ti_sci_trace.h
+++ b/drivers/firmware/ti_sci_trace.h
@@ -7,6 +7,63 @@
 
 #include <linux/tracepoint.h>
 
+#define show_ti_sci_msg_type(x) \
+	__print_symbolic(x, \
+		{ TI_SCI_MSG_ENABLE_WDT, "ENABLE_WDT" }, \
+		{ TI_SCI_MSG_WAKE_RESET, "WAKE_RESET" }, \
+		{ TI_SCI_MSG_VERSION, "VERSION" }, \
+		{ TI_SCI_MSG_WAKE_REASON, "WAKE_REASON" }, \
+		{ TI_SCI_MSG_GOODBYE, "GOODBYE" }, \
+		{ TI_SCI_MSG_SYS_RESET, "SYS_RESET" }, \
+		{ TI_SCI_MSG_QUERY_FW_CAPS, "QUERY_FW_CAPS" }, \
+		{ TI_SCI_MSG_SET_DEVICE_STATE, "SET_DEVICE_STATE" }, \
+		{ TI_SCI_MSG_GET_DEVICE_STATE, "GET_DEVICE_STATE" }, \
+		{ TI_SCI_MSG_SET_DEVICE_RESETS, "SET_DEVICE_RESETS" }, \
+		{ TI_SCI_MSG_SET_CLOCK_STATE, "SET_CLOCK_STATE" }, \
+		{ TI_SCI_MSG_GET_CLOCK_STATE, "GET_CLOCK_STATE" }, \
+		{ TI_SCI_MSG_SET_CLOCK_PARENT, "SET_CLOCK_PARENT" }, \
+		{ TI_SCI_MSG_GET_CLOCK_PARENT, "GET_CLOCK_PARENT" }, \
+		{ TI_SCI_MSG_GET_NUM_CLOCK_PARENTS, "GET_NUM_CLOCK_PARENTS" }, \
+		{ TI_SCI_MSG_SET_CLOCK_FREQ, "SET_CLOCK_FREQ" }, \
+		{ TI_SCI_MSG_QUERY_CLOCK_FREQ, "QUERY_CLOCK_FREQ" }, \
+		{ TI_SCI_MSG_GET_CLOCK_FREQ, "GET_CLOCK_FREQ" }, \
+		{ TI_SCI_MSG_PREPARE_SLEEP, "PREPARE_SLEEP" }, \
+		{ TI_SCI_MSG_LPM_WAKE_REASON, "LPM_WAKE_REASON" }, \
+		{ TI_SCI_MSG_SET_IO_ISOLATION, "SET_IO_ISOLATION" }, \
+		{ TI_SCI_MSG_LPM_SET_DEVICE_CONSTRAINT, "LPM_SET_DEVICE_CONSTRAINT" }, \
+		{ TI_SCI_MSG_LPM_SET_LATENCY_CONSTRAINT, "LPM_SET_LATENCY_CONSTRAINT" }, \
+		{ TI_SCI_MSG_GET_RESOURCE_RANGE, "GET_RESOURCE_RANGE" }, \
+		{ TI_SCI_MSG_SET_IRQ, "SET_IRQ" }, \
+		{ TI_SCI_MSG_FREE_IRQ, "FREE_IRQ" }, \
+		{ TI_SCI_MSG_RM_RING_ALLOCATE, "RM_RING_ALLOCATE" }, \
+		{ TI_SCI_MSG_RM_RING_FREE, "RM_RING_FREE" }, \
+		{ TI_SCI_MSG_RM_RING_RECONFIG, "RM_RING_RECONFIG" }, \
+		{ TI_SCI_MSG_RM_RING_RESET, "RM_RING_RESET" }, \
+		{ TI_SCI_MSG_RM_RING_CFG, "RM_RING_CFG" }, \
+		{ TI_SCI_MSG_RM_PSIL_PAIR, "RM_PSIL_PAIR" }, \
+		{ TI_SCI_MSG_RM_PSIL_UNPAIR, "RM_PSIL_UNPAIR" }, \
+		{ TI_SCI_MSG_RM_UDMAP_TX_ALLOC, "RM_UDMAP_TX_ALLOC" }, \
+		{ TI_SCI_MSG_RM_UDMAP_TX_FREE, "RM_UDMAP_TX_FREE" }, \
+		{ TI_SCI_MSG_RM_UDMAP_RX_ALLOC, "RM_UDMAP_RX_ALLOC" }, \
+		{ TI_SCI_MSG_RM_UDMAP_RX_FREE, "RM_UDMAP_RX_FREE" }, \
+		{ TI_SCI_MSG_RM_UDMAP_FLOW_CFG, "RM_UDMAP_FLOW_CFG" }, \
+		{ TI_SCI_MSG_RM_UDMAP_OPT_FLOW_CFG, "RM_UDMAP_OPT_FLOW_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_TX_CH_CFG, "RM_UDMAP_TX_CH_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_TX_CH_GET_CFG, "RM_UDMAP_TX_CH_GET_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_RX_CH_CFG, "RM_UDMAP_RX_CH_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_RX_CH_GET_CFG, "RM_UDMAP_RX_CH_GET_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_FLOW_CFG, "RM_UDMAP_FLOW_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_FLOW_SIZE_THRESH_CFG, "RM_UDMAP_FLOW_SIZE_THRESH_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_FLOW_GET_CFG, "RM_UDMAP_FLOW_GET_CFG" }, \
+		{ TISCI_MSG_RM_UDMAP_FLOW_SIZE_THRESH_GET_CFG, "RM_UDMAP_FLOW_SIZE_THRESH_GET_CFG" }, \
+		{ TI_SCI_MSG_PROC_REQUEST, "PROC_REQUEST" }, \
+		{ TI_SCI_MSG_PROC_RELEASE, "PROC_RELEASE" }, \
+		{ TI_SCI_MSG_PROC_HANDOVER, "PROC_HANDOVER" }, \
+		{ TI_SCI_MSG_SET_CONFIG, "SET_CONFIG" }, \
+		{ TI_SCI_MSG_SET_CTRL, "SET_CTRL" }, \
+		{ TI_SCI_MSG_GET_STATUS, "GET_STATUS" } \
+	)
+
 
 DECLARE_EVENT_CLASS(ti_sci_hdr_event_class,
 	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
@@ -28,8 +85,9 @@ DECLARE_EVENT_CLASS(ti_sci_hdr_event_class,
 		__entry->status = status;
 	),
 
-	TP_printk("type=%04X host=%02X seq=%02X flags=%08X status=%d",
-		__entry->type, __entry->host, __entry->seq, __entry->flags, __entry->status)
+	TP_printk("type=%s host=%02X seq=%02X flags=%08X status=%d",
+		show_ti_sci_msg_type(__entry->type), __entry->host,
+		__entry->seq, __entry->flags, __entry->status)
 );
 
 DEFINE_EVENT(ti_sci_hdr_event_class,
@@ -73,9 +131,10 @@ TRACE_EVENT(ti_sci_msg_dump,
 		memcpy(__get_dynamic_array(cmd), xfer->xfer_buf, __entry->len);
 	),
 
-	TP_printk("type=%04X host=%02X seq=%02X flags=%08X data=%s",
-		__entry->type, __entry->host, __entry->seq, __entry->flags,
-		__print_hex_str(__get_dynamic_array(cmd), __entry->len))
+	TP_printk("type=%s host=%02X seq=%02X flags=%08X data=%s",
+		show_ti_sci_msg_type(__entry->type), __entry->host,
+		__entry->seq, __entry->flags,
+		__print_hex(__get_dynamic_array(cmd), __entry->len))
 );
 #endif /* _TRACE_TI_SCI_H */
 

-- 
2.43.0

Re: [PATCH 1/2] firmware: ti_sci: Add trace events

[Andrew Davis]

On 8/20/25 1:10 PM, Jonathan Cormier wrote:
> Add TI sci trace events to help to debug and measure the speed of the
> communication channel. The xfer_begin and xfer_end calls can be used
> to time how long a transfer takes. The rx_callback and msg_dump trace
> events help track the data that gets returned.
> 
> Based on tracing done in ARM SCMI
> 
> Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
> ---
>   MAINTAINERS                     |  1 +
>   drivers/firmware/Makefile       |  3 ++
>   drivers/firmware/ti_sci.c       | 11 ++++++
>   drivers/firmware/ti_sci_trace.h | 87 +++++++++++++++++++++++++++++++++++++++++
>   4 files changed, 102 insertions(+)
> 
> diff --git a/MAINTAINERS b/MAINTAINERS
> index fad6cb025a1918beec113b576cf28b76151745ef..a6fac706feceedfc5039ec07de954ac35a9af848 100644
> --- a/MAINTAINERS
> +++ b/MAINTAINERS
> @@ -24631,6 +24631,7 @@ F:	drivers/pmdomain/ti/ti_sci_pm_domains.c
>   F:	include/dt-bindings/soc/ti,sci_pm_domain.h
>   F:	include/linux/soc/ti/ti_sci_inta_msi.h
>   F:	include/linux/soc/ti/ti_sci_protocol.h
> +F:	include/trace/events/ti_sci.h
>   
>   TEXAS INSTRUMENTS' TMP117 TEMPERATURE SENSOR DRIVER
>   M:	Puranjay Mohan <puranjay@kernel.org>
> diff --git a/drivers/firmware/Makefile b/drivers/firmware/Makefile
> index 4ddec2820c96fa9be012e89dac3038968bb67039..a055c53bdfa9e5c64adb4e20a9ca6c6661d80297 100644
> --- a/drivers/firmware/Makefile
> +++ b/drivers/firmware/Makefile
> @@ -2,6 +2,9 @@
>   #
>   # Makefile for the linux kernel.
>   #
> +
> +ccflags-y += -I$(src)			# needed for trace events
> +
>   obj-$(CONFIG_ARM_SCPI_PROTOCOL)	+= arm_scpi.o
>   obj-$(CONFIG_ARM_SDE_INTERFACE)	+= arm_sdei.o
>   obj-$(CONFIG_DMI)		+= dmi_scan.o
> diff --git a/drivers/firmware/ti_sci.c b/drivers/firmware/ti_sci.c
> index ae5fd1936ad322e5e3a94897cc042f6548f919e6..87b1330305939bb6b19bbdaa594b17b266092a34 100644
> --- a/drivers/firmware/ti_sci.c
> +++ b/drivers/firmware/ti_sci.c
> @@ -127,6 +127,9 @@ struct ti_sci_info {
>   #define cl_to_ti_sci_info(c)	container_of(c, struct ti_sci_info, cl)
>   #define handle_to_ti_sci_info(h) container_of(h, struct ti_sci_info, handle)
>   
> +#define CREATE_TRACE_POINTS
> +#include "ti_sci_trace.h"
> +
>   #ifdef CONFIG_DEBUG_FS
>   
>   /**
> @@ -269,6 +272,9 @@ static void ti_sci_rx_callback(struct mbox_client *cl, void *m)
>   		return;
>   	}
>   
> +	trace_ti_sci_rx_callback(hdr, 0);
> +	trace_ti_sci_msg_dump(hdr, xfer);
> +

You could instead put these in the same ti_sci_do_xfer() as the other
trace additions, after the completion, xfer->xfer_buf will contain
the response "hdr" message. Keeps all the tracing in one spot, and
if you are going for timing info you'll want to take into account
the completion scheduling/polling.

Andrew

>   	ti_sci_dump_header_dbg(dev, hdr);
>   	/* Take a copy to the rx buffer.. */
>   	memcpy(xfer->xfer_buf, mbox_msg->buf, xfer->rx_len);
> @@ -402,6 +408,9 @@ static inline int ti_sci_do_xfer(struct ti_sci_info *info,
>   	int timeout;
>   	struct device *dev = info->dev;
>   	bool done_state = true;
> +	struct ti_sci_msg_hdr *hdr = (struct ti_sci_msg_hdr *)xfer->tx_message.buf;
> +
> +	trace_ti_sci_xfer_begin(hdr, 0);
>   
>   	ret = mbox_send_message(info->chan_tx, &xfer->tx_message);
>   	if (ret < 0)
> @@ -437,6 +446,8 @@ static inline int ti_sci_do_xfer(struct ti_sci_info *info,
>   	 */
>   	mbox_client_txdone(info->chan_tx, ret);
>   
> +	trace_ti_sci_xfer_end(hdr, ret);
> +
>   	return ret;
>   }
>   
> diff --git a/drivers/firmware/ti_sci_trace.h b/drivers/firmware/ti_sci_trace.h
> new file mode 100644
> index 0000000000000000000000000000000000000000..7f99c41ea08aec6cf64d601576cad29b14c6ad5b
> --- /dev/null
> +++ b/drivers/firmware/ti_sci_trace.h
> @@ -0,0 +1,87 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM ti_sci
> +
> +#if !defined(_TRACE_TI_SCI_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_TI_SCI_H
> +
> +#include <linux/tracepoint.h>
> +
> +
> +DECLARE_EVENT_CLASS(ti_sci_hdr_event_class,
> +	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
> +	TP_ARGS(hdr, status),
> +
> +	TP_STRUCT__entry(
> +		__field(u16, type)
> +		__field(u8, host)
> +		__field(u8, seq)
> +		__field(u32, flags)
> +		__field(int, status)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->type = hdr->type;
> +		__entry->host = hdr->host;
> +		__entry->seq = hdr->seq;
> +		__entry->flags = hdr->flags;
> +		__entry->status = status;
> +	),
> +
> +	TP_printk("type=%04X host=%02X seq=%02X flags=%08X status=%d",
> +		__entry->type, __entry->host, __entry->seq, __entry->flags, __entry->status)
> +);
> +
> +DEFINE_EVENT(ti_sci_hdr_event_class,
> +	ti_sci_xfer_begin,
> +	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
> +	TP_ARGS(hdr, status)
> +);
> +
> +DEFINE_EVENT(ti_sci_hdr_event_class,
> +	ti_sci_rx_callback,
> +	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
> +	TP_ARGS(hdr, status)
> +);
> +
> +DEFINE_EVENT(ti_sci_hdr_event_class,
> +	ti_sci_xfer_end,
> +	TP_PROTO(struct ti_sci_msg_hdr *hdr, int status),
> +	TP_ARGS(hdr, status)
> +);
> +
> +
> +TRACE_EVENT(ti_sci_msg_dump,
> +	TP_PROTO(struct ti_sci_msg_hdr *hdr, struct ti_sci_xfer *xfer),
> +	TP_ARGS(hdr, xfer),
> +
> +	TP_STRUCT__entry(
> +		__field(u16, type)
> +		__field(u8, host)
> +		__field(u8, seq)
> +		__field(u32, flags)
> +		__field(size_t, len)
> +		__dynamic_array(unsigned char, cmd, xfer->rx_len)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->type = hdr->type;
> +		__entry->host = hdr->host;
> +		__entry->seq = hdr->seq;
> +		__entry->flags = hdr->flags;
> +		__entry->len = xfer->rx_len;
> +		memcpy(__get_dynamic_array(cmd), xfer->xfer_buf, __entry->len);
> +	),
> +
> +	TP_printk("type=%04X host=%02X seq=%02X flags=%08X data=%s",
> +		__entry->type, __entry->host, __entry->seq, __entry->flags,
> +		__print_hex_str(__get_dynamic_array(cmd), __entry->len))
> +);
> +#endif /* _TRACE_TI_SCI_H */
> +
> +/* This part must be outside protection */
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH .
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE ti_sci_trace
> +#include <trace/define_trace.h>
> 

Re: [PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[Andrew Davis]

On 8/20/25 1:10 PM, Jonathan Cormier wrote:
> Add trace events to help debug and measure the speed of the
> communication channel.
> 
> Add parsing of the messages types but I am not sure how to parse the
> flags, since the REQ and RESP flags conflict. Left as seperate commit to

The REQ and RESP flags should be handled by different TRACE_EVENTs. Right
now you only dump the content of the response messages (the ones in
rx_callback), also tracing what is sent is just as important, so you
might want to add slightly different ti_sci_msg_dump EVENT for the
sending side which uses the different REQ flag parser.

Andrew

> make it easier to drop or make changes depending on comments.  The two
> commits should squash easily.
> 
> Nishanth Menon and Vignesh Raghavendra requested I send this patch
> upstream.
> 
> Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
> ---
> Jonathan Cormier (2):
>        firmware: ti_sci: Add trace events
>        firmware: ti_sci: trace: Decode message types
> 
>   MAINTAINERS                     |   1 +
>   drivers/firmware/Makefile       |   3 +
>   drivers/firmware/ti_sci.c       |  11 +++
>   drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
>   4 files changed, 161 insertions(+)
> ---
> base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
> change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca
> 
> Best regards,

Re: [PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[Jon Cormier]

On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.com> wrote:
>
> On 8/20/25 1:10 PM, Jonathan Cormier wrote:
> > Add trace events to help debug and measure the speed of the
> > communication channel.
> >
> > Add parsing of the messages types but I am not sure how to parse the
> > flags, since the REQ and RESP flags conflict. Left as seperate commit to
>
> The REQ and RESP flags should be handled by different TRACE_EVENTs. Right
> now you only dump the content of the response messages (the ones in
> rx_callback), also tracing what is sent is just as important, so you
> might want to add slightly different ti_sci_msg_dump EVENT for the
> sending side which uses the different REQ flag parser.


Does it make sense to have seperate trace events, one that only decode
the hdrs and ones that also include the buffers?

I'm bothered by the code duplication, but am trying to convince myself
it doesn't matter.

Currently, with the above updates, if you enabled all the traces,
you'd see something like:

[15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
flags=00000402 status=0
[15.xxxxxxx] ti_sci_tx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
flags=00000402 data=<data>
[15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0
[15.xxxxxxx] ti_sci_rx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 data=<data>
[15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0

Presumably if you were worried about timing, you'd disable the
msg_dumps, avoiding the extra memcpy's.  And if you only cared about
the data being sent, you'd only enable the msg_dumps.  Does this make
sense / is it worth the extra trace calls?

Or removing the buffer decoding in the msg_dumps, removes the duplication:

[15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
flags=00000402 status=0
[15.xxxxxxx] ti_sci_msg_dump: data=<data>
[15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0
[15.xxxxxxx] ti_sci_msg_dump: data=<data>
[15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0

Or do condense the trace calls so they all have the data into something like:

[15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
flags=00000402 status=0  data=<data>
[15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0 data=<data>
[15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
flags=00000002 status=0

Simplifying the code in the trace header.
>
>
> Andrew
>
> > make it easier to drop or make changes depending on comments.  The two
> > commits should squash easily.
> >
> > Nishanth Menon and Vignesh Raghavendra requested I send this patch
> > upstream.
> >
> > Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
> > ---
> > Jonathan Cormier (2):
> >        firmware: ti_sci: Add trace events
> >        firmware: ti_sci: trace: Decode message types
> >
> >   MAINTAINERS                     |   1 +
> >   drivers/firmware/Makefile       |   3 +
> >   drivers/firmware/ti_sci.c       |  11 +++
> >   drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
> >   4 files changed, 161 insertions(+)
> > ---
> > base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
> > change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca
> >
> > Best regards,
>


-- 
Jonathan Cormier
Senior Software Engineer

Voice:  315.425.4045 x222

http://www.CriticalLink.com
6712 Brooklawn Parkway, Syracuse, NY 13211

Re: [PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[Andrew Davis]

On 8/22/25 11:05 AM, Jon Cormier wrote:
> On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.com> wrote:
>>
>> On 8/20/25 1:10 PM, Jonathan Cormier wrote:
>>> Add trace events to help debug and measure the speed of the
>>> communication channel.
>>>
>>> Add parsing of the messages types but I am not sure how to parse the
>>> flags, since the REQ and RESP flags conflict. Left as seperate commit to
>>
>> The REQ and RESP flags should be handled by different TRACE_EVENTs. Right
>> now you only dump the content of the response messages (the ones in
>> rx_callback), also tracing what is sent is just as important, so you
>> might want to add slightly different ti_sci_msg_dump EVENT for the
>> sending side which uses the different REQ flag parser.
> 
> 
> Does it make sense to have seperate trace events, one that only decode
> the hdrs and ones that also include the buffers?
> 
> I'm bothered by the code duplication, but am trying to convince myself
> it doesn't matter.
> 
> Currently, with the above updates, if you enabled all the traces,
> you'd see something like:
> 
> [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000402 status=0
> [15.xxxxxxx] ti_sci_tx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000402 data=<data>
> [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0
> [15.xxxxxxx] ti_sci_rx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 data=<data>
> [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0
> 
> Presumably if you were worried about timing, you'd disable the
> msg_dumps, avoiding the extra memcpy's.  And if you only cared about
> the data being sent, you'd only enable the msg_dumps.  Does this make
> sense / is it worth the extra trace calls?
> 
> Or removing the buffer decoding in the msg_dumps, removes the duplication:
> 
> [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000402 status=0
> [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0
> [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0
> 

I like this one ^^^ but I'd also just remove the `ti_sci_rx_callback`
trace, the contents would always be the same as `ti_sci_xfer_end`.

This way you have two sets of symmetrical trace events, a "begin" and "end"
that can be used for timing measurements, and a dump message for "send" and
"receive" that would help with debugging based on the message contents.

As for the code duplication in the send/receive traces, I'm not sure
what can be done, these trace macros already confuse me enough without
trying to optimize them :)

Andrew

> Or do condense the trace calls so they all have the data into something like:
> 
> [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000402 status=0  data=<data>
> [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0 data=<data>
> [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> flags=00000002 status=0
> 
> Simplifying the code in the trace header.
>>
>>
>> Andrew
>>
>>> make it easier to drop or make changes depending on comments.  The two
>>> commits should squash easily.
>>>
>>> Nishanth Menon and Vignesh Raghavendra requested I send this patch
>>> upstream.
>>>
>>> Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
>>> ---
>>> Jonathan Cormier (2):
>>>         firmware: ti_sci: Add trace events
>>>         firmware: ti_sci: trace: Decode message types
>>>
>>>    MAINTAINERS                     |   1 +
>>>    drivers/firmware/Makefile       |   3 +
>>>    drivers/firmware/ti_sci.c       |  11 +++
>>>    drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
>>>    4 files changed, 161 insertions(+)
>>> ---
>>> base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
>>> change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca
>>>
>>> Best regards,
>>
> 
> 

Re: [PATCH 0/2] PATCH: firmware: ti_sci: Add trace events to TI SCI

[Jon Cormier]

On Fri, Aug 22, 2025 at 1:39 PM Andrew Davis <afd@ti.com> wrote:
>
> On 8/22/25 11:05 AM, Jon Cormier wrote:
> > On Wed, Aug 20, 2025 at 4:04 PM Andrew Davis <afd@ti.com> wrote:
> >>
> >> On 8/20/25 1:10 PM, Jonathan Cormier wrote:
> >>> Add trace events to help debug and measure the speed of the
> >>> communication channel.
> >>>
> >>> Add parsing of the messages types but I am not sure how to parse the
> >>> flags, since the REQ and RESP flags conflict. Left as seperate commit to
> >>
> >> The REQ and RESP flags should be handled by different TRACE_EVENTs. Right
> >> now you only dump the content of the response messages (the ones in
> >> rx_callback), also tracing what is sent is just as important, so you
> >> might want to add slightly different ti_sci_msg_dump EVENT for the
> >> sending side which uses the different REQ flag parser.
> >
> >
> > Does it make sense to have seperate trace events, one that only decode
> > the hdrs and ones that also include the buffers?
> >
> > I'm bothered by the code duplication, but am trying to convince myself
> > it doesn't matter.
> >
> > Currently, with the above updates, if you enabled all the traces,
> > you'd see something like:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0
> > [15.xxxxxxx] ti_sci_tx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> > [15.xxxxxxx] ti_sci_rx_msg_dump: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
> > Presumably if you were worried about timing, you'd disable the
> > msg_dumps, avoiding the extra memcpy's.  And if you only cared about
> > the data being sent, you'd only enable the msg_dumps.  Does this make
> > sense / is it worth the extra trace calls?
> >
> > Or removing the buffer decoding in the msg_dumps, removes the duplication:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0
> > [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> > [15.xxxxxxx] ti_sci_msg_dump: data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
>
> I like this one ^^^ but I'd also just remove the `ti_sci_rx_callback`

Sounds good
>
> trace, the contents would always be the same as `ti_sci_xfer_end`.


So in TI's 6.12 branch, there is a response_expected variable which
skips waiting for a response message. Indicating that there won't
always be a rx buffer.  If I keep the rx_callback scheme, it cleanly
handles both cases without changes.
However if I change xfer_end to track the rx buffer, sometimes it
won't have a header to parse. Or sometimes it will use the TX header
and sometimes it would be the RX header, which would be confusing.

I could keep and move the ti_sci_rx_callback trace into ti_sci_do_xfer
(-> ti_sci_xfer_rx), right after the completion and timeout check.
This would keep all the tracing in this one function, though if
someone wanted to know if there is lost time in waiting on the
completion it wouldn't be tracked.

https://lore.kernel.org/all/20241220114118.uwi5bsefxnue46re@lcpd911/
>
>
> This way you have two sets of symmetrical trace events, a "begin" and "end"
> that can be used for timing measurements, and a dump message for "send" and
> "receive" that would help with debugging based on the message contents.
>
> As for the code duplication in the send/receive traces, I'm not sure
> what can be done, these trace macros already confuse me enough without
> trying to optimize them :)
>
> Andrew
>
> > Or do condense the trace calls so they all have the data into something like:
> >
> > [15.579036] ti_sci_xfer_begin: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000402 status=0  data=<data>
> > [15.587595] ti_sci_rx_callback: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0 data=<data>
> > [15.606135] ti_sci_xfer_end: type=SET_DEVICE_STATE host=0C seq=00
> > flags=00000002 status=0
> >
> > Simplifying the code in the trace header.
> >>
> >>
> >> Andrew
> >>
> >>> make it easier to drop or make changes depending on comments.  The two
> >>> commits should squash easily.
> >>>
> >>> Nishanth Menon and Vignesh Raghavendra requested I send this patch
> >>> upstream.
> >>>
> >>> Signed-off-by: Jonathan Cormier <jcormier@criticallink.com>
> >>> ---
> >>> Jonathan Cormier (2):
> >>>         firmware: ti_sci: Add trace events
> >>>         firmware: ti_sci: trace: Decode message types
> >>>
> >>>    MAINTAINERS                     |   1 +
> >>>    drivers/firmware/Makefile       |   3 +
> >>>    drivers/firmware/ti_sci.c       |  11 +++
> >>>    drivers/firmware/ti_sci_trace.h | 146 ++++++++++++++++++++++++++++++++++++++++
> >>>    4 files changed, 161 insertions(+)
> >>> ---
> >>> base-commit: d7b8f8e20813f0179d8ef519541a3527e7661d3a
> >>> change-id: 20250709-linux_master_ti_sci_trace-91fd2af65dca
> >>>
> >>> Best regards,
> >>
> >
> >
>


-- 
Jonathan Cormier
Senior Software Engineer

Voice:  315.425.4045 x222

http://www.CriticalLink.com
6712 Brooklawn Parkway, Syracuse, NY 13211