From: Steven Rostedt <rostedt@goodmis.org>
To: Claudio <claudio.fontana@gliwa.com>
Cc: Ingo Molnar <mingo@redhat.com>,
Peter Zijlstra <peterz@infradead.org>,
Thomas Gleixner <tglx@linutronix.de>,
linux-kernel@vger.kernel.org
Subject: Re: ftrace performance (sched events): cyclictest shows 25% more latency
Date: Fri, 6 Jul 2018 18:00:17 -0400 [thread overview]
Message-ID: <20180706180017.1f52ba5f@gandalf.local.home> (raw)
In-Reply-To: <20180706173922.734616de@gandalf.local.home>
On Fri, 6 Jul 2018 17:39:22 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:
> On Fri, 6 Jul 2018 17:24:28 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > I'll investigate further.
>
> Note, I enabled function tracing to trace the scheduler function:
>
> # trace-cmd start -p function -l schedule
>
> And then ran cyclictest. That does not cause any noticeable increase
> in latency (try it). So there is some kind of side effect with the
> trace event itself, and not the recording of the event.
It does add some noise but not nearly as much as a trace event. But,
then I did function graph tracing:
First I did:
trace-cmd record -p function_graph -l schedule /work/git-local/rt-tests.git/cyclictest --smp -p95 -m -s -N -l 100000 -q
And got this:
<idle>-0 [000] 3034.534021: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.534029: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.534043: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.535084: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.535086: funcgraph_exit: # 1056.055 us | }
trace-cmd-1693 [000] 3034.535090: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.535093: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.536146: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.536147: funcgraph_exit: # 1056.563 us | }
trace-cmd-1693 [000] 3034.536150: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.536153: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.537206: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.537207: funcgraph_exit: # 1056.107 us | }
trace-cmd-1693 [000] 3034.537210: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.537213: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.538262: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.538263: funcgraph_exit: # 1053.077 us | }
trace-cmd-1693 [000] 3034.538265: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.538266: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.538554: sched_switch: swapper/0:0 [120] S ==> cyclictest:1698 [120]
cyclictest-1698 [000] 3034.538565: funcgraph_entry: | schedule() {
cyclictest-1698 [000] 3034.538566: sched_switch: cyclictest:1698 [4] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.539318: sched_switch: swapper/0:0 [120] S ==> trace-cmd:1693 [120]
trace-cmd-1693 [000] 3034.539319: funcgraph_exit: # 1053.723 us | }
trace-cmd-1693 [000] 3034.539322: funcgraph_entry: | schedule() {
trace-cmd-1693 [000] 3034.539324: sched_switch: trace-cmd:1693 [120] D ==> swapper/0:0 [120]
<idle>-0 [000] 3034.539567: sched_switch: swapper/0:0 [120] S ==> cyclictest:1698 [4]
cyclictest-1698 [000] 3034.539567: funcgraph_exit: # 1002.624 us | }
And that continued on as normal.
Then I ran it like this:
trace-cmd record -p function_graph -l schedule /work/git-local/rt-tests.git/cyclictest --smp -p95 -m -s -N -l 100000 -q
And this was my result:
trace-cmd-1749 [000] 3321.110772: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.111826: funcgraph_exit: # 1053.004 us | }
trace-cmd-1749 [000] 3321.111830: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.112885: funcgraph_exit: # 1054.734 us | }
trace-cmd-1749 [000] 3321.112888: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.113930: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.113942: funcgraph_exit: # 1054.240 us | }
trace-cmd-1749 [000] 3321.113947: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.114933: funcgraph_exit: # 1002.600 us | }
cyclictest-1756 [000] 3321.114935: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.115000: funcgraph_exit: # 1053.451 us | }
trace-cmd-1749 [000] 3321.115004: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.115939: funcgraph_exit: # 1003.116 us | }
cyclictest-1756 [000] 3321.115941: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.116058: funcgraph_exit: # 1054.142 us | }
trace-cmd-1749 [000] 3321.116061: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.116945: funcgraph_exit: # 1003.559 us | }
cyclictest-1756 [000] 3321.116947: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.117115: funcgraph_exit: # 1053.649 us | }
trace-cmd-1749 [000] 3321.117119: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.117951: funcgraph_exit: # 1003.586 us | }
cyclictest-1756 [000] 3321.117953: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.118172: funcgraph_exit: # 1053.264 us | }
trace-cmd-1749 [000] 3321.118176: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.118957: funcgraph_exit: # 1003.656 us | }
cyclictest-1756 [000] 3321.118960: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.119230: funcgraph_exit: # 1053.770 us | }
trace-cmd-1749 [000] 3321.119234: funcgraph_entry: | schedule() {
cyclictest-1756 [000] 3321.119965: funcgraph_exit: # 1004.830 us | }
cyclictest-1756 [000] 3321.119967: funcgraph_entry: | schedule() {
trace-cmd-1749 [000] 3321.120286: funcgraph_exit: # 1052.469 us | }
No noticeable difference in the time the scheduler took (going to and
from idle).
-- Steve
next prev parent reply other threads:[~2018-07-06 22:00 UTC|newest]
Thread overview: 17+ messages / expand[flat|nested] mbox.gz Atom feed top
2018-07-06 6:22 ftrace performance (sched events): cyclictest shows 25% more latency Claudio
2018-07-06 21:24 ` Steven Rostedt
2018-07-06 21:39 ` Steven Rostedt
2018-07-06 22:00 ` Steven Rostedt [this message]
2018-07-09 10:06 ` Claudio
2018-07-09 14:53 ` Claudio
2018-07-09 15:11 ` Steven Rostedt
2018-07-09 15:32 ` Steven Rostedt
2018-07-24 9:58 ` ftrace global trace_pipe_raw Claudio
2018-07-24 14:23 ` Steven Rostedt
2018-07-24 14:25 ` Steven Rostedt
2018-07-24 15:30 ` Claudio
2018-12-19 11:32 ` Claudio
2018-12-19 16:37 ` Steven Rostedt
2019-01-16 8:00 ` Claudio
2019-01-16 13:47 ` Steven Rostedt
2018-07-24 9:59 ` Claudio
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=20180706180017.1f52ba5f@gandalf.local.home \
--to=rostedt@goodmis.org \
--cc=claudio.fontana@gliwa.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@redhat.com \
--cc=peterz@infradead.org \
--cc=tglx@linutronix.de \
/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).