xfce4-volumed takes 100% cpu when system is idle for some time

This looks like a problem in GStreamer to me. Could you please get the bzr trunk (lp:xfce4-volumed), build it with debug support (./configure --with-debug) and then run it in gdb (gdb ./src/xfce4-volumed) ? Then, just interrupt it (Ctrl+C in gdb) when it is using 100% CPU, and type 'bt' in gdb, and give me the backtrace, so we can see which gstreamer function causes problems, exactly. Thanks in advance.

Hello Steve,

sorry for my terribly late reply. I never had the time to debug this. I'm also not sure if debugging it this way would have helped at all. Problem is that it only happened with the automatically started volumed. Or at least once it crashed and I killed and restarted it, it never came up. Also, after the latest karmic updates I didn't notic*e the issue anymore. So it already could be fixed. But due to xfce session management bugs (*) I also switched to gnome now.

Maybe we should close this bug for now?

Thanks,
Bernd

PS: (*) Somehow xfce4 has problems to save my running session, it can take up to 30 minutes to shut down my system, when I tell xfce4 to save my session. And on startup, it then forgets to open some programs, e.g. kxkb. Recently, it somehow manages to mess up the panel related xml files and didn't start my session at all anymore. I was then so upset, that I switched to gnome. But given the lack of my time and the availibility of other window managers, I just skipped that part.

Thanks for your answer, Bernd. I'll leave this bug open and incomplete until
someone reports a similar problem.

I left my laptop on overnight. Usually it's very quiet, but I just noticed the fan was running loud. I checked with 'top' and saw that one of the CPU cores was pegged at 100% CPU. The xfce4-volumed process was responsible.

gdb shows me:

(gdb) where
#0 0xb78c5430 in __kernel_vsyscall ()
#1 0xb75e6ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb783c53b in g_poll () from /lib/libglib-2.0.so.0
#3 0xb782f55b in ?? () from /lib/libglib-2.0.so.0
#4 0xb782fb8f in g_main_loop_run () from /lib/libglib-2.0.so.0
#5 0x08049fb2 in ?? ()
#6 0xb753eb56 in __libc_start_main () from /lib/tls/i686/cmov/libc.so.6
#7 0x08049c91 in ?? ()

and strace refused to attach:

chris@chris-laptop:~$ sudo strace -p 2541
[sudo] password for chris:
attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted

so this is still a problem.

I often leave the machine idle, and have only seen this behaviour once before.

This is on an up-to-date karmic box.

Judging by the process' use of CPU time compared to the machine's uptime, it seems that this wasn't a result of the machine being idle, especially given that the process was frozen in gdb for some time before I ran 'uptime':

chris@chris-laptop:~$ ps -ef | grep xfce4-v
chris 2541 1 97 05:00 ? 07:12:56 /usr/bin/xfce4-volumed

chris@chris-laptop:~$ uptime
 12:30:54 up 7:31, 5 users, load average: 0.10, 0.40, 0.84

Hi there and thanks for the additional info,

Unfortunately there is still nothing I can use to identify and fix the bug. Chris, could you please get xfce4-volumed from bzr and build and install it with --enable-debug, and then attach a gdb trace as soon as it takes 100% CPU again? I would at least need to know what function causes this to can identify the problem.

Thanks in advance.

Hi Steve. Unfortunately I didn't notice you had replied. I just had xfce4-volumed go crazy on me again and was going to ask here what I can do to help debug it. It's running as I type, so if there is anything I can with the non-bzr non-debug copy while it's going crazy, I will do so.

Are you sure I want the bzr version, rather than just an 'apt-get source' of the package? That way I'll be testing with the same version that's defective. Perhaps the problem won't show up in the bzr version?

I went ahead and tried to use bzr to check it out, but couldn't see how to pass the --enable-debug flag.

Should I be using bzr-buildpackage? What are the magic words?

Hello,

You can use the package source if you want, no worries. For some unknown
reasons, autotools decided to play a trick on me so --enable-debug isn't
auto-complemented, but it does work, and it will build xfce4-volumed with
the -g option that will enable GDB to give us human-readable informations
about where's it's hanging.

I don't often build packages from source, whether from "apt-get source" or from "bzr". What's the incantation I need to specify to get the -g flag to be passed to the compiler? And is it better to arrange for -O2 not to be used too? If so, how?

Hi there,

