Bug 552932 - pulseaudio memory leak when starting gnome
Summary: pulseaudio memory leak when starting gnome
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: pulseaudio
Version: 12
Hardware: x86_64
OS: Linux
low
medium
Target Milestone: ---
Assignee: Lennart Poettering
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 556994 (view as bug list)
Depends On:
Blocks: 555125
TreeView+ depends on / blocked
 
Reported: 2010-01-06 15:25 UTC by sebtemp1
Modified: 2010-01-26 01:05 UTC (History)
5 users (show)

Fixed In Version: 0.9.21-4.fc12
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 555125 (view as bug list)
Environment:
Last Closed: 2010-01-13 18:20:07 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
log files (40.07 KB, application/x-compressed-tar)
2010-01-06 15:29 UTC, sebtemp1
no flags Details
Screenshots of the problem (456.75 KB, application/x-compressed-tar)
2010-01-10 10:22 UTC, sebtemp1
no flags Details
Valgrind massif result (505.02 KB, text/plain)
2010-01-11 23:50 UTC, sebtemp1
no flags Details
ms_print output with pulseaudio debuginfo symbols (366.71 KB, text/plain)
2010-01-12 23:26 UTC, sebtemp1
no flags Details
Result of udevadm monitor --property (52.88 KB, text/plain)
2010-01-13 17:55 UTC, sebtemp1
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Launchpad 424655 0 None None None Never

Description sebtemp1 2010-01-06 15:25:37 UTC
User-Agent:       Mozilla/5.0 (X11; U; Linux x86_64; fr; rv:1.9.1.6) Gecko/20091216 Fedora/3.5.6-1.fc12 Firefox/3.5.6

Pulseaudio memory leak after gnome start, leading to complete RAM saturation, swap and so on in a few hours.
This is independant of audio softwares running at the same time.


Reproducible: Always

Steps to Reproduce:
Just start gnome usually.
Actual Results:  
After a few hours, 2 Gb RAM consumed, checked with gnome-system-monitor.

Expected Results:  
pulseaudio staying < 10Mo occupation in RAM space.

List of files given in the archive :
uname : result of uname -a
alsa_info : result of alsa-info.sh --no-upload
lsmod.txt : result of lsmod
lspci.txt : result of lspci
rpm.txt : result of rpm -qa
pulse_log_console.txt : result of pulse -vvvvv after having deactivated pulse auto-restart
gnome_boot.txt : list of the services concerning pulseaudio started at gnome start.
valgrind_pulse.txt : result of G_SLICE=always-malloc G_DEBUG=gc-friendly valgrind -v --tool=memcheck --leak-check=full --num-callers=40 --log-file=valgrind.log pulseaudio -vvvv
valgrind_pulse_error.txt contains the output in the console of the previous command : pulseaudio failed to start so this isn't a good demonstration of the problem ... When starting pulseaudio without valgrind, I don't have this problem.

Check ubuntu forums : seems to be the same problem because of udev and pulseaudio incompatibility (maybe a file descriptor not closed if I remember correctly).

Comment 1 sebtemp1 2010-01-06 15:29:07 UTC
Created attachment 382010 [details]
log files

Comment 2 Lennart Poettering 2010-01-06 15:54:03 UTC
Uh, measuring actual memory consumption is not as simple as you might think:

http://pulseaudio.org/wiki/MemoryConsumption

And that ubuntu bug appears to be about an fd leak, not a memory leak, so I don't think that is related here.

Comment 3 sebtemp1 2010-01-07 10:33:33 UTC
Hello,

Thanks for your time, but actually I know the limitation of checking the memory like I did.
I'm not speaking of a 64Mb pb here, I'm speaking of 3Go Ram memory consumption in approximately 10 hours, LEADING TO SWAP on hard drive, even without using any audio software. I don't care about top not being accurate, if there is 3 Go taken and swap, there is a problem, this is not something that could happen just because of preallocation mechanism. This is why I put this bug as urgent : this is not just a crash impacting only pulseaudio, after one day I have to reboot because my laptop is useless.
I already used pulseaudio before, and this is not the correct behavior : normally the memory print is nearly constant over time, even while using audio, < 10Mo according to gnome-system-monitor.

You can take a look at ubuntu bug 424655 :
https://bugs.launchpad.net/ubuntu/+source/pulseaudio/+bug/424655

This is EXACTLY the same behavior.
I was speaking of fd leak because of this (seen in ubuntu 424655) :

One potential explanation: the fd leak made udev completely stop recognizing new hardware on a lot of systems (which was fixed in -6.1). So the fix might uncover another leak by adding/probing sound hw which previously didn't appear in udev (since it simply stopped working because of exceeding the 1024 fd limit)

