[PATCH 0/2] Add SCMI full message tracing

[PATCH 0/2] Add SCMI full message tracing

[Cristian Marussi]

Hi,

after a few recent troubles handling too strictly out-of-spec replies from
SCMI servers deployed in the wild, I though it could have been useful to
have a basic way to dump at will the effective full payloads of successfuly
transmitted/received SCMI messages.

The existing SCMI traces already collect a bunch of information about SCMI
message exchanges but they do NOT keep any payload information: this is
certainly preferable most of the time since dumping full SCMI messages to
the trace buffer involves a full copy of the payload.

For this reason I added a new distinct trace_scmi_msg_dump with this series
in order to be able to selectively enable at will message dumping only when
required.

Only successfully transmitted and received (valid) xfers are dumped.

At first I was thinking about just dumping raw header and payload, but in
order to make the log a bit more human readable (without the need of
tooling to parse the log), I added some parsing/interpretation of the
header, so that the final result is something like:

root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable 
root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe 

(my annotations non on traces =>>)			 proto  type  cmd   seq  status    payload
							  |      |    |      |     |        |
 ++ cmd/reply						  |      |    |      |     |        |
   cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
<idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000


 ++ cmd/reply/delayed
   cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
<idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]: 
<idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca


 ++ enable notif/notif
iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
         <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
         <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16

Payload is dumped as it comes through byte-by-byte without any endianity
conversion to avoid further load on the system.

Any thoughs ?

Thanks,
Cristian

Cristian Marussi (2):
  include: trace: Add SCMI full message tracing
  firmware: arm_scmi: Use new SCMI full message tracing

 drivers/firmware/arm_scmi/driver.c | 21 ++++++++++++++++++++
 include/trace/events/scmi.h        | 31 ++++++++++++++++++++++++++++++
 2 files changed, 52 insertions(+)

-- 
2.32.0

[PATCH 0/2] Add SCMI full message tracing

[Cristian Marussi]

Hi,

after a few recent troubles handling too strictly out-of-spec replies from
SCMI servers deployed in the wild, I though it could have been useful to
have a basic way to dump at will the effective full payloads of successfuly
transmitted/received SCMI messages.

The existing SCMI traces already collect a bunch of information about SCMI
message exchanges but they do NOT keep any payload information: this is
certainly preferable most of the time since dumping full SCMI messages to
the trace buffer involves a full copy of the payload.

For this reason I added a new distinct trace_scmi_msg_dump with this series
in order to be able to selectively enable at will message dumping only when
required.

Only successfully transmitted and received (valid) xfers are dumped.

At first I was thinking about just dumping raw header and payload, but in
order to make the log a bit more human readable (without the need of
tooling to parse the log), I added some parsing/interpretation of the
header, so that the final result is something like:

root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable 
root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe 

(my annotations non on traces =>>)			 proto  type  cmd   seq  status    payload
							  |      |    |      |     |        |
 ++ cmd/reply						  |      |    |      |     |        |
   cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
<idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000


 ++ cmd/reply/delayed
   cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
<idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]: 
<idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca


 ++ enable notif/notif
iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
         <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
         <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16

Payload is dumped as it comes through byte-by-byte without any endianity
conversion to avoid further load on the system.

Any thoughs ?

Thanks,
Cristian

Cristian Marussi (2):
  include: trace: Add SCMI full message tracing
  firmware: arm_scmi: Use new SCMI full message tracing

 drivers/firmware/arm_scmi/driver.c | 21 ++++++++++++++++++++
 include/trace/events/scmi.h        | 31 ++++++++++++++++++++++++++++++
 2 files changed, 52 insertions(+)

-- 
2.32.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH 1/2] include: trace: Add SCMI full message tracing

[Cristian Marussi]

Add a distinct trace event to dump full SCMI message headers and payloads.

Signed-off-by: Cristian Marussi <cristian.marussi@arm.com>
---
 include/trace/events/scmi.h | 31 +++++++++++++++++++++++++++++++
 1 file changed, 31 insertions(+)

