Re: weird loadavg on idle machine post 5.7

Paul Gortmaker
2020-07-02T21:17:04Z

[weird loadavg on idle machine post 5.7] On 02/07/2020 (Thu 13:15) Dave Jones wrote:

> When I upgraded my firewall to 5.7-rc2 I noticed that on a mostly
> idle machine (that usually sees loadavg hover in the 0.xx range)
> that it was consistently above 1.00 even when there was nothing running.
> All that perf showed was the kernel was spending time in the idle loop
> (and running perf).
>
> For the first hour or so after boot, everything seems fine, but over
> time loadavg creeps up, and once it's established a new baseline, it
> never seems to ever drop below that again.
>
> One morning I woke up to find loadavg at '7.xx', after almost as many
> hours of uptime, which makes me wonder if perhaps this is triggered
> by something in cron. I have a bunch of scripts that fire off
> every hour that involve thousands of shortlived runs of iptables/ipset,
> but running them manually didn't seem to automatically trigger the bug.
>
> Given it took a few hours of runtime to confirm good/bad, bisecting this
> took the last two weeks. I did it four different times, the first

I've seen pretty much the same thing - I was helping paulmck test
rcu-dev for something hopefully unrelated, when I 1st saw it, and
assumed it came in with the sched-core merge and was using one under
that as "good" to attempt bisect.

> producing bogus results from over-eager 'good', but the last two runs

Yeah - it sucks. I was using Paul's TREE03 rcu-torture for loading and
even after a two hour test I'd still get "false good" results. Only
after 7h was I quite confident that good was really good.

> both implicated this commit:
>
> commit c6e7bd7afaeb3af55ffac122828035f1c01d1d7b (refs/bisect/bad)
> Author: Peter Zijlstra <peterz@infradead.org>
> Date: Sun May 24 21:29:55 2020 +0100
>
> sched/core: Optimize ttwu() spinning on p->on_cpu

I was down to 10 commits roughly above and below this guy before hearing
you were working the same problem.

I just got this guy to reveal a false load after a 2h test as well.
I want to let the one underneath soak overnight just to also confirm it
is "good" - so that is pending.

What I can add, is that it is like we are "leaking" an instance into
calc_load_tasks -- which isn't anything new -- see when tglx fixed it
before in d60585c5766. Unfortunate we don't have some low overhead leak
checks on that... ?

Anyway, if I "fix" the leak, then everything seems back to normal:

(gdb) p calc_load_tasks
$2 = {counter = 1}
(gdb) set variable calc_load_tasks = { 0 }
(gdb) p calc_load_tasks
$4 = {counter = 0}
(gdb) continue
Continuing.

[ ... watching decay on resumed target ....]

10:13:14 up 9:54, 4 users, load average: 0.92, 0.98, 1.15
10:13:54 up 9:55, 4 users, load average: 0.47, 0.86, 1.10
10:15:17 up 9:56, 4 users, load average: 0.12, 0.65, 1.00
10:19:20 up 10:00, 4 users, load average: 0.00, 0.28, 0.76
10:26:07 up 10:07, 4 users, load average: 0.00, 0.06, 0.48
10:32:48 up 10:14, 4 users, load average: 0.00, 0.00, 0.29

Obviously that isn't a fix, but it shows it is an accounting thing.
I've also used gdb to snoop all the cfs->avg fields and they look as
expected for a completely idle machine. Nothing hiding in avg_rt or
avg_dl either.

>
> Both Rik and Mel reported seeing ttwu() spend significant time on:
>
> smp_cond_load_acquire(&p->on_cpu, !VAL);
>
> Attempt to avoid this by queueing the wakeup on the CPU that owns the
> p->on_cpu value. This will then allow the ttwu() to complete without
> further waiting.
>
> Since we run schedule() with interrupts disabled, the IPI is
> guaranteed to happen after p->on_cpu is cleared, this is what makes it
> safe to queue early.
>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> Signed-off-by: Mel Gorman <mgorman@techsingularity.net>
> Signed-off-by: Ingo Molnar <mingo@kernel.org>
> Cc: Jirka Hladky <jhladky@redhat.com>
> Cc: Vincent Guittot <vincent.guittot@linaro.org>
> Cc: valentin.schneider@arm.com
> Cc: Hillf Danton <hdanton@sina.com>
> Cc: Rik van Riel <riel@surriel.com>
> Link: https://lore.kernel.org/r/20200524202956.27665-2-mgorman@techsingularity.net
>
> Unfortunatly it doesn't revert cleanly on top of rc3 so I haven't
> confirmed 100% that it's the cause yet, but the two separate bisects
> seem promising.

I've not tried the revert (yet) - but Kyle saw me boring people on
#kernel with the details of bisecting this and gave me the heads-up you
were looking at it too (thanks Kyle!). So I figured I'd better add
what I'd seen so far.

I'm testing with what is largely a defconfig, plus KVM_INTEL (needed for
paulmck TREE03 rcu-torture), plus I enabled KGDB and DEBUG_INFO after a
while so I could poke and prod - but was reproducing it before that.

For completeness, the test was:

tools/testing/selftests/rcutorture/bin/kvm.sh --cpus 24 --duration 120 \
--configs TREE03 --trust-make

...on a 24 core 2013 vintage xeon-v2 COTS box. As above, the 120m
seemed to give between 60-75% confidence on not getting a false good.

Anyway - so that is all I know so far...

Paul.
--

>
> I don't see any obvious correlation between what's changing there and
> the symtoms (other than "scheduler magic") but maybe those closer to
> this have ideas what could be going awry ?
>
> Dave