[SRU] multipath + libvirtd eats away more memory over time

[Alvin]

libvirtd fills the memory, until the libvirtd process gets killed. This happens over a long time.
- This server (info by ubuntu-bug) has 4GB of memory and an uptime of 27 days. Some KVM machines have been active during that period. The last 4 days before the crash, no virtual machine was running on the server, but libvirtd slowly filled memory.
- Another server has 32 GB of memory and active virtual machines. It took a few weeks more until memory was completely filled.

Steps to reproduce:
- Start libvirtd
- Wait a long time

ProblemType: Bug
Architecture: amd64
Date: Wed Apr 28 08:43:52 2010
DistroRelease: Ubuntu 9.10
Package: libvirt-bin 0.7.0-1ubuntu13.1
ProcEnviron:
 LANG=C
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.31-20.58-server
SourcePackage: libvirt
Uname: Linux 2.6.31-20-server x86_64

======
SRU:
 * IMPACT: If affected, libvirtd will eventually leak all memory, and OOM the system.
 * ADDRESSED: Applied patch solves two memory leaks by freeing memory on function exit conditions.
 * PATCH: As attached from Nigel Jones below. He has also submitted this upstream as well.
 * TEST CASE: In some cases, you can reproduce this issue by running "top -p $(pidof libvirtd)" in one window, watching RES memory usage increase, while running "while true; do sudo multipath -F; sudo multipath -v4; done" in another window. Due to a race condition (see Bug: #585027), this will sometimes not reproduce the issue by itself. In these cases, you can "simulate" the race condition by "sudo dmsetup remove <string>", and then running the commands above.
 * REGRESSION POTENTIAL: Patch is pretty simple, clean. Regression potential should be minimal.
======

[Alvin (alvind)]

Attaching dmesg for more information

[Thierry Carrez (ttx)]

We fixed a few leaks recently in Lucid, any chance you could check if that's fixed there ?

[Dustin Kirkland  (kirkland)]

And there are a number of other leaks fixed in the upstream version
Jamie and I tried to get working for Lucid.

We might have to consider a memory-leak cherry pick series...

[Alvin (alvind)]

ok, I'll test this the easy (and slow) way.
I have set up two servers with Lucid and libvirt and will leave them running a few days. They have nothing to do and no virtual machines are running on them. A cronjob is set up to output the memory usage every hour.
Next monday, I'll be in the office and see if there's any change in memory usage.

[Serge van Ginderachter (svg)]

I upgraded my laptop earlier this week, some days before the final Lucid release. libvirt-bin is installed though I don't actively use it (only accasionaly for testing purposes, but atm no vm's are installed), though libvirt has been installed for a long time earlier. Problem only now arises after this upgrade to Lucid and after i left it runnig for longer than around 8 hours.

Yesterday I booted my laptop in the morning and left it running all night. This morning I came to my desk and found my laptop unresponsive, having to wait a huge time beofre being able to unlock my screen and seeing what was happening. I'm attaching the screenshot I took from top, evidence of what I think is a huge memory leak.

[Alvin (alvind)]

Well, it's confirmed on 2 servers.
Since thursday while doing nothing:
- server1: 260MB went to 345MB
- server2: 745MB went to 830MB

[Nick Outin (outin)]

I've got something similar happening on Lucid. I rebooted a new server last night, and this morning libvirtd is using about 5GB of memory, without any virtual machines running. Looking at my munin graphs, this appears to have been happening on both of my new servers for the past few days, with the most extreme case of libvirtd using all 48GB of memory over the course of two days.

Setting the libvirtd log level to 2 displays a lot of:

23:07:15.340: info : udevGetDeviceProperty:111 : udev reports device 'sdc' does not have property 'DRIVER'
23:07:15.343: info : udevGetDeviceProperty:111 : udev reports device 'sdb' does not have property 'DRIVER'

Sometimes these appear multiple times a second, other times they only appear every 20 seconds. Both devices (sdb and sdc) are being used by multipath, and are mapped to /dev/mapper/mpath0, but I'm not sure why libvirtd cares about them. Nothing else is showing up in the logs, and loglevel 3 displays nothing.