diff --git a/include/trace/events/scmi.h b/include/trace/events/scmi.h
index cee4b2b64ae4..40995c8416ba 100644
--- a/include/trace/events/scmi.h
+++ b/include/trace/events/scmi.h
@@ -112,6 +112,37 @@ TRACE_EVENT(scmi_rx_done,
 		__entry->transfer_id, __entry->msg_id, __entry->protocol_id,
 		__entry->seq, __entry->msg_type)
 );
+
+TRACE_EVENT(scmi_msg_dump,
+	TP_PROTO(u8 protocol_id, u8 msg_id, unsigned char *tag, u16 seq,
+		 int status, void *buf, size_t len),
+	TP_ARGS(protocol_id, msg_id, tag, seq, status, buf, len),
+
+	TP_STRUCT__entry(
+		__field(u8, protocol_id)
+		__field(u8, msg_id)
+		__array(char, tag, 5)
+		__field(u16, seq)
+		__field(int, status)
+		__field(size_t, len)
+		__dynamic_array(unsigned char, cmd, len)
+	),
+
+	TP_fast_assign(
+		__entry->protocol_id = protocol_id;
+		__entry->msg_id = msg_id;
+		strscpy(__entry->tag, tag, 5);
+		__entry->seq = seq;
+		__entry->status = status;
+		__entry->len = len;
+		memcpy(__get_dynamic_array(cmd), buf, __entry->len);
+	),
+
+	TP_printk("[0x%02X]:%s:[0x%02X]:[%04X]:[%d]: %s",
+		  __entry->protocol_id, __entry->tag, __entry->msg_id,
+		  __entry->seq, __entry->status,
+		__print_hex_str(__get_dynamic_array(cmd), __entry->len))
+);
 #endif /* _TRACE_SCMI_H */
 
 /* This part must be outside protection */
-- 
2.32.0

[PATCH 1/2] include: trace: Add SCMI full message tracing

[Cristian Marussi]

Add a distinct trace event to dump full SCMI message headers and payloads.

Signed-off-by: Cristian Marussi <cristian.marussi@arm.com>
---
 include/trace/events/scmi.h | 31 +++++++++++++++++++++++++++++++
 1 file changed, 31 insertions(+)

diff --git a/include/trace/events/scmi.h b/include/trace/events/scmi.h
index cee4b2b64ae4..40995c8416ba 100644
--- a/include/trace/events/scmi.h
+++ b/include/trace/events/scmi.h
@@ -112,6 +112,37 @@ TRACE_EVENT(scmi_rx_done,
 		__entry->transfer_id, __entry->msg_id, __entry->protocol_id,
 		__entry->seq, __entry->msg_type)
 );
+
+TRACE_EVENT(scmi_msg_dump,
+	TP_PROTO(u8 protocol_id, u8 msg_id, unsigned char *tag, u16 seq,
+		 int status, void *buf, size_t len),
+	TP_ARGS(protocol_id, msg_id, tag, seq, status, buf, len),
+
+	TP_STRUCT__entry(
+		__field(u8, protocol_id)
+		__field(u8, msg_id)
+		__array(char, tag, 5)
+		__field(u16, seq)
+		__field(int, status)
+		__field(size_t, len)
+		__dynamic_array(unsigned char, cmd, len)
+	),
+
+	TP_fast_assign(
+		__entry->protocol_id = protocol_id;
+		__entry->msg_id = msg_id;
+		strscpy(__entry->tag, tag, 5);
+		__entry->seq = seq;
+		__entry->status = status;
+		__entry->len = len;
+		memcpy(__get_dynamic_array(cmd), buf, __entry->len);
+	),
+
+	TP_printk("[0x%02X]:%s:[0x%02X]:[%04X]:[%d]: %s",
+		  __entry->protocol_id, __entry->tag, __entry->msg_id,
+		  __entry->seq, __entry->status,
+		__print_hex_str(__get_dynamic_array(cmd), __entry->len))
+);
 #endif /* _TRACE_SCMI_H */
 
 /* This part must be outside protection */