Here is a set of instructions that should just work (the apt-get install
should install everything you'll need to build the application):

sudo apt-get install autotools-dev autoconf libtool libnotify-dev
libxfconf-0-dev libxcb-keysyms0-dev libglib2.0-dev
libgstreamer-plugins-base0.10-dev libgstreamer0.10-dev
cd /tmp
bzr branch lp:xfce4-volumed/0.1.6
cd 0.1.6
./autogen.sh
./configure --enable-debug
make
killall xfce4-volumed
gdb ./src/xfce4-volumed
run

Then, once it begins to be using 100% CPU, open the terminal where it run,
hit Ctrl+C once, and then type:
bt

Thanks in advance :)

In addition to the packages Steve pointed to, you of course also need build-essential to be able to build packages in the first place.

Package libxcb-keysyms0-dev is not available, but is referred to by another package.
This may mean that the package is missing, has been obsoleted, or
is only available from another source
However the following packages replace it:
  libxcb-keysyms1-dev

So I'll try using that instead...

Yeah sorry, I forgot the name changed in Karmic. You shall not need
build-essential, however.

2009/10/30, Chris Moore <email address hidden>:
> Package libxcb-keysyms0-dev is not available, but is referred to by another
> package.
> This may mean that the package is missing, has been obsoleted, or
> is only available from another source
> However the following packages replace it:
> libxcb-keysyms1-dev
>
> So I'll try using that instead...
>
> --
> xfce4-volumed takes 100% cpu when system is idle for some time
> https://bugs.launchpad.net/bugs/417778
> You received this bug notification because you are a bug assignee.
>

--
Steve Dodier
Student at École Nationale Supérieure d'Ingénieurs de Bourges
Free Software Developer
OpenPGP : 1B6B1670

Thanks for the instructions, I built it as you said, the only difference being I did it in my home directory so it would survive a reboot, but the backtrace is still useless:

Reading symbols from /home/chris/Programs/xfce4-volumed/0.1.6/src/xfce4-volumed...done.
(gdb) run
Starting program: /home/chris/Programs/xfce4-volumed/0.1.6/src/xfce4-volumed
[Thread debugging using libthread_db enabled]
XCB: RaiseVolume ok, keycode=123 mod=0x0000
XCB: RaiseVolume ok, keycode=123 mod=0x0000
XCB: RaiseVolume ok, keycode=123 mod=0x0000
XCB: LowerVolume ok, keycode=122 mod=0x0000
XCB: LowerVolume ok, keycode=122 mod=0x0000
XCB: LowerVolume ok, keycode=122 mod=0x0000
XCB: Mute ok, keycode=121 mod=0x0000
XCB: Mute ok, keycode=121 mod=0x0000
XCB: Mute ok, keycode=121 mod=0x0000
[New Thread 0xb69fcb70 (LWP 14891)]
[New Thread 0xb61fbb70 (LWP 14892)]
[New Thread 0xb59e2b70 (LWP 14893)]
[Thread 0xb59e2b70 (LWP 14893) exited]
[New Thread 0xb59e2b70 (LWP 14894)]
[New Thread 0xb11e0b70 (LWP 14895)]
[New Thread 0xac9deb70 (LWP 14896)]
** (<unknown>:14887): DEBUG: The card HDAIntelAlsamixer was found and set as the current card.

** (<unknown>:14887): DEBUG: There is no track label stored in xfconf

** (<unknown>:14887): DEBUG: The wanted track could not be found, using the first one instead.

** (<unknown>:14887): DEBUG: Xfconf volume step: 5

^C
Program received signal SIGINT, Interrupt.
0xb7fe2430 in __kernel_vsyscall ()
(gdb) bt
#0 0xb7fe2430 in __kernel_vsyscall ()
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb7f5953b in g_poll () from /lib/libglib-2.0.so.0
#3 0xb7f4c55b in ?? () from /lib/libglib-2.0.so.0
#4 0xb7f4cb8f in g_main_loop_run () from /lib/libglib-2.0.so.0
#5 0x0804a26a in main (argc=1, argv=0xbffff354) at main.c:166
(gdb)

I'll leave the gdb running in case there's something I can do to coax more information out of it.

Feel free to talk to me on jabber (<email address hidden>) if that would speed things up.

I just noticed there are multiple threads:

(gdb) thread apply all bt