The setup is two Dell R710 servers accessing a shared Dell MD3000 SAS array. OS is 10.04 AMD64 server, with all patches applied as of the morning of May 6th.

- uname -a: Linux ares 2.6.32-22-server #33-Ubuntu SMP Wed Apr 28 14:34:48 UTC 2010 x86_64 GNU/Linux
- libvirt-bin 0.7.5-5ubuntu27

[Nick Outin (outin)]

I spent some more time on this, and it appears my leak is related to multipath. Shutting down multipath (multipath -F; service multipath-tools stop) stops the leak. Alvin also appears to have multipath running, it's listed in the dmesg he uploaded.

The udev messages I'm seeing in the libvirtd log are mirrored when running "udevadm monitor". I found that removing "|change" from the ACTION line in /lib/udev/rules.d/95-multipath.rules appears to fix the leak, or at least slows it down considerably. I ran my two servers overnight, and this morning libvirtd on the changed server is using 53MB of RES memory as reported by top, and the unchanged server is using 2.5GB. Both had similar workloads.

Here's the exact line:

/lib/udev/rules.d/95-multipath.rules
from:
ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v0 /dev/%k"
to:
ACTION=="add", SUBSYSTEM=="block", RUN+="/sbin/multipath -v0 /dev/%k"

I found it was added in debian bug #489850, and it looks harmless enough to change, at least in my instance.

Also, an overnight run with multipath turned off resulted in only 5MB of RES memory usage by libvirtd.

[Dustin Kirkland  (kirkland)]

Hi Nick,

Thanks for the analysis. As I don't have
/lib/udev/rules.d/95-multipath.rules on my system, can you tell me the
output of:

dpkg -S /lib/udev/rules.d/95-multipath.rules

If this is the root of the issue, we should link this bug against that package.

[Nick Outin (outin)]

Hi Dustin,

Here's what I get:

$ dpkg -S /lib/udev/rules.d/95-multipath.rules
multipath-tools: /lib/udev/rules.d/95-multipath.rules

[Dustin Kirkland  (kirkland)]

I've updated the title and marked the bug against the multipath-tools package as well.

I'm a little skeptical about that though... The multipath-tools package has only had two minor changes since 10 Mar 2009. Unless something new in libvirt is only now exposing this issue...

[Nigel Jones (dev-nigelj)]

I've done a bit of an experiment and this is what I've found:

Running valgrind on libvirtd -v ($ sudo valgrind -v --leak-check=full --show-reachable=yes /usr/sbin/libvirtd -v) produced the output in lp571093-libvirt-val-run1

A quick summary:

==15520== 78,696 (18,048 direct, 60,648 indirect) bytes in 376 blocks are definitely lost in loss record 324 of 325
==15520== at 0x4C267CC: calloc (vg_replace_malloc.c:467)
==15520== by 0x42CFAD: virAlloc (memory.c:100)
==15520== by 0x47C96D: udevAddOneDevice (node_device_udev.c:1209)
==15520== by 0x47D166: udevDeviceMonitorStartup (node_device_udev.c:1265)
==15520== by 0x54BD1BF: virStateInitialize (in /usr/lib/libvirt.so.0.7.5)
==15520== by 0x41A64B: main (libvirtd.c:3153)
==15520==
==15520== 204,320 (22,736 direct, 181,584 indirect) bytes in 98 blocks are definitely lost in loss record 325 of 325
==15520== at 0x4C267CC: calloc (vg_replace_malloc.c:467)
==15520== by 0x50508CB: udev_device_new (libudev-device.c:240)
==15520== by 0x505285C: udev_monitor_receive_device (libudev-monitor.c:589)
==15520== by 0x47D367: udevEventHandleCallback (node_device_udev.c:1356)
==15520== by 0x414AF8: virEventRunOnce (event.c:478)
==15520== by 0x4166D8: qemudOneLoop (libvirtd.c:2169)
==15520== by 0x4169B2: qemudRunLoop (libvirtd.c:2278)
==15520== by 0x70669C9: start_thread (pthread_create.c:300)
==15520== by 0x736369C: clone (clone.S:112)

