linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Jim Quinlan <james.quinlan@broadcom.com>
To: Sudeep Holla <sudeep.holla@arm.com>
Cc: lukasz.luba@arm.com, 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: Thu, 19 Dec 2019 11:32:07 -0500	[thread overview]
Message-ID: <CA+-6iNxn29WpUrbc9gL4EMTJfZj7FRCeO-_QaUqbjJYd1JAEKA@mail.gmail.com> (raw)
In-Reply-To: <7b59a2f1-0786-d24f-a653-76a60c15a8ae@broadcom.com>

> 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

  reply	other threads:[~2019-12-19 16:32 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 [this message]
2019-12-20  9:20       ` Lukasz Luba
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=CA+-6iNxn29WpUrbc9gL4EMTJfZj7FRCeO-_QaUqbjJYd1JAEKA@mail.gmail.com \
    --to=james.quinlan@broadcom.com \
    --cc=linux-arm-kernel@lists.infradead.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=lukasz.luba@arm.com \
    --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).