[PATCH v2 0/2] Add SCMI full message tracing

[PATCH v2 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
successfully 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.

Following the advice from Jim, 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 

 ++ cmd/reply
    sugov:0-257     [000] .....   401.954788: scmi_msg_dump: pt=13 t=CMND msg_id=07 seq=0082 s=0 pyld=0000000000000000
     <idle>-0       [000] d.h2.   401.955085: scmi_msg_dump: pt=13 t=RESP msg_id=07 seq=0082 s=0 pyld=


 ++ cmd/reply/delayed
   cat-263     [001] .....   471.533806: scmi_msg_dump: pt=15 t=CMND msg_id=06 seq=008A s=0 pyld=0100000001000000
<idle>-0       [000] d.h2.   471.554001: scmi_msg_dump: pt=15 t=RESP msg_id=06 seq=008A s=0 pyld=
<idle>-0       [000] d.h2.   471.574102: scmi_msg_dump: pt=15 t=DLYD msg_id=06 seq=008A s=0 pyld=01000000a05a320000000000efbeaddefecafeca


 ++ enable notif/notif
iio_generic_buf-282     [000] .....   535.327307: scmi_msg_dump: pt=15 t=CMND msg_id=0A seq=00AB s=0 pyld=0800000003000000
         <idle>-0       [000] d.h2.   535.327561: scmi_msg_dump: pt=15 t=RESP msg_id=0A seq=00AB s=0 pyld=00000000
         <idle>-0       [000] d.h2.   535.334421: scmi_msg_dump: pt=15 t=NOTI msg_id=01 seq=0000 s=0 pyld=000000000800000008daffffffffffff008268d4c075fd1610daffffffffffff008268d4c075fd1618daffffffffffff008268d4c075fd16
         <idle>-0       [000] d.h2.   535.434649: scmi_msg_dump: pt=15 t=NOTI msg_id=01 seq=0000 s=0 pyld=000000000800000009daffffffffffff008268d4c075fd1611daffffffffffff008268d4c075fd1619daffffffffffff008268d4c075fd16

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

Thanks,
Cristian

---
V1 --> V2
- changed dumping format

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 v2 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>
---
v1 --> v2
- changed dump formatting
---
 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 fa8879568a37..65016a767b7a 100644
--- a/include/trace/events/scmi.h
+++ b/include/trace/events/scmi.h
@@ -137,6 +137,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("pt=%02X t=%s msg_id=%02X seq=%04X s=%d pyld=%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 v2 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 c4e291f3fede..31afd60982f1 100644
--- a/drivers/firmware/arm_scmi/driver.c
+++ b/drivers/firmware/arm_scmi/driver.c
@@ -661,6 +661,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);
 
@@ -695,6 +700,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);
@@ -828,6 +839,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. */
@@ -904,6 +921,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 v2 0/2] Add SCMI full message tracing

[Sudeep Holla]

On Thu, Jun 30, 2022 at 06:31:33PM +0100, Cristian Marussi 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
> successfully 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.

Looks good to me. I would like to hear from Jim if possible. I plan to
merge this ASAP.

-- 
Regards,
Sudeep

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

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

[Jim Quinlan]

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

Hi,
LGTM, I appreciate this change. For testing, I fed  your sample output to this:

     perl -MData::Dumper -nae  's/^.+scmi_msg_dump:// && print Dumper
{ (map { split /=/; } split" ") }' < scmi.txt

which gives this

$VAR1 = {
          'pt' => '15',
          'seq' => '0000',
          'pyld' =>
'000000000800000009daffffffffffff008268d4c075fd1611daffffffffffff008268d4c075fd1619daffffffffffff008268d4c075fd16',
          'msg_id' => '01',
          's' => '0',
          't' => 'NOTI'
        };
which is what I wanted.   BTW, if I ever write a script that would
take this SCMI trace text and
decode it to nice cmd names and arguments -- where would I submit such a script?

Thanks and Regards,
Jim Quinlan
Broadcom STB


On Fri, Jul 1, 2022 at 9:54 AM Sudeep Holla <sudeep.holla@arm.com> wrote:
>
> On Thu, Jun 30, 2022 at 06:31:33PM +0100, Cristian Marussi 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
> > successfully 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.
>
> Looks good to me. I would like to hear from Jim if possible. I plan to
> merge this ASAP.
>
> --
> Regards,
> Sudeep

[-- 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 v2 0/2] Add SCMI full message tracing

[Sudeep Holla]

On Fri, Jul 01, 2022 at 11:03:38AM -0400, Jim Quinlan wrote:
> Hi,
> LGTM, I appreciate this change. For testing, I fed  your sample output to this:
>

Thanks!

>      perl -MData::Dumper -nae  's/^.+scmi_msg_dump:// && print Dumper
> { (map { split /=/; } split" ") }' < scmi.txt
> 
> which gives this
> 
> $VAR1 = {
>           'pt' => '15',
>           'seq' => '0000',
>           'pyld' =>
> '000000000800000009daffffffffffff008268d4c075fd1611daffffffffffff008268d4c075fd1619daffffffffffff008268d4c075fd16',
>           'msg_id' => '01',
>           's' => '0',
>           't' => 'NOTI'
>         };
> which is what I wanted.   BTW, if I ever write a script that would
> take this SCMI trace text and
> decode it to nice cmd names and arguments -- where would I submit such a script?
>

I am not 100% sure. After reading this, the first thoughts were scripts/
or tools/scripts but looking at the content I am less sure about latter.
Worth posting and then check what people have to say once this lands upstream.
Or even once this is merged into -next officially.

-- 
Regards,
Sudeep

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

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

[Sudeep Holla]

On Thu, 30 Jun 2022 18:31:33 +0100, Cristian Marussi wrote:
> 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
> successfully 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.
> 
> [...]

Applied to sudeep.holla/linux (for-next/scmi), thanks!

[1/2] include: trace: Add SCMI full message tracing
      https://git.kernel.org/sudeep.holla/c/2bd0467074
[2/2] firmware: arm_scmi: Use new SCMI full message tracing
      https://git.kernel.org/sudeep.holla/c/b60e088682

--
Regards,
Sudeep


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