-- 
2.32.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH 2/2] firmware: arm_scmi: Use new SCMI full message tracing

[Cristian Marussi]

Add full message tracing for all transmitted and successfully received SCMI
commands, replies and notifications.

Signed-off-by: Cristian Marussi <cristian.marussi@arm.com>
---
 drivers/firmware/arm_scmi/driver.c | 21 +++++++++++++++++++++
 1 file changed, 21 insertions(+)

diff --git a/drivers/firmware/arm_scmi/driver.c b/drivers/firmware/arm_scmi/driver.c
index 8b7ac6663d57..276d3a4fd6b8 100644
--- a/drivers/firmware/arm_scmi/driver.c
+++ b/drivers/firmware/arm_scmi/driver.c
@@ -660,6 +660,11 @@ static void scmi_handle_notification(struct scmi_chan_info *cinfo,
 		smp_store_mb(xfer->priv, priv);
 	info->desc->ops->fetch_notification(cinfo, info->desc->max_msg_size,
 					    xfer);
+
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id, "NOTI",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->rx.buf, xfer->rx.len);
+
 	scmi_notify(cinfo->handle, xfer->hdr.protocol_id,
 		    xfer->hdr.id, xfer->rx.buf, xfer->rx.len, ts);
 
@@ -694,6 +699,12 @@ static void scmi_handle_response(struct scmi_chan_info *cinfo,
 		smp_store_mb(xfer->priv, priv);
 	info->desc->ops->fetch_response(cinfo, xfer);
 
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id,
+			    xfer->hdr.type == MSG_TYPE_DELAYED_RESP ?
+			    "DLYD" : "RESP",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->rx.buf, xfer->rx.len);
+
 	trace_scmi_rx_done(xfer->transfer_id, xfer->hdr.id,
 			   xfer->hdr.protocol_id, xfer->hdr.seq,
 			   xfer->hdr.type);
@@ -827,6 +838,12 @@ static int scmi_wait_for_message_response(struct scmi_chan_info *cinfo,
 				xfer->state = SCMI_XFER_RESP_OK;
 			}
 			spin_unlock_irqrestore(&xfer->lock, flags);
+
+			/* Trace polled replies. */
+			trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id,
+					    "RESP",
+					    xfer->hdr.seq, xfer->hdr.status,
+					    xfer->rx.buf, xfer->rx.len);
 		}
 	} else {
 		/* And we wait for the response. */
@@ -903,6 +920,10 @@ static int do_xfer(const struct scmi_protocol_handle *ph,
 		return ret;
 	}
 
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id, "CMND",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->tx.buf, xfer->tx.len);
+
 	ret = scmi_wait_for_message_response(cinfo, xfer);
 	if (!ret && xfer->hdr.status)
 		ret = scmi_to_linux_errno(xfer->hdr.status);
-- 
2.32.0

[PATCH 2/2] firmware: arm_scmi: Use new SCMI full message tracing

[Cristian Marussi]

Add full message tracing for all transmitted and successfully received SCMI
commands, replies and notifications.

Signed-off-by: Cristian Marussi <cristian.marussi@arm.com>
---
 drivers/firmware/arm_scmi/driver.c | 21 +++++++++++++++++++++
 1 file changed, 21 insertions(+)

diff --git a/drivers/firmware/arm_scmi/driver.c b/drivers/firmware/arm_scmi/driver.c
index 8b7ac6663d57..276d3a4fd6b8 100644
--- a/drivers/firmware/arm_scmi/driver.c
+++ b/drivers/firmware/arm_scmi/driver.c
@@ -660,6 +660,11 @@ static void scmi_handle_notification(struct scmi_chan_info *cinfo,
 		smp_store_mb(xfer->priv, priv);
 	info->desc->ops->fetch_notification(cinfo, info->desc->max_msg_size,
 					    xfer);
+
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id, "NOTI",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->rx.buf, xfer->rx.len);
+
 	scmi_notify(cinfo->handle, xfer->hdr.protocol_id,
 		    xfer->hdr.id, xfer->rx.buf, xfer->rx.len, ts);
 
