Bug#789796: systemd[1]: Looping too fast. Throttling execution a little.

[Martin von Wittich]

Hi,

here are the results so far:

Domain-0: systemd 215-17+deb8u4

> xendev.iserv.eu ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> xendev.iserv.eu ~ # zgrep BUG /var/log/syslog* | wc -l
> 0
> xendev.iserv.eu ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> xendev.iserv.eu ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0

build-i386: systemd 215-17+deb8u4

> build-i386.iserv.eu ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> build-i386.iserv.eu ~ # zgrep BUG /var/log/syslog* | wc -l
> 1
> build-i386.iserv.eu ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> build-i386.iserv.eu ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0

dev2: systemd 215-17+deb8u4

> dev2.iserv.eu ~ # zgrep Loop /var/log/syslog* | wc -l
> 232
> dev2.iserv.eu ~ # zgrep BUG /var/log/syslog* | wc -l
> 412
> dev2.iserv.eu ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> dev2.iserv.eu ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0

tim: systemd 215-17+deb8u4

> tim.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> tim.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 46
> tim.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> tim.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 8

dev3: systemd 215-17+deb8u5~1.gbp51d6e1

> dev3.iserv.eu ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> dev3.iserv.eu ~ # zgrep BUG /var/log/syslog* | wc -l
> 755
> dev3.iserv.eu ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> dev3.iserv.eu ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 18

janis: systemd 215-17+deb8u5~1.gbp51d6e1

> janis.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> janis.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 64
> janis.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> janis.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 4

gunnar: systemd 215-17+deb8u5~1.gbp51d6e1

> gunnar.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> gunnar.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 26
> gunnar.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> gunnar.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 5

jerg: systemd 215-17+deb8u5~1.gbp51d6e1

> jerg.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> jerg.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 46
> jerg.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> jerg.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 34

dominik: systemd 215-17+deb8u5~1.gbp51d6e1

> dominik.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 8560
> dominik.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 34
> dominik.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> dominik.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 6

florian: systemd 215-17+deb8u5~1.gbp51d6e1

> florian.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 4124
> florian.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 620
> florian.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> florian.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 7

max: systemd 215-17+deb8u5~1.gbp51d6e1

> max.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> max.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 32
> max.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> max.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 1

redmine: systemd 215-17+deb8u5~1.gbp51d6e1

> redmine.iserv.eu ~ # zgrep Loop /var/log/syslog* | wc -l
> 0
> redmine.iserv.eu ~ # zgrep BUG /var/log/syslog* | wc -l
> 0
> redmine.iserv.eu ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> redmine.iserv.eu ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0

joerg: systemd 215-17+deb8u5~1.gbp51d6e1

> joerg.mein-iserv.de ~ # zgrep Loop /var/log/syslog* | wc -l
> 21483
> joerg.mein-iserv.de ~ # zgrep BUG /var/log/syslog* | wc -l
> 30
> joerg.mein-iserv.de ~ # zgrep Loop /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0
> joerg.mein-iserv.de ~ # zgrep BUG /var/log/syslog{-20160712.gz,-20160713,} | wc -l
> 0

As you can see, there wasn't a single "Looping too fast" message in the 
last 3 syslogs (2016-07-12 0:00 to 2016-07-14 ~2:00) [zgrep Loop 
/var/log/syslog{-20160712.gz,-20160713,} output], although most VMs had 
been affected by this issue in the past [zgrep Loop /var/log/syslog* 
output].

Unfortunately this is true both for VMs with systemd 
215-17+deb8u5~1.gbp51d6e1 and for VMs with systemd 215-17+deb8u4, so in 
the last three days, not even the old version of systemd had this issue. 
Maybe the bug is exacerbated by CPU starvation, so that in the past it 
started on a single VM, and then spread like a domino effect to the 
remaining ones because the host CPUs were completely overloaded, and now 
there are no longer enough vulnerable VMs to set it off reliably?

There are still "BUG: soft lockup" messages on some VMs, but these 
almost all occured at pretty much exactly 0:00 o'clock, which is the 
time when logrotate runs on our servers (we like our logs to begin and 
end at 0:00 o'clock exactly), so I suppose the host CPU is just 
overburdened when all these rotations and daemon restarts happen at the 
exact same time.

I haven't gotten any reports from my colleagues of any other issues 
since I upgraded most of the machines to systemd 
215-17+deb8u5~1.gbp51d6e1, so I'd say so far it's looking pretty good. I 
will post new results on Friday.

-- 
Mit freundlichen Grüßen,
Martin von Wittich

IServ GmbH
Bültenweg 73
38106 Braunschweig

Telefon:   0531-2243666-0
Fax:       0531-2243666-9
E-Mail:    info at iserv.eu
Internet:  iserv.eu

USt-IdNr. DE265149425 | Amtsgericht Braunschweig | HRB 201822
Geschäftsführer: Benjamin Heindl, Jörg Ludwig