For those of you who can reproduce this pulseaudio memleak (I can't), it would be interesting to compare an udev dump with both versions. Please install 147~6, do udevadm info --export-db > /tmp/udev.log
attach /tmp/udev.log here. Then upgrade to 147~-6.1, reboot, do the command again, and attach /tmp/udev.log again.

You can have a look at https://bugzilla.redhat.com/show_bug.cgi?id=552932 for nearly the same pb, too.

Sébastien

Comment 4 Lennart Poettering 2010-01-07 18:12:27 UTC
Those valgrind runs show that PA is leaking exactly no memory.

So, valgrind shows no leak, and top/ps are useful for identifying leaks, so why do you cleam that PA is doing anything it shouldnt do?

What does "pacmd stat" say? It should tell you how much memory PA itself actually thinks it uses.

Comment 5 Lennart Poettering 2010-01-07 18:21:20 UTC
Apparently, gnome-system-monitor's "Memory" column reflects the number of resident pages in memory. That is mostly just a hint how a process is treated by the swapper. And not surprisingly PA is treated nicely, since it has a negative nice level...

Comment 6 Lennart Poettering 2010-01-07 20:00:22 UTC
In g-s-m you can activate a "Writable Memory" column. That's way more interesting than "Memory". What does it say for you for PA when you think pa is bahaving badly?

Comment 7 sebtemp1 2010-01-08 12:21:28 UTC
I cleam there is a problem mostly because of hard drive swap (swap memory visible vith g-s-m too, always 0, begining to fill after 15 hours because no more RAM, everything getting slow).

pacmd stat shows no problem it seems : 

Welcome to PulseAudio! Use "help" for usage information.
>>> Memory blocks currently allocated: 1, size: 63,9 Kio.
Memory blocks allocated during the whole lifetime: 42, size: 2,1 Mio.
Memory blocks imported from other processes: 0, size: 0 B.
Memory blocks exported to other processes: 0, size: 0 B.
Total sample cache size: 0 B.
Default sample spec: s16le 2ch 44100Hz
Default channel map: front-left,front-right
Default sink name: alsa_output.pci-0000_00_1b.0.analog-stereo
Default source name: alsa_input.pci-0000_00_1b.0.analog-stereo
Memory blocks of type POOL: 1 allocated/1 accumulated.
Memory blocks of type POOL_EXTERNAL: 0 allocated/0 accumulated.
Memory blocks of type APPENDED: 0 allocated/0 accumulated.
Memory blocks of type USER: 0 allocated/0 accumulated.
Memory blocks of type FIXED: 0 allocated/41 accumulated.
Memory blocks of type IMPORTED: 0 allocated/0 accumulated.

The Writable memory column is exactly equal to the Memory column, always increasing slowly, approximately 0.2Mo/second.

As indicated, the test with valgrind may not be representative of the problem, because pulseaudio is immediatly shutting down with valgrind. I joined the log of the problem in the archive.

Comment 8 Lennart Poettering 2010-01-08 13:59:48 UTC
so neither valgrind nor pa itself seem to think there was a memory leak...

Could you please show a screenshot or so how this looks like after a while?

Comment 9 Lennart Poettering 2010-01-08 14:00:11 UTC
(In reply to comment #8)
> Could you please show a screenshot or so how this looks like after a while?  

a screenshot of g-s-m that is

Comment 10 sebtemp1 2010-01-10 10:22:39 UTC
Created attachment 382775 [details]
Screenshots of the problem

Here you are.
I let it run during the night, the screenshots show the state in the morning. There was already swap, so this is a good example : took 10 seconds to open firefox ...

For your previous answer, I don't think you can conclude that valgrind didn't show there was a memory leak. As I said, pulseaudio was running for 1 or 2 seconds under valgrind and failed. I don't know why. I thought first this was because of SELinux context (not the same entry point because this is launched by valgrind) but I don't have any alert, even while deactivating silent denials.

I joined the error in valgrind_pulse_error.txt in my first post, the main thing is :
E: module-console-kit.c: GetSessionsForUnixUser() call failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
E: module.c: Failed to load  module "module-console-kit" (argument: ""): initialization failed.
E: main.c: Module load failed.
E: main.c: Échec lors de l'initialisation du démon

Comment 11 Lennart Poettering 2010-01-11 17:07:47 UTC
Hmm, interesting. This indeed doesn't look right.

Do you think you would be able to run PA through valgrind's massif tool? This should give us a hint what leaks the memory here.

Comment 12 sebtemp1 2010-01-11 19:13:43 UTC
I wouuld like to do it, but currently I'm stuck with this dbus problem.
I don't see the reason why pulseaudio is able to contact ConsoleKit via Dbus when launched from a terminal and not when launched by valgrind.

Comment 13 Lennart Poettering 2010-01-11 22:30:50 UTC
(please do not attach compresses logs, makes it hard to read)

Looks like a CK incompat with valgrind. No clue. I'd probably just suggest commenting the loading of that module in /etc/pulse/default.pa while debugging this. It should strictly be necessary as long as you don't switch sessions too often ;-)

Comment 14 sebtemp1 2010-01-11 23:50:41 UTC
Created attachment 383124 [details]
Valgrind massif result

This is the result of :
valgrind --trace-children=yes --tool=massif --alloc-fn=g_malloc --alloc-fn=g_realloc --alloc-fn=g_try_malloc --alloc-fn=g_malloc0 --alloc-fn=g_mem_chunk_alloc pulseaudio

It ran around 10 minutes.

Comment 15 sebtemp1 2010-01-11 23:53:03 UTC
Ok, I hope the previous attachment is good : I'm not an expert in valgrind options !
Anyway, indeed no more errors after commenting the module, and I didn't compress the log this time ;)

Comment 16 Lennart Poettering 2010-01-12 15:59:30 UTC
Hmm, this run seems to lack debug symbols. Could you install those?

Hmm, could you also run "ms_print" on the output this generates? I am already on F13 and lack the right setup to run that the same way on F12.

Comment 17 Lennart Poettering 2010-01-12 22:11:25 UTC
This could be your fix:

http://git.0pointer.de/?p=pulseaudio.git;a=patch;h=15a3018bda8ee92393671ceaf272be418e95a81f

Fixes a memleak when devices we are not interested in come and go. Normally those events should be suppressed by udev anyway and even if they are not this should happen very seldomly, since most folks dont keep unplugging/replugging their mice all the time. ;-)