==15520== LEAK SUMMARY:
==15520== definitely lost: 46,856 bytes in 628 blocks
==15520== indirectly lost: 282,769 bytes in 8,181 blocks
==15520== possibly lost: 0 bytes in 0 blocks
==15520== still reachable: 109,152 bytes in 1,303 blocks
==15520== suppressed: 0 bytes in 0 blocks
==15520==

I triggered the issue by running:
$ sudo multipath -F
$ sudo multipath -v4
multiple times to replicate the issue.

I'd say that this is definitely a libvirt/udev bug based on the behaviour. I believe that while Nick's suggestion in Comment #9 may avoid the problem it looks like it's really a bandaid and it's possible that other applications will trigger this issue via udev.

[ariel (garcia)]

Same memory leak here, running kvm+libvirtd+multipath-tools on nodes with SAN access over QLogic cards
However i noticed something which i guess is highly related:

udev is constantly "discovering" the 4 multipath devices (sdb/sdc/sdd/sde) and causing a high CPU load of around 3 (8 CPU system). "ps" shows a process tree like this again and again

  393 ? S<s 22:09 udevd --daemon
20696 ? S< 0:12 \_ udevd --daemon
 7171 ? S< 0:00 | \_ /sbin/multipath -v0 /dev/sdb
 7190 ? R< 0:00 | \_ /sbin/mpath_prio_emc /dev/sdd
20702 ? S< 0:10 \_ udevd --daemon
 7177 ? S< 0:00 | \_ /sbin/multipath -v0 /dev/sdc
 7189 ? R< 0:00 | \_ /lib/udev/scsi_id -g -u -d /dev/sdb
31869 ? S< 0:01 \_ udevd --daemon
 7179 ? S< 0:00 | \_ /sbin/multipath -v0 /dev/sdd
 7191 ? R< 0:00 | \_ /sbin/mpath_prio_emc /dev/sdb
31875 ? S< 0:01 \_ udevd --daemon

(PIDs change all the time, they are really being called anew).
Uploading the output of 2-3 seconds of "udevadm monitor -e"

[ariel (garcia)]

I performed some additional observations, I agree Nigel's statements in #13:

disabling the "change" ACTION in /lib/udev/rules.d/95-multipath.rules is just a bandaid, the memory leak is there anyways, just that it takes waaaaaaaay longer to fill in the memory.

The problem "solved" by disabling the "change" ACTION in /lib/udev/rules.d/95-multipath.rules seems to be a real bug somewhere in udev or multipath: monitoring with udevadm the number of events gets reduced from "tons per second" to one every 30 seconds in my hardware, which shows all the other events were spurious events generated by a udev/multipath feedback loop...

That issue is being tracked in
https://bugs.launchpad.net/ubuntu/+source/udev/+bug/578180
and also Debian bug
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=581791

