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
Add full message tracing for all transmitted and successfully received SCMI
commands, replies and notifications.
Signed-off-by: Cristian Marussi <[email protected]>
---
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
Add a distinct trace event to dump full SCMI message headers and payloads.
Signed-off-by: Cristian Marussi <[email protected]>
---
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
On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
<[email protected]> 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
>
On Mon, Jun 27, 2022 at 03:05:57PM -0400, Jim Quinlan wrote:
> On Thu, Jun 23, 2022 at 10:55 AM Cristian Marussi
> <[email protected]> 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
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