Re: ftrace performance (sched events): cyclictest shows 25% more latency
From: Steven Rostedt
Date: Fri Jul 06 2018 - 18:00:25 EST
On Fri, 6 Jul 2018 17:39:22 -0400
Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> On Fri, 6 Jul 2018 17:24:28 -0400
> Steven Rostedt <rostedt@xxxxxxxxxxx> 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