| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Thu, 19 Dec 2019 11:32:07 -0500
From: Jim Quinlan <james.quinlan@...adcom.com>
To: Sudeep Holla <sudeep.holla@....com>
Cc: lukasz.luba@....com, linux-arm-kernel@...ts.infradead.org,
linux-kernel@...r.kernel.org, mingo@...hat.com, rostedt@...dmis.org
Subject: Re: [PATCH 1/2] include: trace: Add SCMI header with trace events
> 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
Powered by blists - more mailing lists