Thread 7 (Thread 0xac9deb70 (LWP 14896)):
#0 0xb7fe2430 in __kernel_vsyscall ()
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb6c8ccc2 in ?? () from /usr/lib/libpulse.so.0
#3 0xb6c79e09 in pa_mainloop_poll () from /usr/lib/libpulse.so.0
#4 0xb6c7bc23 in pa_mainloop_iterate () from /usr/lib/libpulse.so.0
#5 0xb6c7bcf4 in pa_mainloop_run () from /usr/lib/libpulse.so.0
#6 0xb6c8cbc3 in ?? () from /usr/lib/libpulse.so.0
#7 0xb6c4fac2 in ?? () from /usr/lib/libpulsecommon-0.9.19.so
#8 0xb7e9580e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#9 0xb74427ee in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 6 (Thread 0xb11e0b70 (LWP 14895)):
#0 0xb7fe2430 in __kernel_vsyscall ()
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb6c8ccc2 in ?? () from /usr/lib/libpulse.so.0
#3 0xb6c79e09 in pa_mainloop_poll () from /usr/lib/libpulse.so.0
#4 0xb6c7bc23 in pa_mainloop_iterate () from /usr/lib/libpulse.so.0
#5 0xb6c7bcf4 in pa_mainloop_run () from /usr/lib/libpulse.so.0
#6 0xb6c8cbc3 in ?? () from /usr/lib/libpulse.so.0
#7 0xb6c4fac2 in ?? () from /usr/lib/libpulsecommon-0.9.19.so
#8 0xb7e9580e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#9 0xb74427ee in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 5 (Thread 0xb59e2b70 (LWP 14894)):
#0 0xb7fe2430 in __kernel_vsyscall ()
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb6c8ccc2 in ?? () from /usr/lib/libpulse.so.0
#3 0xb6c79e09 in pa_mainloop_poll () from /usr/lib/libpulse.so.0
#4 0xb6c7bc23 in pa_mainloop_iterate () from /usr/lib/libpulse.so.0
#5 0xb6c7bcf4 in pa_mainloop_run () from /usr/lib/libpulse.so.0
#6 0xb6c8cbc3 in ?? () from /usr/lib/libpulse.so.0
#7 0xb6c4fac2 in ?? () from /usr/lib/libpulsecommon-0.9.19.so
#8 0xb7e9580e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#9 0xb74427ee in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 3 (Thread 0xb61fbb70 (LWP 14892)):
#0 0xb7fe2430 in __kernel_vsyscall ()
---Type <return> to continue, or q <return> to quit---
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb6d869b2 in ?? () from /usr/lib/gstreamer-0.10/libgstalsa.so
#3 0xb7e02895 in ?? () from /usr/lib/libgstreamer-0.10.so.0
#4 0xb7e041a7 in ?? () from /usr/lib/libgstreamer-0.10.so.0
#5 0xb7f7499f in ?? () from /lib/libglib-2.0.so.0
#6 0xb7f7336f in ?? () from /lib/libglib-2.0.so.0
#7 0xb7e9580e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#8 0xb74427ee in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 2 (Thread 0xb69fcb70 (LWP 14891)):
#0 0xb7fe2430 in __kernel_vsyscall ()
#1 0xb7434ba6 in poll () from /lib/tls/i686/cmov/libc.so.6
#2 0xb6d869b2 in ?? () from /usr/lib/gstreamer-0.10/libgstalsa.so
#3 0xb7e02895 in ?? () from /usr/lib/libgstreamer-0.10.so.0
#4 0xb7e041a7 in ?? () from /usr/lib/libgstreamer-0.10.so.0
#5 0xb7f7499f in ?? () from /lib/libglib-2.0.so.0
#6 0xb7f7336f in ?? () from /lib/libglib-2.0.so.0
#7 0xb7e9580e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#8 0xb74427ee in clone () from /lib/tls/i686/cmov/libc.so.6

Thread...

Alright, the trace confirms what I thought: xfce4-volumed is idling in the
main loop, and either gstreamer or pulseaudio is doing some nonsense. I
don't know how to debug such problems in GStreamer or Pulseaudio, I'll look
at this in a few days when I have some time to ask advice about how to
proceed.

I'll add you on Jabber tonight. Thanks for that trace!