@@ -694,6 +699,12 @@ static void scmi_handle_response(struct scmi_chan_info *cinfo,
 		smp_store_mb(xfer->priv, priv);
 	info->desc->ops->fetch_response(cinfo, xfer);
 
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id,
+			    xfer->hdr.type == MSG_TYPE_DELAYED_RESP ?
+			    "DLYD" : "RESP",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->rx.buf, xfer->rx.len);
+
 	trace_scmi_rx_done(xfer->transfer_id, xfer->hdr.id,
 			   xfer->hdr.protocol_id, xfer->hdr.seq,
 			   xfer->hdr.type);
@@ -827,6 +838,12 @@ static int scmi_wait_for_message_response(struct scmi_chan_info *cinfo,
 				xfer->state = SCMI_XFER_RESP_OK;
 			}
 			spin_unlock_irqrestore(&xfer->lock, flags);
+
+			/* Trace polled replies. */
+			trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id,
+					    "RESP",
+					    xfer->hdr.seq, xfer->hdr.status,
+					    xfer->rx.buf, xfer->rx.len);
 		}
 	} else {
 		/* And we wait for the response. */
@@ -903,6 +920,10 @@ static int do_xfer(const struct scmi_protocol_handle *ph,
 		return ret;
 	}
 
+	trace_scmi_msg_dump(xfer->hdr.protocol_id, xfer->hdr.id, "CMND",
+			    xfer->hdr.seq, xfer->hdr.status,
+			    xfer->tx.buf, xfer->tx.len);
+
 	ret = scmi_wait_for_message_response(cinfo, xfer);
 	if (!ret && xfer->hdr.status)
 		ret = scmi_to_linux_errno(xfer->hdr.status);
-- 
2.32.0


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 0/2] Add SCMI full message tracing

[Jim Quinlan]

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

On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
<cristian.marussi@arm.com> wrote:
>
> Hi,
>
> after a few recent troubles handling too strictly out-of-spec replies from
> SCMI servers deployed in the wild, I though it could have been useful to
> have a basic way to dump at will the effective full payloads of successfuly
> transmitted/received SCMI messages.
>
> The existing SCMI traces already collect a bunch of information about SCMI
> message exchanges but they do NOT keep any payload information: this is
> certainly preferable most of the time since dumping full SCMI messages to
> the trace buffer involves a full copy of the payload.
>
> For this reason I added a new distinct trace_scmi_msg_dump with this series
> in order to be able to selectively enable at will message dumping only when
> required.
>
> Only successfully transmitted and received (valid) xfers are dumped.
>
> At first I was thinking about just dumping raw header and payload, but in
> order to make the log a bit more human readable (without the need of
> tooling to parse the log), I added some parsing/interpretation of the
> header, so that the final result is something like:
>
> root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable
> root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe
>
> (my annotations non on traces =>>)                       proto  type  cmd   seq  status    payload
>                                                           |      |    |      |     |        |
>  ++ cmd/reply                                             |      |    |      |     |        |
>    cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
> <idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000
>I'll probably still use a script, but
as you are keep
>
>  ++ cmd/reply/delayed
>    cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
> <idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]:
> <idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca
>
>
>  ++ enable notif/notif
> iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
>          <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
>          <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16
>
> Payload is dumped as it comes through byte-by-byte without any endianity
> conversion to avoid further load on the system.
>
> Any thoughs ?

Hi Christian,
I haven't tested this but the format looks good to me.  I have a
couple of minor suggestions
below.

As all numbers are hex, consider dropping the '0x'.  BTW,  the seq
value (eg [0020]) is hex but does not have '0x'.

Some TP_printk()s use this  style:

        scmi_msg_dump: pt=15 t=CMND cmd=06 seq=0021 s=0 pyld=12345678abcdef

which allows one to easily grep, for example, for all non-zero returns

        grep 's=[^0]'

