* [PATCH 2/2] drivers: firmware: scmi: Extend SCMI transport layer by trace events
2019-12-16 16:16 [PATCH 1/2] include: trace: Add SCMI header with trace events lukasz.luba
@ 2019-12-16 16:16 ` lukasz.luba
2019-12-16 22:15 ` [PATCH 1/2] include: trace: Add SCMI header with " Jim Quinlan
` (2 subsequent siblings)
3 siblings, 0 replies; 10+ messages in thread
From: lukasz.luba @ 2019-12-16 16:16 UTC (permalink / raw)
To: linux-kernel, sudeep.holla, linux-arm-kernel; +Cc: rostedt, mingo, Lukasz Luba
From: Lukasz Luba <lukasz.luba@arm.com>
The SCMI transport layer communicates via mailboxes and shared memory with
firmware running on a microcontroller. It is platform specific how long it
takes to pass a SCMI message. The most sensitive requests are coming from
CPUFreq subsystem, which might be used by the scheduler.
Thus, there is a need to measure these delays and capture anomalies.
This change introduces trace events wrapped around transfer code.
Signed-off-by: Lukasz Luba <lukasz.luba@arm.com>
---
drivers/firmware/arm_scmi/driver.c | 9 +++++++++
1 file changed, 9 insertions(+)
diff --git a/drivers/firmware/arm_scmi/driver.c b/drivers/firmware/arm_scmi/driver.c
index 3eb0382491ce..0fda9b418bc6 100644
--- a/drivers/firmware/arm_scmi/driver.c
+++ b/drivers/firmware/arm_scmi/driver.c
@@ -29,6 +29,9 @@
#include "common.h"
+#define CREATE_TRACE_POINTS
+#include <trace/events/scmi.h>
+
#define MSG_ID_MASK GENMASK(7, 0)
#define MSG_XTRACT_ID(hdr) FIELD_GET(MSG_ID_MASK, (hdr))
#define MSG_TYPE_MASK GENMASK(9, 8)
@@ -439,6 +442,9 @@ int scmi_do_xfer(const struct scmi_handle *handle, struct scmi_xfer *xfer)
if (unlikely(!cinfo))
return -EINVAL;
+ trace_scmi_xfer_begin(xfer->hdr.id, xfer->hdr.protocol_id,
+ xfer->hdr.seq, xfer->hdr.poll_completion);
+
ret = mbox_send_message(cinfo->chan, xfer);
if (ret < 0) {
dev_dbg(dev, "mbox send fail %d\n", ret);
@@ -478,6 +484,9 @@ int scmi_do_xfer(const struct scmi_handle *handle, struct scmi_xfer *xfer)
*/
mbox_client_txdone(cinfo->chan, ret);
+ trace_scmi_xfer_end(xfer->hdr.id, xfer->hdr.protocol_id, xfer->hdr.seq,
+ xfer->hdr.status);
+
return ret;
}
--
2.17.1
^ permalink raw reply related [flat|nested] 10+ messages in thread* [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-16 16:16 [PATCH 1/2] include: trace: Add SCMI header with trace events lukasz.luba
2019-12-16 16:16 ` [PATCH 2/2] drivers: firmware: scmi: Extend SCMI transport layer by " lukasz.luba
@ 2019-12-16 22:15 ` Jim Quinlan
2019-12-17 10:05 ` Lukasz Luba
2019-12-18 12:09 ` Sudeep Holla
3 siblings, 0 replies; 10+ messages in thread
From: Jim Quinlan @ 2019-12-16 22:15 UTC (permalink / raw)
To: lukasz.luba; +Cc: linux-arm-kernel, linux-kernel, mingo, rostedt, sudeep.holla
From: Lukasz Luba <lukasz.luba@arm.com>
+
+TRACE_EVENT(scmi_xfer_begin,
+ TP_PROTO(u8 id, u8 protocol_id, u16 seq, bool poll),
+ TP_ARGS(id, protocol_id, seq, poll),
+
+ TP_STRUCT__entry(
+ __field(u8, id)
+ __field(u8, protocol_id)
+ __field(u16, seq)
+ __field(bool, poll)
+ ),
+
+ TP_fast_assign(
+ __entry->id = id;
+ __entry->protocol_id = protocol_id;
+ __entry->seq = seq;
+ __entry->poll = poll;
+ ),
+
+ TP_printk("id=%u protocol_id=%u seq=%u poll=%u", __entry->id,
+ __entry->protocol_id, __entry->seq, __entry->poll)
+);
+
+TRACE_EVENT(scmi_xfer_end,
+ TP_PROTO(u8 id, u8 protocol_id, u16 seq, u32 status),
+ TP_ARGS(id, protocol_id, seq, status),
+
+ TP_STRUCT__entry(
+ __field(u8, id)
+ __field(u8, protocol_id)
+ __field(u16, seq)
+ __field(u32, status)
+ ),
+
+ TP_fast_assign(
+ __entry->id = id;
+ __entry->protocol_id = protocol_id;
+ __entry->seq = seq;
+ __entry->status = status;
+ ),
+
+ TP_printk("id=%u protocol_id=%u seq=%u status=%u", __entry->id,
+ __entry->protocol_id, __entry->seq, __entry->status)
+);
Hello,
When there are multiple messages in the mbox queue, I've found it
a chore matching up the 'begin' event with the 'end' event for each
SCMI msg. The id (command) may not be unique, the proto_id may not be
unique, and the seq may not be unique. The combination of the three
may not be unique. Would it make sense to assign a monotonically
increasing ID to each msg so that one can easily match the two events
for each msg? This id could be the result of an atomic increment and
could be stored in the xfer structure. Of course, it would be one of
the values printed out in the events.
Also, would you consider a third event, right after the
scmi_fetch_response() invocation in scmi_rx_callback()? I've found
this to be insightful in situations where we were debugging a timeout.
I'm fine if you elect not to do the above; I just wanted to post
this for your consideration.
Thanks,
Jim Quinlan
Broadcom
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-16 16:16 [PATCH 1/2] include: trace: Add SCMI header with trace events lukasz.luba
2019-12-16 16:16 ` [PATCH 2/2] drivers: firmware: scmi: Extend SCMI transport layer by " lukasz.luba
2019-12-16 22:15 ` [PATCH 1/2] include: trace: Add SCMI header with " Jim Quinlan
@ 2019-12-17 10:05 ` Lukasz Luba
2019-12-18 12:09 ` Sudeep Holla
3 siblings, 0 replies; 10+ messages in thread
From: Lukasz Luba @ 2019-12-17 10:05 UTC (permalink / raw)
To: Jim Quinlan; +Cc: linux-arm-kernel, linux-kernel, mingo, rostedt, sudeep.holla
Hello Jim,
On 12/16/19 10:15 PM, Jim Quinlan wrote:
> From: Lukasz Luba <lukasz.luba@arm.com>
>
> +
> +TRACE_EVENT(scmi_xfer_begin,
> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, bool poll),
> + TP_ARGS(id, protocol_id, seq, poll),
> +
> + TP_STRUCT__entry(
> + __field(u8, id)
> + __field(u8, protocol_id)
> + __field(u16, seq)
> + __field(bool, poll)
> + ),
> +
> + TP_fast_assign(
> + __entry->id = id;
> + __entry->protocol_id = protocol_id;
> + __entry->seq = seq;
> + __entry->poll = poll;
> + ),
> +
> + TP_printk("id=%u protocol_id=%u seq=%u poll=%u", __entry->id,
> + __entry->protocol_id, __entry->seq, __entry->poll)
> +);
> +
> +TRACE_EVENT(scmi_xfer_end,
> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, u32 status),
> + TP_ARGS(id, protocol_id, seq, status),
> +
> + TP_STRUCT__entry(
> + __field(u8, id)
> + __field(u8, protocol_id)
> + __field(u16, seq)
> + __field(u32, status)
> + ),
> +
> + TP_fast_assign(
> + __entry->id = id;
> + __entry->protocol_id = protocol_id;
> + __entry->seq = seq;
> + __entry->status = status;
> + ),
> +
> + TP_printk("id=%u protocol_id=%u seq=%u status=%u", __entry->id,
> + __entry->protocol_id, __entry->seq, __entry->status)
> +);
>
> Hello,
>
> When there are multiple messages in the mbox queue, I've found it
> a chore matching up the 'begin' event with the 'end' event for each
> SCMI msg. The id (command) may not be unique, the proto_id may not be
> unique, and the seq may not be unique. The combination of the three
> may not be unique. Would it make sense to assign a monotonically
> increasing ID to each msg so that one can easily match the two events
> for each msg? This id could be the result of an atomic increment and
> could be stored in the xfer structure. Of course, it would be one of
> the values printed out in the events.
Hmmm, an atomic variable in this code might be too heavy, especially in
case of fast_switch from cpufreq. Let me think about it and experiment.
>
> Also, would you consider a third event, right after the
> scmi_fetch_response() invocation in scmi_rx_callback()? I've found
> this to be insightful in situations where we were debugging a timeout.
Yes, of course. It would be really useful. Thank you for the
suggestion.
>
> I'm fine if you elect not to do the above; I just wanted to post
> this for your consideration.
Thant's a valuable feedback. I will definitely consider it.
Regards,
Lukasz
>
> Thanks,
> Jim Quinlan
> Broadcom
>
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-16 16:16 [PATCH 1/2] include: trace: Add SCMI header with trace events lukasz.luba
` (2 preceding siblings ...)
2019-12-17 10:05 ` Lukasz Luba
@ 2019-12-18 12:09 ` Sudeep Holla
2019-12-18 16:37 ` Jim Quinlan
3 siblings, 1 reply; 10+ messages in thread
From: Sudeep Holla @ 2019-12-18 12:09 UTC (permalink / raw)
To: Jim Quinlan
Cc: lukasz.luba, linux-arm-kernel, linux-kernel, mingo, rostedt,
Sudeep Holla
On Mon, Dec 16, 2019 at 05:15:54PM -0500, Jim Quinlan wrote:
> From: Lukasz Luba <lukasz.luba@arm.com>
>
> +
> +TRACE_EVENT(scmi_xfer_begin,
> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, bool poll),
> + TP_ARGS(id, protocol_id, seq, poll),
> +
> + TP_STRUCT__entry(
> + __field(u8, id)
> + __field(u8, protocol_id)
> + __field(u16, seq)
> + __field(bool, poll)
> + ),
> +
> + TP_fast_assign(
> + __entry->id = id;
> + __entry->protocol_id = protocol_id;
> + __entry->seq = seq;
> + __entry->poll = poll;
> + ),
> +
> + TP_printk("id=%u protocol_id=%u seq=%u poll=%u", __entry->id,
> + __entry->protocol_id, __entry->seq, __entry->poll)
> +);
> +
> +TRACE_EVENT(scmi_xfer_end,
> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, u32 status),
> + TP_ARGS(id, protocol_id, seq, status),
> +
> + TP_STRUCT__entry(
> + __field(u8, id)
> + __field(u8, protocol_id)
> + __field(u16, seq)
> + __field(u32, status)
> + ),
> +
> + TP_fast_assign(
> + __entry->id = id;
> + __entry->protocol_id = protocol_id;
> + __entry->seq = seq;
> + __entry->status = status;
> + ),
> +
> + TP_printk("id=%u protocol_id=%u seq=%u status=%u", __entry->id,
> + __entry->protocol_id, __entry->seq, __entry->status)
> +);
>
> Hello,
>
> When there are multiple messages in the mbox queue, I've found it
> a chore matching up the 'begin' event with the 'end' event for each
> SCMI msg. The id (command) may not be unique, the proto_id may not be
> unique, and the seq may not be unique.
I agree on id and proto_id part easily and the seq may not be unique
if and only if the previous command has completed.
> The combination of the three may not be unique.
Not 100% sure on that. I remember one of the issue you reported where OS
times out and platform may still be processing it. That's one of the
case where seq id may get re-assigned, but now that's fixed and the
scenario may not happen. I am trying to understand why you think it
is not unique ?
> Would it make sense to assign a monotonically increasing ID to each
> msg so that one can easily match the two events for each msg?
I am not sure if we need to maintain a tracker/counter just for trace
purposes.
> This id could be the result of an atomic increment and
> could be stored in the xfer structure. Of course, it would be one of
> the values printed out in the events.
>
> Also, would you consider a third event, right after the
> scmi_fetch_response() invocation in scmi_rx_callback()? I've found
> this to be insightful in situations where we were debugging a timeout.
>
> I'm fine if you elect not to do the above; I just wanted to post
> this for your consideration.
>
I am interested in the scenario we can make use of this and also help
in testing it if we add this. I am not against it but I don't see the
need for it.
--
Regards,
Sudeep
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-18 12:09 ` Sudeep Holla
@ 2019-12-18 16:37 ` Jim Quinlan
2019-12-19 16:32 ` Jim Quinlan
0 siblings, 1 reply; 10+ messages in thread
From: Jim Quinlan @ 2019-12-18 16:37 UTC (permalink / raw)
To: Sudeep Holla; +Cc: lukasz.luba, linux-arm-kernel, linux-kernel, mingo, rostedt
On 12/18/19 7:09 AM, Sudeep Holla wrote:
> On Mon, Dec 16, 2019 at 05:15:54PM -0500, Jim Quinlan wrote:
>> From: Lukasz Luba <lukasz.luba@arm.com>
>>
>> +
>> +TRACE_EVENT(scmi_xfer_begin,
>> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, bool poll),
>> + TP_ARGS(id, protocol_id, seq, poll),
>> +
>> + TP_STRUCT__entry(
>> + __field(u8, id)
>> + __field(u8, protocol_id)
>> + __field(u16, seq)
>> + __field(bool, poll)
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->id = id;
>> + __entry->protocol_id = protocol_id;
>> + __entry->seq = seq;
>> + __entry->poll = poll;
>> + ),
>> +
>> + TP_printk("id=%u protocol_id=%u seq=%u poll=%u", __entry->id,
>> + __entry->protocol_id, __entry->seq, __entry->poll)
>> +);
>> +
>> +TRACE_EVENT(scmi_xfer_end,
>> + TP_PROTO(u8 id, u8 protocol_id, u16 seq, u32 status),
>> + TP_ARGS(id, protocol_id, seq, status),
>> +
>> + TP_STRUCT__entry(
>> + __field(u8, id)
>> + __field(u8, protocol_id)
>> + __field(u16, seq)
>> + __field(u32, status)
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->id = id;
>> + __entry->protocol_id = protocol_id;
>> + __entry->seq = seq;
>> + __entry->status = status;
>> + ),
>> +
>> + TP_printk("id=%u protocol_id=%u seq=%u status=%u", __entry->id,
>> + __entry->protocol_id, __entry->seq, __entry->status)
>> +);
>>
>> Hello,
>>
>> When there are multiple messages in the mbox queue, I've found it
>> a chore matching up the 'begin' event with the 'end' event for each
>> SCMI msg. The id (command) may not be unique, the proto_id may not be
>> unique, and the seq may not be unique.
> I agree on id and proto_id part easily and the seq may not be unique
> if and only if the previous command has completed.
>
>> The combination of the three may not be unique.
> Not 100% sure on that. I remember one of the issue you reported where OS
> times out and platform may still be processing it. That's one of the
> case where seq id may get re-assigned, but now that's fixed and the
> scenario may not happen. I am trying to understand why you think it
> is not unique ?
If I submit a series of five clk_enable() calls via SCMI, and they are all
executed sequentially, they will most likely have the same seq-proto-cmd value
-- do you agree? Now typically one can match the begin tracepoint with the
end because they come in pairs. But when you are using four protocols and
the mbox queue has more than one, it is difficult to eyeball the trace output
and have a good idea of what is going on. If one uses a post
processing script, that's another story.
>
>> Would it make sense to assign a monotonically increasing ID to each
>> msg so that one can easily match the two events for each msg?
> I am not sure if we need to maintain a tracker/counter just for trace
> purposes.
I was just suggesting this for consideration -- if you deem it not helpful,
or cannot demonstrate its usefulness, by all means do not add it.
I have an alternative method for logging SCMI events that I prefer
(see below as to why).
>
>> This id could be the result of an atomic increment and
>> could be stored in the xfer structure. Of course, it would be one of
>> the values printed out in the events.
>>
>> Also, would you consider a third event, right after the
>> scmi_fetch_response() invocation in scmi_rx_callback()? I've found
>> this to be insightful in situations where we were debugging a timeout.
>>
>> I'm fine if you elect not to do the above; I just wanted to post
>> this for your consideration.
>>
> I am interested in the scenario we can make use of this and also help
> in testing it if we add this. I am not against it but I don't see the
> need for it.
I have a test driver that forks four threads, each of which indirectly
creates SCMI messages of different protocols (sensor, clk, perf, brcm). In other
words, a stress test for the SCMI infrastructure and platform response. I
suspect you have a similar test configuration? I set this up so we can reproduce
some problems w/o having to run the entire middleware stack.
At any rate, I've tested V2, and although I get a lot of
... scmi_xfer_begin: transfer_id=48379 msg_id=7 protocol_id=128 seq=0 poll=0
... scmi_rx_done: transfer_id=48379 msg_id=7 protocol_id=128 seq=0 msg_type=0
... scmi_xfer_end: transfer_id=48380 msg_id=8 protocol_id=128 seq=0 status=0
... scmi_xfer_begin: transfer_id=48381 msg_id=7 protocol_id=128 seq=0 poll=0
... scmi_rx_done: transfer_id=48381 msg_id=7 protocol_id=128 seq=0 msg_type=0
... scmi_xfer_end: transfer_id=48381 msg_id=7 protocol_id=128 seq=0 status=0
... scmi_xfer_begin: transfer_id=48382 msg_id=8 protocol_id=128 seq=0 poll=0
... scmi_rx_done: transfer_id=48382 msg_id=8 protocol_id=128 seq=0 msg_type=0
... scmi_xfer_end: transfer_id=48382 msg_id=8 protocol_id=128 seq=0 status=0
... scmi_xfer_begin: transfer_id=48383 msg_id=7 protocol_id=128 seq=0 poll=0
I also see a stretch of over 100 (contiguous) of these
... scmi_rx_done: transfer_id=48321 msg_id=7 protocol_id=128 seq=0 msg_type=0
... scmi_rx_done: transfer_id=48322 msg_id=8 protocol_id=128 seq=0 msg_type=0
... scmi_rx_done: transfer_id=48323 msg_id=7 protocol_id=128 seq=0 msg_type=0
... scmi_rx_done: transfer_id=48324 msg_id=8 protocol_id=128 seq=0 msg_type=0
which I cannot explain -- perhaps ftrace doesn't work well in interrupt context?
Note also that we use interrupts issued from the platform for both channels.
Regards,
Jim
>
> --
> Regards,
> Sudeep
>
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-18 16:37 ` Jim Quinlan
@ 2019-12-19 16:32 ` Jim Quinlan
2019-12-20 9:20 ` Lukasz Luba
0 siblings, 1 reply; 10+ messages in thread
From: Jim Quinlan @ 2019-12-19 16:32 UTC (permalink / raw)
To: Sudeep Holla; +Cc: lukasz.luba, linux-arm-kernel, linux-kernel, mingo, rostedt
> I also see a stretch of over 100 (contiguous) of these
>
> ... scmi_rx_done: transfer_id=48321 msg_id=7 protocol_id=128 seq=0 msg_type=0
> ... scmi_rx_done: transfer_id=48322 msg_id=8 protocol_id=128 seq=0 msg_type=0
> ... scmi_rx_done: transfer_id=48323 msg_id=7 protocol_id=128 seq=0 msg_type=0
> ... scmi_rx_done: transfer_id=48324 msg_id=8 protocol_id=128 seq=0 msg_type=0
>
> which I cannot explain -- perhaps ftrace doesn't work well in interrupt context?
Hello,
Please ignore my previous results; I've switched to using 'nop' as the
current_tracer and the above issue has cleared up. I now get traces
like below:
<idle>-0 [000] d.h. 907.608763: scmi_rx_done:
transfer_id=10599 msg_id=7 protocol_id=128 seq=2 msg_type=0
t1-sensor-1817 [003] .... 907.608879: scmi_xfer_begin:
transfer_id=10601 msg_id=6 protocol_id=21 seq=1 poll=0
t0-brcm-1815 [000] d.h. 907.614133: scmi_rx_done:
transfer_id=10600 msg_id=7 protocol_id=20 seq=0 msg_type=0
t0-brcm-1815 [000] .... 907.614189: scmi_xfer_end:
transfer_id=10599 msg_id=7 protocol_id=128 seq=2 status=0
t0-brcm-1815 [000] .... 907.614215: scmi_xfer_begin:
transfer_id=10602 msg_id=8 protocol_id=128 seq=2 poll=0
<idle>-0 [000] d.h. 907.616380: scmi_rx_done:
transfer_id=10601 msg_id=6 protocol_id=21 seq=1 msg_type=0
t2-clock-1818 [003] .... 907.616418: scmi_xfer_end:
transfer_id=10600 msg_id=7 protocol_id=20 seq=0 status=0
t2-clock-1818 [003] .... 907.616440: scmi_xfer_begin:
transfer_id=10603 msg_id=7 protocol_id=20 seq=0 poll=0
t1-sensor-1817 [003] .... 907.616474: scmi_xfer_end:
transfer_id=10601 msg_id=6 protocol_id=21 seq=1 status=0
<idle>-0 [000] d.h. 907.616478: scmi_rx_done:
transfer_id=10602 msg_id=8 protocol_id=128 seq=2 msg_type=0
t0-brcm-1815 [000] d.h. 907.616526: scmi_rx_done:
transfer_id=10603 msg_id=7 protocol_id=20 seq=0 msg_type=0
t0-brcm-1815 [000] .... 907.616559: scmi_xfer_end:
transfer_id=10602 msg_id=8 protocol_id=128 seq=2 status=0
t0-brcm-1815 [000] .n.. 907.616588: scmi_xfer_begin:
transfer_id=10604 msg_id=7 protocol_id=128 seq=1 poll=0
t1-sensor-1817 [003] .... 907.616628: scmi_xfer_begin:
transfer_id=10605 msg_id=6 protocol_id=21 seq=2 poll=0
t2-clock-1818 [003] .... 907.616660: scmi_xfer_end:
transfer_id=10603 msg_id=7 protocol_id=20 seq=0 status=0
<idle>-0 [000] d.h. 907.616665: scmi_rx_done:
transfer_id=10604 msg_id=7 protocol_id=128 seq=1 msg_type=0
t2-clock-1818 [003] .... 907.616673: scmi_xfer_begin:
transfer_id=10606 msg_id=7 protocol_id=20 seq=0 poll=0
t0-brcm-1815 [000] d.h. 907.618782: scmi_rx_done:
transfer_id=10605 msg_id=6 protocol_id=21 seq=2 msg_type=0
t1-sensor-1817 [003] .... 907.618829: scmi_xfer_end:
transfer_id=10605 msg_id=6 protocol_id=21 seq=2 status=0
t0-brcm-1815 [000] dnH. 907.618834: scmi_rx_done:
transfer_id=10606 msg_id=7 protocol_id=20 seq=0 msg_type=0
t0-brcm-1815 [000] .n.. 907.618855: scmi_xfer_end:
transfer_id=10604 msg_id=7 protocol_id=128 seq=1 status=0
t0-brcm-1815 [000] .n.. 907.618873: scmi_xfer_begin:
transfer_id=10607 msg_id=8 protocol_id=128 seq=1 poll=0
t2-clock-1818 [003] .... 907.618890: scmi_xfer_end:
transfer_id=10606 msg_id=7 protocol_id=20 seq=0 status=0
rcu_sched-7 [000] d.h. 907.618898: scmi_rx_done:
transfer_id=10607 msg_id=8 protocol_id=128 seq=1 msg_type=0
t0-brcm-1815 [000] .... 907.618934: scmi_xfer_end:
transfer_id=10607 msg_id=8 protocol_id=128 seq=1 status=0
t3-brcm-1819 [003] .... 907.618958: scmi_xfer_begin:
transfer_id=10608 msg_id=7 protocol_id=128 seq=0 poll=0
<idle>-0 [000] d.h. 907.618974: scmi_rx_done:
transfer_id=10608 msg_id=7 protocol_id=128 seq=0 msg_type=0
t3-brcm-1819 [003] .... 907.619005: scmi_xfer_end:
transfer_id=10608 msg_id=7 protocol_id=128 seq=0 status=0
t3-brcm-1819 [003] .... 907.619013: scmi_xfer_begin:
transfer_id=10609 msg_id=8 protocol_id=128 seq=0 poll=0
And with V2 having the added xfer id allows me to more easily post
process the above with a script and highlight messages that took too
long (round trip times > 3msec get a double asterisk):
10585 0.02 ms proto=128 cmd=8 seq=0
10586 2.16 ms proto= 21 cmd=6 seq=0
10587 0.87 ms proto=128 cmd=7 seq=1
10588 0.02 ms proto=128 cmd=8 seq=0
10589 0.05 ms proto=128 cmd=7 seq=0
10590 2.15 ms proto= 21 cmd=6 seq=1
10591 2.19 ms proto=128 cmd=8 seq=0
10592 2.13 ms proto= 21 cmd=6 seq=0
10593 0.03 ms proto=128 cmd=7 seq=0
10594 0.02 ms proto=128 cmd=8 seq=0
10595 0.02 ms proto=128 cmd=7 seq=0
10596 0.02 ms proto=128 cmd=8 seq=0
10597 ** 7.16 ms proto= 20 cmd=7 seq=0
10598 ** 7.12 ms proto= 21 cmd=6 seq=1
10599 ** 11.58 ms proto=128 cmd=7 seq=2
10600 ** 9.28 ms proto= 20 cmd=7 seq=0
10601 ** 7.60 ms proto= 21 cmd=6 seq=1
10602 2.34 ms proto=128 cmd=8 seq=2
10603 0.22 ms proto= 20 cmd=7 seq=0
10604 2.27 ms proto=128 cmd=7 seq=1
10605 2.20 ms proto= 21 cmd=6 seq=2
So I do find the extra msg id helpful as well as the extra traceprint.
Regards,
Jim Quinlan
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-19 16:32 ` Jim Quinlan
@ 2019-12-20 9:20 ` Lukasz Luba
2019-12-20 16:24 ` Jim Quinlan
0 siblings, 1 reply; 10+ messages in thread
From: Lukasz Luba @ 2019-12-20 9:20 UTC (permalink / raw)
To: Jim Quinlan, Sudeep Holla; +Cc: linux-arm-kernel, linux-kernel, mingo, rostedt
Hi Jim,
On 12/19/19 4:32 PM, Jim Quinlan wrote:
>> I also see a stretch of over 100 (contiguous) of these
>>
>> ... scmi_rx_done: transfer_id=48321 msg_id=7 protocol_id=128 seq=0 msg_type=0
>> ... scmi_rx_done: transfer_id=48322 msg_id=8 protocol_id=128 seq=0 msg_type=0
>> ... scmi_rx_done: transfer_id=48323 msg_id=7 protocol_id=128 seq=0 msg_type=0
>> ... scmi_rx_done: transfer_id=48324 msg_id=8 protocol_id=128 seq=0 msg_type=0
>>
>> which I cannot explain -- perhaps ftrace doesn't work well in interrupt context?
>
> Hello,
> Please ignore my previous results; I've switched to using 'nop' as the
> current_tracer and the above issue has cleared up. I now get traces
> like below:
>
> <idle>-0 [000] d.h. 907.608763: scmi_rx_done:
> transfer_id=10599 msg_id=7 protocol_id=128 seq=2 msg_type=0
> t1-sensor-1817 [003] .... 907.608879: scmi_xfer_begin:
> transfer_id=10601 msg_id=6 protocol_id=21 seq=1 poll=0
> t0-brcm-1815 [000] d.h. 907.614133: scmi_rx_done:
> transfer_id=10600 msg_id=7 protocol_id=20 seq=0 msg_type=0
> t0-brcm-1815 [000] .... 907.614189: scmi_xfer_end:
> transfer_id=10599 msg_id=7 protocol_id=128 seq=2 status=0
> t0-brcm-1815 [000] .... 907.614215: scmi_xfer_begin:
> transfer_id=10602 msg_id=8 protocol_id=128 seq=2 poll=0
> <idle>-0 [000] d.h. 907.616380: scmi_rx_done:
> transfer_id=10601 msg_id=6 protocol_id=21 seq=1 msg_type=0
> t2-clock-1818 [003] .... 907.616418: scmi_xfer_end:
> transfer_id=10600 msg_id=7 protocol_id=20 seq=0 status=0
> t2-clock-1818 [003] .... 907.616440: scmi_xfer_begin:
> transfer_id=10603 msg_id=7 protocol_id=20 seq=0 poll=0
> t1-sensor-1817 [003] .... 907.616474: scmi_xfer_end:
> transfer_id=10601 msg_id=6 protocol_id=21 seq=1 status=0
> <idle>-0 [000] d.h. 907.616478: scmi_rx_done:
> transfer_id=10602 msg_id=8 protocol_id=128 seq=2 msg_type=0
> t0-brcm-1815 [000] d.h. 907.616526: scmi_rx_done:
> transfer_id=10603 msg_id=7 protocol_id=20 seq=0 msg_type=0
> t0-brcm-1815 [000] .... 907.616559: scmi_xfer_end:
> transfer_id=10602 msg_id=8 protocol_id=128 seq=2 status=0
> t0-brcm-1815 [000] .n.. 907.616588: scmi_xfer_begin:
> transfer_id=10604 msg_id=7 protocol_id=128 seq=1 poll=0
> t1-sensor-1817 [003] .... 907.616628: scmi_xfer_begin:
> transfer_id=10605 msg_id=6 protocol_id=21 seq=2 poll=0
> t2-clock-1818 [003] .... 907.616660: scmi_xfer_end:
> transfer_id=10603 msg_id=7 protocol_id=20 seq=0 status=0
> <idle>-0 [000] d.h. 907.616665: scmi_rx_done:
> transfer_id=10604 msg_id=7 protocol_id=128 seq=1 msg_type=0
> t2-clock-1818 [003] .... 907.616673: scmi_xfer_begin:
> transfer_id=10606 msg_id=7 protocol_id=20 seq=0 poll=0
> t0-brcm-1815 [000] d.h. 907.618782: scmi_rx_done:
> transfer_id=10605 msg_id=6 protocol_id=21 seq=2 msg_type=0
> t1-sensor-1817 [003] .... 907.618829: scmi_xfer_end:
> transfer_id=10605 msg_id=6 protocol_id=21 seq=2 status=0
> t0-brcm-1815 [000] dnH. 907.618834: scmi_rx_done:
> transfer_id=10606 msg_id=7 protocol_id=20 seq=0 msg_type=0
> t0-brcm-1815 [000] .n.. 907.618855: scmi_xfer_end:
> transfer_id=10604 msg_id=7 protocol_id=128 seq=1 status=0
> t0-brcm-1815 [000] .n.. 907.618873: scmi_xfer_begin:
> transfer_id=10607 msg_id=8 protocol_id=128 seq=1 poll=0
> t2-clock-1818 [003] .... 907.618890: scmi_xfer_end:
> transfer_id=10606 msg_id=7 protocol_id=20 seq=0 status=0
> rcu_sched-7 [000] d.h. 907.618898: scmi_rx_done:
> transfer_id=10607 msg_id=8 protocol_id=128 seq=1 msg_type=0
> t0-brcm-1815 [000] .... 907.618934: scmi_xfer_end:
> transfer_id=10607 msg_id=8 protocol_id=128 seq=1 status=0
> t3-brcm-1819 [003] .... 907.618958: scmi_xfer_begin:
> transfer_id=10608 msg_id=7 protocol_id=128 seq=0 poll=0
> <idle>-0 [000] d.h. 907.618974: scmi_rx_done:
> transfer_id=10608 msg_id=7 protocol_id=128 seq=0 msg_type=0
> t3-brcm-1819 [003] .... 907.619005: scmi_xfer_end:
> transfer_id=10608 msg_id=7 protocol_id=128 seq=0 status=0
> t3-brcm-1819 [003] .... 907.619013: scmi_xfer_begin:
> transfer_id=10609 msg_id=8 protocol_id=128 seq=0 poll=0
>
> And with V2 having the added xfer id allows me to more easily post
> process the above with a script and highlight messages that took too
> long (round trip times > 3msec get a double asterisk):
>
> 10585 0.02 ms proto=128 cmd=8 seq=0
> 10586 2.16 ms proto= 21 cmd=6 seq=0
> 10587 0.87 ms proto=128 cmd=7 seq=1
> 10588 0.02 ms proto=128 cmd=8 seq=0
> 10589 0.05 ms proto=128 cmd=7 seq=0
> 10590 2.15 ms proto= 21 cmd=6 seq=1
> 10591 2.19 ms proto=128 cmd=8 seq=0
> 10592 2.13 ms proto= 21 cmd=6 seq=0
> 10593 0.03 ms proto=128 cmd=7 seq=0
> 10594 0.02 ms proto=128 cmd=8 seq=0
> 10595 0.02 ms proto=128 cmd=7 seq=0
> 10596 0.02 ms proto=128 cmd=8 seq=0
> 10597 ** 7.16 ms proto= 20 cmd=7 seq=0
> 10598 ** 7.12 ms proto= 21 cmd=6 seq=1
> 10599 ** 11.58 ms proto=128 cmd=7 seq=2
> 10600 ** 9.28 ms proto= 20 cmd=7 seq=0
> 10601 ** 7.60 ms proto= 21 cmd=6 seq=1
> 10602 2.34 ms proto=128 cmd=8 seq=2
> 10603 0.22 ms proto= 20 cmd=7 seq=0
> 10604 2.27 ms proto=128 cmd=7 seq=1
> 10605 2.20 ms proto= 21 cmd=6 seq=2
>
> So I do find the extra msg id helpful as well as the extra traceprint.
Thank you for sharing your experiments and thoughts. I have probably
similar setup for stressing the communication channel, but I do also
some wired things in the firmware. That's why I need to measure these
delays. I am happy that it is useful for you also.
I don't know if your firmware supports 'fast channel', but please keep
in mind that it is not tracked in this 'transfer_id'.
This transfer_id in v2 version does not show the real transfers
to the firmware since there is another path called 'fast channel' or
'fast_switch' in the CPUfreq. It is in drivers/firmware/arm_scmi/perf.c
and the atomic variable is not incremented in that path. Adding it also
there just for atomic_inc() probably would add delays in the fast_switch
and also brings little value.
For the normal channel, where we have spinlocks and other stuff, this
atomic_inc() could stay in my opinion.
Regards,
Lukasz
>
> Regards,
> Jim Quinlan
>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-20 9:20 ` Lukasz Luba
@ 2019-12-20 16:24 ` Jim Quinlan
2019-12-23 15:39 ` Lukasz Luba
0 siblings, 1 reply; 10+ messages in thread
From: Jim Quinlan @ 2019-12-20 16:24 UTC (permalink / raw)
To: Lukasz Luba, Sudeep Holla; +Cc: linux-arm-kernel, linux-kernel, mingo, rostedt
> Thank you for sharing your experiments and thoughts. I have probably
> similar setup for stressing the communication channel, but I do also
> some wired things in the firmware. That's why I need to measure these
> delays. I am happy that it is useful for you also.
>
> I don't know if your firmware supports 'fast channel', but please keep
> in mind that it is not tracked in this 'transfer_id'.
> This transfer_id in v2 version does not show the real transfers
> to the firmware since there is another path called 'fast channel' or
> 'fast_switch' in the CPUfreq. It is in drivers/firmware/arm_scmi/perf.c
> and the atomic variable is not incremented in that path. Adding it also
> there just for atomic_inc() probably would add delays in the fast_switch
> and also brings little value.
> For the normal channel, where we have spinlocks and other stuff, this
> atomic_inc() could stay in my opinion.
>
> Regards,
> Lukasz
Hi Lukasz,
We currently do not use "fast channels" - although it is possible we might someday.
I find the transfer_id useful per your v2 even if it doesn't cover FC. Thanks for
submitting and discussing this!
Regards,
Jim Quinlan
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
2019-12-20 16:24 ` Jim Quinlan
@ 2019-12-23 15:39 ` Lukasz Luba
0 siblings, 0 replies; 10+ messages in thread
From: Lukasz Luba @ 2019-12-23 15:39 UTC (permalink / raw)
To: Jim Quinlan, Sudeep Holla; +Cc: linux-arm-kernel, linux-kernel, mingo, rostedt
On 12/20/19 4:24 PM, Jim Quinlan wrote:
>
>> Thank you for sharing your experiments and thoughts. I have probably
>> similar setup for stressing the communication channel, but I do also
>> some wired things in the firmware. That's why I need to measure these
>> delays. I am happy that it is useful for you also.
>>
>> I don't know if your firmware supports 'fast channel', but please keep
>> in mind that it is not tracked in this 'transfer_id'.
>> This transfer_id in v2 version does not show the real transfers
>> to the firmware since there is another path called 'fast channel' or
>> 'fast_switch' in the CPUfreq. It is in drivers/firmware/arm_scmi/perf.c
>> and the atomic variable is not incremented in that path. Adding it also
>> there just for atomic_inc() probably would add delays in the fast_switch
>> and also brings little value.
>> For the normal channel, where we have spinlocks and other stuff, this
>> atomic_inc() could stay in my opinion.
>>
>> Regards,
>> Lukasz
> Hi Lukasz,
>
> We currently do not use "fast channels" - although it is possible we might someday.
> I find the transfer_id useful per your v2 even if it doesn't cover FC. Thanks for
> submitting and discussing this!
Thank you for cooperation.
Regards,
Lukasz
>
> Regards,
> Jim Quinlan
>
^ permalink raw reply [flat|nested] 10+ messages in thread