| 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
| ||
|
Message-ID: <20180422221827.GB27674@bigcity.dyn.berto.se>
Date: Mon, 23 Apr 2018 00:18:27 +0200
From: Niklas Söderlund
<niklas.soderlund@...natech.se>
To: Vincent Guittot <vincent.guittot@...aro.org>
Cc: Heiner Kallweit <hkallweit1@...il.com>,
Peter Zijlstra <peterz@...radead.org>,
"Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
Ingo Molnar <mingo@...hat.com>,
linux-kernel <linux-kernel@...r.kernel.org>,
linux-renesas-soc@...r.kernel.org
Subject: Re: Potential problem with 31e77c93e432dec7 ("sched/fair: Update
blocked load when newly idle")
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 <trace file name>
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
<idle>-0 [001] 147.662725: bprint: _nohz_idle_balance: _nohz_idle_balance cpu 1 idle 0 flag 2
<idle>-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
<idle>-0 [000] 241.615152: function: dump_backtrace
--
Regards,
Niklas Söderlund
Download attachment "trace-cmd.dat.gz" of type "application/gzip" (342838 bytes)
Powered by blists - more mailing lists