This format is also easy to parse with a script:  strip the preamble,
split on whitespace, and then split on '=' to get the  [key, value]
pairs.

Thanks,
Jim Quinlan
Broadcom STB





>
> Thanks,
> Cristian
>
> Cristian Marussi (2):
>   include: trace: Add SCMI full message tracing
>   firmware: arm_scmi: Use new SCMI full message tracing
>
>  drivers/firmware/arm_scmi/driver.c | 21 ++++++++++++++++++++
>  include/trace/events/scmi.h        | 31 ++++++++++++++++++++++++++++++
>  2 files changed, 52 insertions(+)
>
> --
> 2.32.0
>

[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 4210 bytes --]

Re: [PATCH 0/2] Add SCMI full message tracing

[Jim Quinlan]

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

On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
<cristian.marussi@arm.com> wrote:
>
> Hi,
>
> after a few recent troubles handling too strictly out-of-spec replies from
> SCMI servers deployed in the wild, I though it could have been useful to
> have a basic way to dump at will the effective full payloads of successfuly
> transmitted/received SCMI messages.
>
> The existing SCMI traces already collect a bunch of information about SCMI
> message exchanges but they do NOT keep any payload information: this is
> certainly preferable most of the time since dumping full SCMI messages to
> the trace buffer involves a full copy of the payload.
>
> For this reason I added a new distinct trace_scmi_msg_dump with this series
> in order to be able to selectively enable at will message dumping only when
> required.
>
> Only successfully transmitted and received (valid) xfers are dumped.
>
> At first I was thinking about just dumping raw header and payload, but in
> order to make the log a bit more human readable (without the need of
> tooling to parse the log), I added some parsing/interpretation of the
> header, so that the final result is something like:
>
> root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable
> root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe
>
> (my annotations non on traces =>>)                       proto  type  cmd   seq  status    payload
>                                                           |      |    |      |     |        |
>  ++ cmd/reply                                             |      |    |      |     |        |
>    cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
> <idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000
>I'll probably still use a script, but
as you are keep
>
>  ++ cmd/reply/delayed
>    cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
> <idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]:
> <idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca
>
>
>  ++ enable notif/notif
> iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
>          <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
>          <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16
>
> Payload is dumped as it comes through byte-by-byte without any endianity
> conversion to avoid further load on the system.
>
> Any thoughs ?

Hi Christian,
I haven't tested this but the format looks good to me.  I have a
couple of minor suggestions
below.

As all numbers are hex, consider dropping the '0x'.  BTW,  the seq
value (eg [0020]) is hex but does not have '0x'.

Some TP_printk()s use this  style:

        scmi_msg_dump: pt=15 t=CMND cmd=06 seq=0021 s=0 pyld=12345678abcdef

which allows one to easily grep, for example, for all non-zero returns

        grep 's=[^0]'

This format is also easy to parse with a script:  strip the preamble,
split on whitespace, and then split on '=' to get the  [key, value]
pairs.

Thanks,
Jim Quinlan
Broadcom STB





>
> Thanks,
> Cristian
>
> Cristian Marussi (2):
>   include: trace: Add SCMI full message tracing
>   firmware: arm_scmi: Use new SCMI full message tracing
>
>  drivers/firmware/arm_scmi/driver.c | 21 ++++++++++++++++++++
>  include/trace/events/scmi.h        | 31 ++++++++++++++++++++++++++++++
>  2 files changed, 52 insertions(+)
>
> --
> 2.32.0
>

[-- Attachment #1.2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 4210 bytes --]

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

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 0/2] Add SCMI full message tracing

[Cristian Marussi]