So, if this really your fix this would suggest that for some reason (virtual?) devices come and go all the time on your machine. Could you check that by running "udevadm monitor" for a while? Is there a lot going on?

Comment 18 sebtemp1 2010-01-12 23:26:24 UTC
Created attachment 383373 [details]
ms_print output with pulseaudio debuginfo symbols

Here you are ;)
I installed the symbols only for pulseaudio rpm, not the other packages for the moment.

You seem to be right for the other test : udevadm returns the following lines :

UDEV  [1263251760.702821] change   /devices/pci0000:00/0000:00:1f.2/host5/target5:0:0/5:0:0:0/block/sr0 (block)
KERNEL[1263251760.707446] change   /devices/pci0000:00/0000:00:1f.2/host5/target5:0:0/5:0:0:0 (scsi)
UDEV  [1263251760.707464] change   /devices/pci0000:00/0000:00:1f.2/host5/target5:0:0/5:0:0:0 (scsi)
KERNEL[1263251760.707481] change   /devices/pci0000:00/0000:00:1f.2/host5/target5:0:0/5:0:0:0/block/sr0 (block)
UDEV  [1263251760.777527] change   /devices/pci0000:00/0000:00:1f.2/host5/target5:0:0/5:0:0:0/block/sr0 (block)
...

I did a capture of the output of udevadm during 1 minute, and I have 3216 lines like these in the file. And i did not deco/reco my mice 3216 times in 1 minute for sure ;)

Comment 19 Lennart Poettering 2010-01-12 23:39:07 UTC
Ah, nice. There's probably something wrong with your CD drive. Could you redo the udev monitor call and add a "--property"? That should tell us what exactly changed on those devices when those "change" events are triggered.

Given that indeed there is quite some udev traffic going on I am quite sure that the aforementioned patch fixes that issue.

Now, as mentioned there is definitely a bug somewhere else, since that udev traffic should definitely *not* happen.

Comment 20 sebtemp1 2010-01-13 17:55:06 UTC
Created attachment 383529 [details]
Result of udevadm monitor --property

Ok, seems to be CD drive as you said !
But I'm not sure of what happens in there ...

For pulseaudio, I'll try to find an SRPM and recompile it with the modif.

Comment 21 Lennart Poettering 2010-01-13 18:20:07 UTC
OK, talked to Kay Sievers now. This seems to be a firmware problem in the drive. The drive sends out media changed events all the time. And it should not. There probably needs to be added some framework in the kernel that hose events can be suppressed.

I will now close this bug, since the memleak in PA is actually fixed. I'll then duplicate the bug and assign to the kernel, since there really needs to be done something about the firmware/kernel bug that triggered this memleak issue in PA.

Comment 22 Lennart Poettering 2010-01-13 18:29:37 UTC
The duplicated kernel bug is https://bugzilla.redhat.com/show_bug.cgi?id=555125

Comment 23 sebtemp1 2010-01-13 19:20:42 UTC
Ok, thanks a lot for your help !

The correction for this bug in PA will be included in the next release of PA ?

Comment 24 Lennart Poettering 2010-01-14 15:35:05 UTC
Yes, of course.

Comment 25 Fedora Update System 2010-01-15 01:46:52 UTC
pulseaudio-0.9.21-3.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/pulseaudio-0.9.21-3.fc12

Comment 26 Fedora Update System 2010-01-18 01:24:26 UTC
pulseaudio-0.9.21-4.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/pulseaudio-0.9.21-4.fc12

Comment 27 Lennart Poettering 2010-01-20 16:59:26 UTC
*** Bug 556994 has been marked as a duplicate of this bug. ***

Comment 28 Fedora Update System 2010-01-26 01:04:27 UTC
pulseaudio-0.9.21-4.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.