On Friday 30 October 2009, Steve Dodier wrote:
> Alright, the trace confirms what I thought: xfce4-volumed is idling in the
> main loop, and either gstreamer or pulseaudio is doing some nonsense. I
> don't know how to debug such problems in GStreamer or Pulseaudio, I'll look
> at this in a few days when I have some time to ask advice about how to
> proceed.

I don't think I had Pulseaudio installed all the time. I try it from time to
time, but especially with voip programs such as skype or qutecom I run into
problems and always remove it after a few days (I really don't like skype, but
unfortunately need it for my work :( ). So it is highly unlikely I had skype
installed all the time while I noticed this bug.

Anyway, if this is an issue with Pulse or gstreamer, shouldn't be gnome
affected as well somehow? And I don't notice any problems now that I use
gnome.

Cheers,
Bernd

I can confirm this very annoying bug on latest xubuntu.
I didn't find a regular pattern, but I noticed it happens after some suspend/resume cycles.

I never suspend or resume, and I see the same bug.

I've not seen the bug since running:

  sudo apt-get remove xfce4-volumed

I don't know what the package is for, but I've not missed it.

Description: Volume management daemon for Xfce 4
 Xfce4-volumed is responsible for making the volume up/down and mute keys of the
 keyboard work automatically, and uses the Xfce 4 mixer's defined card and track
 for chosing which track to act on. It also provides volume change / mute toggle
 notifications if the notification server used supports x-canonical-icon-only
 and x-canonical-synchronous notifications.

Yes, it is xfce4-volumed process to eat the 100% of cpu sometimes, but removing it doesn't seems a solution of the bug.

Removing the package removed all the symptoms of the bug and didn't introduce any further problems.

It was a very effective fix from my point of view.

I realise there's probably a more elegant fix, but I also realise we're unlikely to see it any time soon.

> Removing the package removed all the symptoms of the bug and didn't
> introduce any further problems.
>
> It was a very effective fix from my point of view.
>
> I realise there's probably a more elegant fix, but I also realise we're
> unlikely to see it any time soon.
>

Well removing software for eliminate bugs, it is not a matter of be elegant or not, is just removing software.

But still this bug is present and people which care about control volumes with keyboard then will probably care also to try resolving this problem.

I find useless keeping replying that removing that package fix the issue.

FWIW, I can confirm this bug on Xubuntu on Karmic. (never saw it before I upgraded from Hardy). For me, it's after a suspend / resume cycle. I just kill the process and get on with life. I guess I'll go the remove option since I don't use the keyboard volume control anyway

This bug also affects me on Karmic and it's very easy to reproduce: I have a USB headset connected to my machine and whenever I unplug the USB headset xfce4-volumed (and xfce4-mixer-plugin) use up 100% CPU.

I hope to be able to do some debugging later on...

I wish you could send me some GDB backtraces to see where it's hanging
exactly. I've still not been able to trigger the bug on my computers. Thanks
in advance.

Thanks Charlie. This shows the problem is more likely to be in Gstreamer
than XFCE directly as it happens with two different components
(xfce4-mixer-plugin and xfce4-volumed).

I am seeing 3 threads for the xfce4-volumed process, 2 of the threads appear to be related to gstreamer (maybe one for each sound device/mixer) and one of these threads is spinning when I unplug my USB headset, stacktrace for that thread is:

#0 0x00007ffff35063c3 in poll () from /lib/libc.so.6
#1 0x00007fffef086e9b in ?? () from /usr/lib/gstreamer-0.10/libgstalsa.so
#2 0x00007ffff6be5417 in ?? () from /usr/lib/libgstreamer-0.10.so.0
#3 0x00007ffff7b7e142 in ?? () from /lib/libglib-2.0.so.0
#4 0x00007ffff7b7cb44 in ?? () from /lib/libglib-2.0.so.0
#5 0x00007ffff7292a04 in start_thread () from /lib/libpthread.so.0
#6 0x00007ffff351280d in clone () from /lib/libc.so.6
#7 0x0000000000000000 in ?? ()

So looks like I need to have a closer look at gstreamer then...

BTW, strace for the spinning thread shows

poll([{fd=12, events=POLLIN|POLLERR|POLLNVAL}, {fd=10, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, -1) = 1 ([{fd=12, revents=POLLERR|POLLNVAL}])

So my guess would be that gstreamer doesn't handle the POLLERR|POLLNVAL result properly.

Looks like this is essentially https://bugzilla.gnome.org/show_bug.cgi?id=507527

Has anyone tried removing gnome-mixer to see if that is the cause of this bug? I ask because Xubuntu does not install gnome-mixer by default. It does use xfce4-mixer and xfce4-volumed. If gnome-mixer is causing the issue, removing it should make the issue go away (as a WORKAROUND).

Thanks for helping with this important issue.

https://bugzilla.gnome.org/show_bug.cgi?id=507527 was initially raised for gnome-mixer, but has been moved to GStreamer (see comment 6) and is now raised against "Product: GStreamer, Component: gst-plugins-base" which is where the problem is (see comment 5).

Just one more observation: xfce4-volumed opens all mixers on startup, then chooses to use only one, but it doesn't bother to close the other mixers. This behaviour could be improved to avoid wasting resources (btw, this would actually also fix the problem in some cases where the problem is triggered by unplugging a secondary sound device like a USB headset that's not being used by xfce4-volumed).

2010/1/9 cmeerw <email address hidden>

> Just one more observation: xfce4-volumed opens all mixers on startup,
> then chooses to use only one, but it doesn't bother to close the other
> mixers. This behaviour could be improved to avoid wasting resources
> (btw, this would actually also fix the problem in some cases where the
> problem is triggered by unplugging a secondary sound device like a USB
> headset that's not being used by xfce4-volumed).
>
>
Hm, that's one of the things I have to do. At the moment I just open them
all to allow switching from one to another when the name of the card is
changed in xfconf. This will be done for the next version of xfce4-volumed.

Hi, I have found a use-case for this bug that I can repeat every single time. I have a USB webcam (Logitech C600). If I have the webcam plugged in when xfce4-mixer (and xfc4-volumed) starts, everything is fine. However, if I then unplug the webcam, both processes begin racing out of control. I removed xfce4-volumed to see if this behavior continues with just xfce4-mixer. I ran the webcam disconnect test again, revealing that even without volumed installed, xfce4-mixer still races to 100% CPU the moment after I unplug the USB cam.

I think what might be happening (in my case) is that because the device is removed, perhaps the mixer doesn't expect a device to just disappear, and still attempts to query it.

Release: Xubuntu 9.10 (with updates)

Before removing the webcam:

kyle@caeleo:~$ ls -l /proc/20580/fd
total 0
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 0 -> /dev/null
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 1 -> /home/kyle/.xsession-errors
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 10 -> pipe:[287424]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 11 -> pipe:[287424]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 12 -> /dev/snd/controlC0
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 13 -> pipe:[9197]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 14 -> pipe:[9197]
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 15 -> pipe:[287425]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 16 -> pipe:[287425]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 17 -> /dev/snd/controlC1
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 18 -> /dev/mixer
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 19 -> socket:[287426]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 2 -> /home/kyle/.xsession-errors
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 21 -> pipe:[9206]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 3 -> socket:[287416]
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 4 -> pipe:[7647]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 5 -> pipe:[7647]
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 6 -> pipe:[9270]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 7 -> pipe:[9270]
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 8 -> pipe:[287422]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 9 -> pipe:[287422]

After removing:

kyle@caeleo:~$ ls -l /proc/20580/fd
total 0
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 0 -> /dev/null
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 1 -> /home/kyle/.xsession-errors
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 10 -> pipe:[287424]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 11 -> pipe:[287424]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 12 -> /dev/snd/controlC0
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 13 -> pipe:[9197]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 14 -> pipe:[9197]
lr-x------ 1 kyle kyle 64 2010-02-24 11:33 15 -> pipe:[287425]
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 16 -> pipe:[287425]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 17 -> /dev/snd/controlC1 (deleted)
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 18 -> /dev/mixer
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 19 -> socket:[287426]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 2 -> /home/kyle/.xsession-errors
l-wx------ 1 kyle kyle 64 2010-02-24 11:33 21 -> pipe:[9206]
lrwx------ 1 kyle kyle 64 2010-02-24 11:33 3 -> socket:[28741...

The problem is linked to a GStreamer function doing nonsense when some devices are added or removed, so I'm adding GStreamer to the report, hopefully people who know it better than I can bring input about what's going on.

The Gnome/GStreamer bug is updated. There is a workaround (sadly, no good for
long-running processes).

GStreamer bug: https://bugzilla.gnome.org/show_bug.cgi?id=507527