On Mon, Jun 27, 2022 at 03:05:57PM -0400, Jim Quinlan wrote:
> On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
> <cristian.marussi@arm.com> wrote:
> >
> > Hi,
> >
> > after a few recent troubles handling too strictly out-of-spec replies from
> > SCMI servers deployed in the wild, I though it could have been useful to
> > have a basic way to dump at will the effective full payloads of successfuly
> > transmitted/received SCMI messages.
> >
> > The existing SCMI traces already collect a bunch of information about SCMI
> > message exchanges but they do NOT keep any payload information: this is
> > certainly preferable most of the time since dumping full SCMI messages to
> > the trace buffer involves a full copy of the payload.
> >
> > For this reason I added a new distinct trace_scmi_msg_dump with this series
> > in order to be able to selectively enable at will message dumping only when
> > required.
> >
> > Only successfully transmitted and received (valid) xfers are dumped.
> >
> > At first I was thinking about just dumping raw header and payload, but in
> > order to make the log a bit more human readable (without the need of
> > tooling to parse the log), I added some parsing/interpretation of the
> > header, so that the final result is something like:
> >
> > root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable
> > root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe
> >
> > (my annotations non on traces =>>)                       proto  type  cmd   seq  status    payload
> >                                                           |      |    |      |     |        |
> >  ++ cmd/reply                                             |      |    |      |     |        |
> >    cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
> > <idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000
> >I'll probably still use a script, but
> as you are keep
> >
> >  ++ cmd/reply/delayed
> >    cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
> > <idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]:
> > <idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca
> >
> >
> >  ++ enable notif/notif
> > iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
> >          <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
> >          <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16
> >
> > Payload is dumped as it comes through byte-by-byte without any endianity
> > conversion to avoid further load on the system.
> >
> > Any thoughs ?
> 
> Hi Christian,
> I haven't tested this but the format looks good to me.  I have a
> couple of minor suggestions
> below.
> 

Hi Jim,

thanks for having a look.

> As all numbers are hex, consider dropping the '0x'.  BTW,  the seq
> value (eg [0020]) is hex but does not have '0x'.
> 

Yes indeed, good point.

> Some TP_printk()s use this  style:
> 
>         scmi_msg_dump: pt=15 t=CMND cmd=06 seq=0021 s=0 pyld=12345678abcdef
> 
> which allows one to easily grep, for example, for all non-zero returns
> 
>         grep 's=[^0]'
> 
> This format is also easy to parse with a script:  strip the preamble,
> split on whitespace, and then split on '=' to get the  [key, value]
> pairs.

In fact having a grep-friendly format is better.

Thanks for your feedback, I'll wait to see if someone else wants to
chime in and repost.

Thanks,
Cristian

Re: [PATCH 0/2] Add SCMI full message tracing

[Cristian Marussi]

