Bug 1769928

Summary: systemd leaks memory (in dbus) and spends its time sending PropertiesChanged notifications
Product: Red Hat Enterprise Linux 7 Reporter: Renaud Métrich <rmetrich>
Component: systemdAssignee: systemd-maint
Status: CLOSED ERRATA QA Contact: Frantisek Sumsal <fsumsal>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 7.7CC: acomabon, amarirom, azone, jreznik, jsynacek, kwalker, mrobson, msekleta, qguo, sbroz, sfu, systemd-maint-list, systemd-maint
Target Milestone: rcKeywords: Patch, Reproducer, ZStream
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1817503 1817504 1917520 1920506 (view as bug list) Environment:
Last Closed: 2020-09-29 20:32:23 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1817503, 1817504, 1917520, 1920506    

Description Renaud Métrich 2019-11-07 17:55:51 UTC
Description of problem:

A customer running Openshift 3.11 is suffering an issue on multiple systems running latest systemd (systemd-219-67.el7_7.1) where he sees systemd consuming 48GB of memory and spending his time sending PropertiesChanged notifications for all devices in loop.
Early investigation shows over a 30s period, systemd
- executed epoll_wait() only 95 times, returning immediately
- read udev 71462 times
- sent 34888 PropertiesChanged notifications (637 devices per "epoll" round)

Extracting coredump informations using "strings" shows the memory is allocated for DBus messages: (strings coredump | sort | uniq -c | sort -nr)

35328408 sa{sv}as
17936804 PropertiesChanged
17902069 org.freedesktop.DBus.Properties
...


Version-Release number of selected component (if applicable):

systemd-219-67.el7_7.1


How reproducible:

Don't know. Often on customer prod boxes

Comment 6 Renaud Métrich 2020-01-21 12:12:05 UTC
Simple reproducer:

1. Create the following "reproducer.gdb" script

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
break src/libsystemd/sd-bus/sd-bus.c:2748

commands
	if (r == 1)
		printf "r = %d; bus's FD = %d; sleeping 25 seconds to enter condition\n", r, bus->output_fd
		shell sleep 25
	else
		if (r == -110)
			printf "r = %d; bus's FD = %d; condition met, systemd should be leaking now\n", r, bus->output_fd
			delete
		end
	end
	continue
end

continue
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

2. Attach gdb to running systemd with reproducer

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# gdb -x reproducer.gdb /usr/lib/systemd/systemd 1
[...]
Breakpoint 1 at 0x56421918c2c8: file src/libsystemd/sd-bus/sd-bus.c, line 2748.
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

3. From another terminal, execute systemctl

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# systemctl
Failed to list units: Connection timed out
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

gdb output:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Breakpoint 1, bus_process_internal (bus=0x56421a570230, hint_priority=hint_priority@entry=false, 
    priority=priority@entry=0, ret=ret@entry=0x0) at src/libsystemd/sd-bus/sd-bus.c:2748
2748	                if (r == -ENOTCONN || r == -ECONNRESET || r == -EPIPE || r == -ESHUTDOWN) {
r = 1; bus's FD = 21; sleeping 25 seconds to enter condition

Breakpoint 1, bus_process_internal (bus=0x56421a570230, hint_priority=hint_priority@entry=false, 
    priority=priority@entry=0, ret=ret@entry=0x0) at src/libsystemd/sd-bus/sd-bus.c:2748
2748	                if (r == -ENOTCONN || r == -ECONNRESET || r == -EPIPE || r == -ESHUTDOWN) {
r = -110; bus's FD = 21; condition met, systemd should be leaking now
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

4. Watch memory growing with time passing

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# grep VmRSS /proc/1/status
VmRSS:	  210772 kB
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

The growth will stop once wqueue for the leaking bus is full (~480 MB).

BEWARE: don't hit Ctrl-C to stop gdb, or else the system will panic.
Instead, use the following command: kill -CONT 1
Then use "quit" at the gdb prompt.

Comment 10 Renaud Métrich 2020-01-24 07:47:58 UTC
Comparing the RHEL8 and RHEL7 code, I was wondering why I couldn't reproduce.
It appears that the following commit must be backported to RHEL7:

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
commit 5ae37ad833583e6c1c7765767b7f8360afca3b07
Author: Lennart Poettering <lennart>
Date:   Fri Dec 15 22:24:16 2017 +0100

    sd-bus: when attached to an sd-event loop, disconnect on processing errors
    
    If we can't process the bus for some reason we shouldn't just disable
    the event source, but log something and give up on the connection. Hence
    do that, and disconnect.
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

In a nutshell, upon receiving -ETIMEDOUT, no special handling should be done in bus_process_internal() but in io_callback() instead.

Comment 19 Lukáš Nykrýn 2020-03-26 09:23:13 UTC
fix merged to github master branch -> https://github.com/systemd-rhel/rhel-7/pull/71

Comment 32 errata-xmlrpc 2020-09-29 20:32:23 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Low: systemd security and bug fix update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:4007