Hi Vincent, On 2018-04-20 18:00:13 +0200, Vincent Guittot wrote: [snip] > > > > You results are similar to Heiner's ones. The problem is still there > > even if we only kick ilb which mainly send an IPI reschedule to the > > other CPU if Idle > > > > Could it be possible to record some traces of the problem to get a better view > of what happens ? > > I have a small patch that adds some traces in the functions that seems to create > the problem Sure, I applied the patch bellow on-top of c18bb396d3d261eb ("Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net"). > > --- > kernel/sched/fair.c | 6 ++++++ > 1 file changed, 6 insertions(+) > > diff --git a/kernel/sched/fair.c b/kernel/sched/fair.c > index 0951d1c..a951464 100644 > --- a/kernel/sched/fair.c > +++ b/kernel/sched/fair.c > @@ -9606,6 +9606,8 @@ static bool _nohz_idle_balance(struct rq *this_rq, unsigned int flags, > */ > WRITE_ONCE(nohz.has_blocked, 0); > > + trace_printk("_nohz_idle_balance cpu %d idle %d flag %x", this_cpu, idle, flags); > + > /* > * Ensures that if we miss the CPU, we must see the has_blocked > * store from nohz_balance_enter_idle(). > @@ -9680,6 +9682,8 @@ static bool _nohz_idle_balance(struct rq *this_rq, unsigned int flags, > if (likely(update_next_balance)) > nohz.next_balance = next_balance; > > + trace_printk("_nohz_idle_balance return %d", ret); > + > return ret; > } > > @@ -9732,6 +9736,8 @@ static void nohz_newidle_balance(struct rq *this_rq) > time_before(jiffies, READ_ONCE(nohz.next_blocked))) > return; > > + trace_printk("nohz_newidle_balance start update"); > + > raw_spin_unlock(&this_rq->lock); > /* > * This CPU is going to be idle and blocked load of idle CPUs > -- > 2.7.4 > > > Also that would be good to stop tracing when the RCU stall happens > > In case you are not familiar with the trace tool, I have put below how to configure ftrace to trace scheudler, irq, timer ... events and stop tracing when dump_backtrace function is called > > trace-cmd reset > /dev/null > trace-cmd start -b 40000 -p function -l dump_backtrace:traceoff -e sched -e cpu_idle -e cpu_frequency -e timer -e ipi -e irq -e printk > trace-cmd start -b 40000 -p function -l dump_backtrace > > The trace-cmd start has to be called twice to make sure that we will not trace all function > > Once the dump happen and the trace is stopped, you can extract the traces with > > trace-cmd extract -o Thanks for the help with trace-cmd, I have attached the full trace-cmd.dat extracted from running this. But a quick run of trace-cmd report. trace-cmd-1948 [000] 144.504072: bputs: pick_next_task_fair: nohz_newidle_balance start update trace-cmd-1948 [000] 144.504079: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 trace-cmd-1948 [000] 144.504082: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 144.572757: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 144.572765: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 144.572771: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 144.612750: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 144.612752: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 144.612757: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 145.032809: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 145.032813: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 145.032817: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/u5:0-460 [001] 145.249412: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/u5:0-460 [001] 145.249416: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/u5:0-460 [001] 145.249418: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [001] 145.362764: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [001] 145.362773: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 rcu_sched-9 [001] 145.362775: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 systemd-journal-1090 [001] 145.582817: bputs: pick_next_task_fair: nohz_newidle_balance start update systemd-journal-1090 [001] 145.582822: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 systemd-journal-1090 [001] 145.582824: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 146.392753: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 146.392756: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 146.392760: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 systemd-udevd-1723 [000] 146.832885: bputs: pick_next_task_fair: nohz_newidle_balance start update systemd-udevd-1723 [000] 146.832891: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 systemd-udevd-1723 [000] 146.832893: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [001] 146.882739: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [001] 146.882742: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 rcu_sched-9 [001] 146.882747: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 haveged-1823 [001] 146.952985: bputs: pick_next_task_fair: nohz_newidle_balance start update haveged-1823 [001] 146.952988: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 haveged-1823 [001] 146.952993: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 147.002743: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 147.002752: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 147.002755: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 147.042741: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 147.042744: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 147.042748: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 147.082741: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 147.082743: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 147.082748: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 sshd-1881 [000] 147.277339: bputs: pick_next_task_fair: nohz_newidle_balance start update sshd-1881 [000] 147.277343: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 sshd-1881 [000] 147.277346: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 147.342741: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 147.342749: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 147.342754: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rcu_sched-9 [000] 147.382739: bputs: pick_next_task_fair: nohz_newidle_balance start update rcu_sched-9 [000] 147.382741: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 rcu_sched-9 [000] 147.382745: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 sshd-1881 [000] 147.621105: bputs: pick_next_task_fair: nohz_newidle_balance start update sshd-1881 [000] 147.621108: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 0 idle 2 flag 2 sshd-1881 [000] 147.621110: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 -0 [001] 147.662725: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 0 flag 2 -0 [001] 147.662730: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 151.032830: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 151.032833: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 151.032835: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 155.032777: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 155.032780: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 155.032781: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 haveged-1823 [001] 155.515789: bputs: pick_next_task_fair: nohz_newidle_balance start update haveged-1823 [001] 155.515792: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 haveged-1823 [001] 155.515794: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 157.032718: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 157.032720: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 157.032722: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 159.032724: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 159.032726: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 159.032728: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 161.032698: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 161.032701: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 161.032702: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 165.032671: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 165.032673: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 165.032675: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 167.032667: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 167.032669: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 167.032671: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 169.032654: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 169.032657: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 169.032658: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rpcbind-1847 [001] 169.472688: bputs: pick_next_task_fair: nohz_newidle_balance start update rpcbind-1847 [001] 169.472691: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 rpcbind-1847 [001] 169.472693: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 kworker/1:1-31 [001] 171.032660: bputs: pick_next_task_fair: nohz_newidle_balance start update kworker/1:1-31 [001] 171.032662: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 kworker/1:1-31 [001] 171.032664: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 rpcbind-1847 [001] 199.482558: bputs: pick_next_task_fair: nohz_newidle_balance start update rpcbind-1847 [001] 199.482561: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 2 flag 2 rpcbind-1847 [001] 199.482563: bprint: _nohz_idle_balance: _nohz_idle_balance return 1 -0 [000] 241.615152: function: dump_backtrace -- Regards, Niklas Söderlund