On Mon, Jun 27, 2022 at 03:05:57PM -0400, Jim Quinlan wrote:
> On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
> <cristian.marussi@arm.com> wrote:
> >
> > Hi,
> >
> > after a few recent troubles handling too strictly out-of-spec replies from
> > SCMI servers deployed in the wild, I though it could have been useful to
> > have a basic way to dump at will the effective full payloads of successfuly
> > transmitted/received SCMI messages.
> >
> > The existing SCMI traces already collect a bunch of information about SCMI
> > message exchanges but they do NOT keep any payload information: this is
> > certainly preferable most of the time since dumping full SCMI messages to
> > the trace buffer involves a full copy of the payload.
> >
> > For this reason I added a new distinct trace_scmi_msg_dump with this series
> > in order to be able to selectively enable at will message dumping only when
> > required.
> >
> > Only successfully transmitted and received (valid) xfers are dumped.
> >
> > At first I was thinking about just dumping raw header and payload, but in
> > order to make the log a bit more human readable (without the need of
> > tooling to parse the log), I added some parsing/interpretation of the
> > header, so that the final result is something like:
> >
> > root@deb-guest:~# echo 1 > /sys/kernel/debug/tracing/events/scmi/scmi_msg_dump/enable
> > root@deb-guest:~# cat /sys/kernel/debug/tracing/trace_pipe
> >
> > (my annotations non on traces =>>)                       proto  type  cmd   seq  status    payload
> >                                                           |      |    |      |     |        |
> >  ++ cmd/reply                                             |      |    |      |     |        |
> >    cat-224     [002] .....   147.755847: scmi_msg_dump: [0x15]:CMND:[0x06]:[0021]:[0]: 0000000000000000
> > <idle>-0       [000] d.h2.   147.758311: scmi_msg_dump: [0x15]:RESP:[0x06]:[0021]:[0]: 25000000000000000000000000000000
> >I'll probably still use a script, but
> as you are keep
> >
> >  ++ cmd/reply/delayed
> >    cat-223     [001] .....   122.384192: scmi_msg_dump: [0x15]:CMND:[0x06]:[0020]:[0]: 0100000001000000
> > <idle>-0       [000] d.h2.   122.405548: scmi_msg_dump: [0x15]:RESP:[0x06]:[0020]:[0]:
> > <idle>-0       [000] d.h2.   122.425839: scmi_msg_dump: [0x15]:DLYD:[0x06]:[0020]:[0]: 01000000a05a320000000000efbeaddefecafeca
> >
> >
> >  ++ enable notif/notif
> > iio_generic_buf-233     [003] .....   522.399690: scmi_msg_dump: [0x15]:CMND:[0x0A]:[0024]:[0]: 0800000003000000
> >          <idle>-0       [000] dNh2.   522.417778: scmi_msg_dump: [0x15]:RESP:[0x0A]:[0024]:[0]: 00000000
> >          <idle>-0       [000] d.h2.   522.500945: scmi_msg_dump: [0x15]:NOTI:[0x01]:[0000]:[0]: 000000000800000008daffffffffffff0040d3a45d46fb1610daffffffffffff0040d3a45d46fb1618daffffffffffff0040d3a45d46fb16
> >
> > Payload is dumped as it comes through byte-by-byte without any endianity
> > conversion to avoid further load on the system.
> >
> > Any thoughs ?
> 
> Hi Christian,
> I haven't tested this but the format looks good to me.  I have a
> couple of minor suggestions
> below.
> 

Hi Jim,

thanks for having a look.

> As all numbers are hex, consider dropping the '0x'.  BTW,  the seq
> value (eg [0020]) is hex but does not have '0x'.
> 

Yes indeed, good point.

> Some TP_printk()s use this  style:
> 
>         scmi_msg_dump: pt=15 t=CMND cmd=06 seq=0021 s=0 pyld=12345678abcdef
> 
> which allows one to easily grep, for example, for all non-zero returns
> 
>         grep 's=[^0]'
> 
> This format is also easy to parse with a script:  strip the preamble,
> split on whitespace, and then split on '=' to get the  [key, value]
> pairs.

In fact having a grep-friendly format is better.

Thanks for your feedback, I'll wait to see if someone else wants to
chime in and repost.

Thanks,
Cristian


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 0/2] Add SCMI full message tracing

[Sudeep Holla]

On Wed, Jun 29, 2022 at 07:19:32PM +0100, Cristian Marussi wrote:
> On Mon, Jun 27, 2022 at 03:05:57PM -0400, Jim Quinlan wrote:

[...]

> > This format is also easy to parse with a script:  strip the preamble,
> > split on whitespace, and then split on '=' to get the  [key, value]
> > pairs.
> 
> In fact having a grep-friendly format is better.
> 
> Thanks for your feedback, I'll wait to see if someone else wants to
> chime in and repost.
> 

I agree with Jim's proposal, please update and send the patch.

-- 
Regards,
Sudeep

Re: [PATCH 0/2] Add SCMI full message tracing

[Sudeep Holla]

On Wed, Jun 29, 2022 at 07:19:32PM +0100, Cristian Marussi wrote:
> On Mon, Jun 27, 2022 at 03:05:57PM -0400, Jim Quinlan wrote:

[...]

> > This format is also easy to parse with a script:  strip the preamble,
> > split on whitespace, and then split on '=' to get the  [key, value]
> > pairs.
> 
> In fact having a grep-friendly format is better.
> 
> Thanks for your feedback, I'll wait to see if someone else wants to
> chime in and repost.
> 

I agree with Jim's proposal, please update and send the patch.

-- 
Regards,
Sudeep

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel