| Message ID | 20191216161650.21844-1-lukasz.luba@arm.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [1/2] include: trace: Add SCMI header with trace events | expand |
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
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 >
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
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 >
> 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
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 >
> 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
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 >
diff --git a/MAINTAINERS b/MAINTAINERS index cc0a4a8ae06a..0182315226fc 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -15966,6 +15966,7 @@ F: drivers/firmware/arm_scpi.c F: drivers/firmware/arm_scmi/ F: drivers/reset/reset-scmi.c F: include/linux/sc[mp]i_protocol.h +F: include/trace/events/scmi.h SYSTEM RESET/SHUTDOWN DRIVERS M: Sebastian Reichel <sre@kernel.org> diff --git a/include/trace/events/scmi.h b/include/trace/events/scmi.h new file mode 100644 index 000000000000..a84016b02ffd --- /dev/null +++ b/include/trace/events/scmi.h @@ -0,0 +1,56 @@ +/* SPDX-License-Identifier: GPL-2.0 */ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM scmi + +#if !defined(_TRACE_SCMI_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_SCMI_H + +#include <linux/tracepoint.h> + +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) +); +#endif /* _TRACE_SCMI_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h>