[Niall O'Reilly (niall-oreilly+launchpad)]

At least part of this problem seems to be independent of multipath.
I'm seeing libvirtd steadily eating more memory even though I have
currently no virtual machines even defined, much less active, and
have not had occasion to install multipath.

[Nigel Jones (dev-nigelj)]

Some more investigation:

--technical bits-- (non tech lower down)

libvirtd debug logging (attached) shows running multipath -F/multipath -v4 does the following:

14:02:28.570: debug : udevEventHandleCallback:1363 : udev action: 'add'
14:02:28.570: info : udevGetDeviceProperty:111 : udev reports device '252:0' does not have property 'DRIVER'
14:02:28.570: info : udevGetDeviceProperty:111 : udev reports device '252:0' does not have property 'PCI_CLASS'
14:02:28.570: info : udevGetDeviceProperty:111 : udev reports device '252:0' does not have property 'INTERFACE'
14:02:28.570: info : udevGetDeviceType:1082 : Could not determine device type for device with sysfs path '252:0'

[snip]
14:02:28.592: debug : udevEventHandleCallback:1363 : udev action: 'add'
14:02:28.592: info : udevGetDeviceProperty:111 : udev reports device 'dm-0' does not have property 'DRIVER'
14:02:28.592: debug : udevGetDeviceProperty:131 : Found property key 'DEVNAME' value '/dev/dm-0' for device with sysname 'dm-0'
14:02:28.592: info : udevGetDeviceProperty:111 : udev reports device 'dm-0' does not have property 'ID_BUS'
14:02:28.592: info : udevGetDeviceProperty:111 : udev reports device 'dm-0' does not have property 'ID_SERIAL'
14:02:28.592: info : udevGetDeviceSysfsAttr:200 : udev reports device 'dm-0' does not have sysfs attr 'device/vendor'
14:02:28.592: info : udevGetDeviceSysfsAttr:200 : udev reports device 'dm-0' does not have sysfs attr 'device/model'
14:02:28.592: info : udevGetDeviceProperty:111 : udev reports device 'dm-0' does not have property 'ID_TYPE'
14:02:28.592: info : udevKludgeStorageType:912 : Could not find definitive storage type for device with sysfs path '/sys/devices/virtual/block/dm-0', trying to guess it
14:02:28.592: info : udevKludgeStorageType:924 : Could not determine storage type for device with sysfs path '/sys/devices/virtual/block/dm-0'
[snip]
14:02:28.594: debug : udevEventHandleCallback:1363 : udev action: 'remove'
14:02:28.594: info : udevRemoveOneDevice:1147 : Failed to find device to remove that has udev name '/sys/devices/virtual/bdi/252:0'
14:02:28.598: debug : udevEventHandleCallback:1363 : udev action: 'remove'
14:02:28.598: info : udevRemoveOneDevice:1147 : Failed to find device to remove that has udev name '/sys/devices/virtual/block/dm-0'

udevEventHandleCallback(...) will call udevAddOneDevice(device) in turn runs udevGetDeviceProperty(...) indirectly.

Assuming (and I'd need to check this) that udevGetDeviceProperty() returns PROPERTY_ERROR then I have a feeling we have found the problem as it does not look to have free'd the memory in the exit path - would have to check, especially if udevRemoveOneDevice also fails.

-- non technical bits --

It would be interesting to see if other peoples debug output from libvirt mimics my data. Instructions can be found at http://honk.sigxcpu.org/con/Debugging_libvirt.html

In particular instead of libvirtd -d, try:

LIBVIRT_DEBUG=1 libvirtd -v

I'm going to have a bit more of a play around soon to see if I can work this out a bit more.

[Nigel Jones (dev-nigelj)]

I've had another look at this bug, reproducing etc, this time through GDB, with the output from valgrind & the debug output in my last two posts, here is what I believe is happening:

1. multipath -v4 gets called (or other appropriate trigger)
 - multipath detects a device that it believes is new, which triggers a udev add/change event
2. libvirt picks up on the events and runs the code within udevAddOneDevice(device)
3. While running around it seems that one of the if functions around node_device_udev.c:1230 returns non zero and hits the 'goto out' call.
4. As a result virNodeDeviceDefFree(def); does not get called and libvirt still thinks that the device exists.
5. When multipath realizes itself that the device isn't worth anything it triggers a udev remove call.
6. libvirt tries to remove the device but fails early on because it doesn't know what udev is talking about, and again doesn't free memory.

For what it's worth, just before the goto out call was made gdb was about to tell me the following:
(gdb) p def
$4 = (virNodeDeviceDefPtr) 0x1cabd70
(gdb) x/t def
0x1cabd70: 00000000000000000000000000000000
(gdb) x/3x def
0x1cabd70: 0x00000000 0x00000000 0x00000000
(gdb) x/s def
0x1cabd70: ""

I've got a distinct feeling that if virNodeDeviceDefFree(def) was called before the function returned, this memory leak wouldn't have happened.

I'm going to give it a test and see what happens.

[Nigel Jones (dev-nigelj)]

Okay, I've created a patch that should fix the issue in two ways, first as observed in my previous comment I suspected that adding a virNodeDeviceDefFree(def) to udevAddOneDevice() would solve the issue, it for the most part did but still left approximately an 8k RES memory leak.

Looking at the valgrind data that I had managed to generate (Comment #13) I suspected a second leak and noticed that udevProcessDeviceListEntry() after running udevAddOneDevice() ran udev_device_unref(device); which according to the udev code does:

 * Drop a reference of a udev device. If the refcount reaches zero,
 * the resources of the device will be released.

Based on the fact that the reference is wiped at the end of udevProcessDeviceListEntry() I have added it to udevEventHandleCallback() which is the other main location of udevAddOneDevice() getting called.

This is now resulting in no increase in RES memory (except for natural increases).

Patch is attached.

[Launchpad Janitor (janitor)]

This bug was fixed in the package libvirt - 0.7.5-5ubuntu27.1

---------------
libvirt (0.7.5-5ubuntu27.1) maverick; urgency=low

  [ Nigel Jones ]
  * debian/patches/9024-free-memory-for-invalid-devices.patch: clean
    up a memory leak affecting multipath+libvirt, LP: #571093
 -- Dustin Kirkland <email address hidden> Mon, 24 May 2010 10:00:07 -0500

[Nigel Jones (dev-nigelj)]

I have forwarded the bug/patch to Debian BTS as http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=582965 so they can incorporate the fix there.

[ariel (garcia)]

Hi Nigel, Dustin,

great, thanks!! i installed the two libvirt{0,-bin} packages from Maverick and testing right now.

Sadly the memory leak is still there for me... If i leave the unmodified
      /lib/udev/rules.d/95-multipath.rules
in operation the memory usage of libvirtd grows around 15M in 1 minute!!
Removing the 'change' action in 95-multipath.rules of course helps a lot to reduce the leak (in that case kernel/udev trigger "only" two events every 15 seconds with our hardware...).

# dpkg -l | grep libvirt
ii libvirt-bin 0.7.5-5ubuntu27.1 the programs
ii libvirt0 0.7.5-5ubuntu27.1 library for inte

# ps axf -eo pid,%mem,rsz,vsz,sz,state,stime,command | grep libvirtd | grep -v grep; \
sleep 60 ; \
ps axf -eo pid,%mem,rsz,vsz,sz,state,stime,command | grep libvirtd | grep -v grep

25520 0.5 90668 302488 75622 S 14:56 /usr/sbin/libvirtd -d
25520 0.6 106788 303920 75980 S 14:56 /usr/sbin/libvirtd -d
#
# cd /lib/udev/rules.d
# cat 95-multipath.rules | grep -v ^#
RUN+="socket:/org/kernel/dm/multipath_event"
ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v0 /dev/%k"

[Nigel Jones (dev-nigelj)]

Ariel,

What was the previous rate of increase?

I don't personally have the hardware to reproduce the issue (looks like ocfs2 + EMC SAN based on your udev output), so could you maybe provide the following:

 * valgrind -v --leak-check=full --show-reachable=yes /usr/sbin/libvirtd -v
  (Once it's settled and you've observed that the RES memory has increased Ctrl+C valgrind and attach the output)
 * LIBVIRT_DEBUG=1 libvirtd -v
  (Again, try to collect the debug messages while the change events are occurring)

I'll see if I can work it out more with that info.

[Martin Pitt (pitti)]

Accepted libvirt into lucid-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

[Martin Pitt (pitti)]

FAILED: libvirt (The source libvirt - 0.7.5-5ubuntu27.1 is already accepted in ubuntu/maverick and you cannot upload the same version within the same distribution. You have to modify the source version and re-upload.)

Sorry, you have to re-do the upload. It seems that the -27.1 upload should have never be targetted at maverick in the first place? Use -27.0.1 then?

[.:. brainsik (brainsik)]

What's the status of this getting into lucid-updates?

[Martin Pitt (pitti)]

Accepted libvirt into lucid-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

[Chuck Short (zulcss)]

@brainsik: can you enable lucid-propsed and please test?

thanks
chuck

[Steve Langasek (vorlon)]

This package is present on the ubuntu-server CDs, so we need to get the SRU verified /immediately/ in order to not hold up the 10.04.1 point release. Can someone please test this package today and verify that the fix is correct?

[Nigel Jones (dev-nigelj)]

Steve,

Looks like the latest version of the patch was not applied (libvirt maintainers applied a modified patch to upstream that fixed a couple more memory leaks.

This version does work, but I know others still had some lingering problems that I couldn't reproduce.

The patch they are now using is: http://libvirt.org/git/?p=libvirt.git;a=commit;h=e7f3bad46edf352abd9f700af9ec59882762c4ca

But it does currently WFM.

[Steve Langasek (vorlon)]

Discussed further with Nigel on IRC; he confirmed that this appears to be a partial fix which is regression-free. So we can promote this to lucid-updates for 10.04.1, then reopen this for tracking the remaining memory leaks.

[Launchpad Janitor (janitor)]

This bug was fixed in the package libvirt - 0.7.5-5ubuntu27.2

---------------
libvirt (0.7.5-5ubuntu27.2) lucid-proposed; urgency=low

  [ Nigel Jones ]
  * debian/patches/9024-free-memory-for-invalid-devices.patch: clean
    up a memory leak affecting multipath+libvirt, LP: #571093
 -- Dustin Kirkland <email address hidden> Wed, 07 Jul 2010 10:18:48 -0400

[Thierry Carrez (ttx)]

@Dustin: What's the status on that one ? Feel free to reassign to Serge if you can't work on it.

[Nigel Jones (dev-nigelj)]

I've included the attached patch in an SRU candidate for Bug #455832, you can view the proposed debdiff there.

[Dustin Kirkland  (kirkland)]

Nigel, hmm, I'm confused. The patch you just attached is completely different from the patch of the same name in libvirt-0.7.5/debian/patches/9024-free-memory-for-invalid-devices.patch, which is lucid-proposed now.

Can you please clarify? What exactly is still required to close this bug?

[Dustin Kirkland  (kirkland)]

Ah, I see.

Okay, uploading a package to lucid-proposed fixing this, and Bug #455832.

[Martin Pitt (pitti)]

Accepted libvirt into lucid-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

[Nigel Jones (dev-nigelj)]

I've tested this bug again w/ the new patch, it is working fine as expected for me, w/ no increase of RES memory while running the multipath commands to add/remove devices in udev.

Looks ready to me (and w/ my testing of bug #455832), it should be ready for pushing.

[Launchpad Janitor (janitor)]

This bug was fixed in the package libvirt - 0.7.5-5ubuntu27.3

---------------
libvirt (0.7.5-5ubuntu27.3) lucid-proposed; urgency=low

  * debian/patches/9024-free-memory-for-invalid-devices.patch: updated
    to match upstream patch which includes a fix for an entry path
    not found originally, LP: #571093
  * debian/patches/9025-avoid-NULL-dereference-upon-disk-op-fail.patch:
    backport upstream patch to avoid failures when attempting to attach
    a disk or image twice. LP: #455832
 -- Nigel Jones <email address hidden> Fri, 27 Aug 2010 02:40:34 +1200

[Peter Petrakis (peter-petrakis)]

@All,

The stream of udev change events you've observed has been fixed in multipath
itself by this update.

https://launchpad.net/~peter-petrakis/+archive/storage

It's been proposed for SRU on behalf of (LP: #644489)

Please test and verify that the change events cease. So we can
reconcile the multipath-tools status of this bug, Thanks!

[Rolf Leggewie (r0lf)]

lucid has seen the end of its life and is no longer receiving any updates. Marking the lucid task for this ticket as "Won't Fix".

[Rafael David Tinoco (rafaeldtinoco)]

In an effort to keep an up-to-date and valid list of bugs to work on, I have reviewed this report to verify it still requires effort and occurs on an Ubuntu release in standard support, and it does not.

comment #19 seems to summarize the case and there is no further action to be taken on multipath-tools, specially -devel version.

There appears to be no further action possible at this time. I am therefore moving the bug to 'Won't fix'. If you disagree or have new information, we would be grateful if you could please add a comment stating why and then change the status of the bug to 'New'.