* [PATCH 1/2] include: trace: Add SCMI full message tracing
2022-06-23 14:55 [PATCH 0/2] Add SCMI full message tracing Cristian Marussi
@ 2022-06-23 14:55 ` Cristian Marussi
2022-06-23 14:55 ` [PATCH 2/2] firmware: arm_scmi: Use new " Cristian Marussi
2022-06-27 19:05 ` [PATCH 0/2] Add " Jim Quinlan
2 siblings, 0 replies; 6+ messages in thread
From: Cristian Marussi @ 2022-06-23 14:55 UTC (permalink / raw)
To: linux-kernel, linux-arm-kernel
Cc: sudeep.holla, f.fainelli, vincent.guittot, lukasz.luba,
james.quinlan, 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
^ permalink raw reply related [flat|nested] 6+ messages in thread* [PATCH 2/2] firmware: arm_scmi: Use new SCMI full message tracing
2022-06-23 14:55 [PATCH 0/2] Add SCMI full message tracing Cristian Marussi
2022-06-23 14:55 ` [PATCH 1/2] include: trace: " Cristian Marussi
@ 2022-06-23 14:55 ` Cristian Marussi
2022-06-27 19:05 ` [PATCH 0/2] Add " Jim Quinlan
2 siblings, 0 replies; 6+ messages in thread
From: Cristian Marussi @ 2022-06-23 14:55 UTC (permalink / raw)
To: linux-kernel, linux-arm-kernel
Cc: sudeep.holla, f.fainelli, vincent.guittot, lukasz.luba,
james.quinlan, 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
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH 0/2] Add SCMI full message tracing
2022-06-23 14:55 [PATCH 0/2] Add SCMI full message tracing Cristian Marussi
2022-06-23 14:55 ` [PATCH 1/2] include: trace: " Cristian Marussi
2022-06-23 14:55 ` [PATCH 2/2] firmware: arm_scmi: Use new " Cristian Marussi
@ 2022-06-27 19:05 ` Jim Quinlan
2022-06-29 18:19 ` Cristian Marussi
2 siblings, 1 reply; 6+ messages in thread
From: Jim Quinlan @ 2022-06-27 19:05 UTC (permalink / raw)
To: Cristian Marussi
Cc: open list,
moderated list:BROADCOM BCM2711/BCM2835 ARM ARCHITECTURE,
Sudeep Holla, Florian Fainelli, Vincent Guittot, Lukasz Luba
[-- 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
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH 0/2] Add SCMI full message tracing
2022-06-27 19:05 ` [PATCH 0/2] Add " Jim Quinlan
@ 2022-06-29 18:19 ` Cristian Marussi
2022-06-30 16:18 ` Sudeep Holla
0 siblings, 1 reply; 6+ messages in thread
From: Cristian Marussi @ 2022-06-29 18:19 UTC (permalink / raw)
To: Jim Quinlan
Cc: open list,
moderated list:BROADCOM BCM2711/BCM2835 ARM ARCHITECTURE,
Sudeep Holla, Florian Fainelli, Vincent Guittot, Lukasz Luba
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
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] Add SCMI full message tracing
2022-06-29 18:19 ` Cristian Marussi
@ 2022-06-30 16:18 ` Sudeep Holla
0 siblings, 0 replies; 6+ messages in thread
From: Sudeep Holla @ 2022-06-30 16:18 UTC (permalink / raw)
To: Cristian Marussi
Cc: Jim Quinlan, open list,
moderated list:BROADCOM BCM2711/BCM2835 ARM ARCHITECTURE,
Florian Fainelli, Sudeep Holla, Vincent Guittot, Lukasz Luba
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
^ permalink raw reply [flat|nested] 6+ messages in thread