From: Lukasz Luba <lukasz.luba@arm.com>
To: Jim Quinlan <james.quinlan@broadcom.com>,
Sudeep Holla <sudeep.holla@arm.com>
Cc: linux-arm-kernel@lists.infradead.org,
linux-kernel@vger.kernel.org, mingo@redhat.com,
rostedt@goodmis.org
Subject: Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
Date: Fri, 20 Dec 2019 09:20:40 +0000 [thread overview]
Message-ID: <7fe599d3-1ce2-1fde-2911-9516a26090b6@arm.com> (raw)
In-Reply-To: <CA+-6iNxn29WpUrbc9gL4EMTJfZj7FRCeO-_QaUqbjJYd1JAEKA@mail.gmail.com>
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
>
next prev parent reply other threads:[~2019-12-20 9:20 UTC|newest]
Thread overview: 10+ messages / expand[flat|nested] mbox.gz Atom feed top
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
2019-12-18 16:37 ` Jim Quinlan
2019-12-19 16:32 ` Jim Quinlan
2019-12-20 9:20 ` Lukasz Luba [this message]
2019-12-20 16:24 ` Jim Quinlan
2019-12-23 15:39 ` Lukasz Luba
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=7fe599d3-1ce2-1fde-2911-9516a26090b6@arm.com \
--to=lukasz.luba@arm.com \
--cc=james.quinlan@broadcom.com \
--cc=linux-arm-kernel@lists.infradead.org \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@redhat.com \
--cc=rostedt@goodmis.org \
--cc=sudeep.holla@arm.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).