Ticket #758 (new defect)

Opened 2 years ago

Last modified 2 years ago

High CPU load with mixers as `gnome-volume-control.pulse` and `pavucontrol`.

Reported by: PaulePanter Owned by: lennart
Milestone: Component: daemon
Keywords: Cc:

Description

Dear PulseAudio hackers,

I try to hunt down a situation where PulseAudio uses over 100 % of CPU load. I can reproduce it by running gnome-volume-control which starts gnome-volume-control.pulse I think.

I followed HowToDebugCPULoadBugs and HowToUseOProfile and this is what I got. 

$ sudo opcontrol --start
Using default event: CPU_CLK_UNHALTED:100000:0:1:1
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/samples/oprofiled.log
Daemon started.
Profiler running.
$ # start and quit `gnome-volume-control`
$ sudo opcontrol --stop
Stopping profiling.
$ opreport -l /usr/bin/pulseaudio
warning: [vdso] (tgid:3253 range:0xf76e8000-0xf76e9000) could not be found.
CPU: AMD64 processors, speed 2100 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               symbol name
593      100.000  [vdso] (tgid:3253 range:0xf76e8000-0xf76e9000) [vdso] (tgid:3253 range:0xf76e8000-0xf76e9000)
$ opreport -l /usr/bin/gnome-volume-control.pulse
warning: [vdso] (tgid:19426 range:0xf77a8000-0xf77a9000) could not be found.
CPU: AMD64 processors, speed 2100 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               symbol name
1130     54.6422  gnome-volume-control.pulse /usr/bin/gnome-volume-control.pulse
938      45.3578  [vdso] (tgid:19426 range:0xf77a8000-0xf77a9000) [vdso] (tgid:19426 range:0xf77a8000-0xf77a9000)

I am using Debian Sid/unstable with the following versions. 

$ LANG=C dpkg -l pulseaudio gnome-media
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Cfg-files/Unpacked/Failed-cfg/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                                    Version                                 Description
+++-=======================================-=======================================-==============================================================================================
ii  gnome-media                             2.28.1-1                                GNOME media utilities
ii  pulseaudio                              0.9.21-1                                PulseAudio sound server

Please tell me what else you need. I looked through the changelog of the version in Git but did not notice any important changes (only compile fixes and so on) so refrained from installing Git HEAD on my system.

Thanks,

Paul

Attachments

20100202--pa.log (97.8 kB) - added by PaulePanter 2 years ago.
$ LANG=C pulseaudio -vvvvv 2> /tmp/20100202--pa.log # gnome-volume-control started in other terminal.

Change History

follow-ups: ↓ 2 ↓ 10   Changed 2 years ago by lennart

A per symbol breakdown would be good.

in reply to: ↑ 1 ; follow-up: ↓ 3   Changed 2 years ago by PaulePanter

Replying to lennart:

A per symbol breakdown would be good.

What options do I have to pass to opreport to get such a symbol breakdown?

I searched for this »oprofile "symbol breakdown"« and the hits did not contain any information on what options to use. Reading the manual page (man opreport) and searching for »symbol« also just brought the -l option to my attention.

in reply to: ↑ 2 ; follow-up: ↓ 8   Changed 2 years ago by PaulePanter

Replying to PaulePanter:

Replying to lennart:

A per symbol breakdown would be good.

What options do I have to pass to opreport to get such a symbol breakdown? I searched for this »oprofile "symbol breakdown"« and the hits did not contain any information on what options to use. Reading the manual page (man opreport) and searching for »symbol« also just brought the -l option to my attention.

I just read HowToUseOProfile again were it says in step 5 »Generate a per-symbol break down of the profile data:« to use opreport -l /usr/bin/pulseaudio whose output I provided in my report. Or did I do anything wrong. I have the package with debug symbols installed (pulseaudio-dbg 0.9.21-1).

  Changed 2 years ago by PaulePanter

  • summary changed from High CPU load with `gnome-volume-control.pulse`. to High CPU load with mixers as `gnome-volume-control.pulse` and `pavucontrol`.

I am able to reproduce this with pavucontrol too. I therefore adapted the summary. 

$ dpkg -l pavucontrol
[…]
ii  pavucontrol    0.9.9-1        PulseAudio Volume Control

  Changed 2 years ago by PaulePanter

Just a side note in case it matters. I am using a 32-bit userspace with a 64-bit Linux kernel.

follow-up: ↓ 7   Changed 2 years ago by lennart

BTW. as a side note: it is expected that PA's PCU usage increases when pavucontrol/g-v-c runs, since for volume meters on screen we decrease the latency of the audio devices so that what you hear and what you see is neatly in sync. Lower latencies automatically mean higher CPU usage.

So, you can expect something like 30% or so in the worst case, which multiplies if you have many cards.

in reply to: ↑ 6   Changed 2 years ago by PaulePanter

Replying to lennart:

BTW. as a side note: it is expected that PA's PCU usage increases when pavucontrol/g-v-c runs, since for volume meters on screen we decrease the latency of the audio devices so that what you hear and what you see is neatly in sync. Lower latencies automatically mean higher CPU usage.

In top CPU% goes up to 120–130 % for pulseaudio and 50–60 % for pavucontrol/g-v-c.

So, you can expect something like 30% or so in the worst case, which multiplies if you have many cards.

I just have one onboard card.

in reply to: ↑ 3 ; follow-up: ↓ 9   Changed 2 years ago by PaulePanter

Replying to PaulePanter:

Replying to PaulePanter:

Replying to lennart:

A per symbol breakdown would be good.

What options do I have to pass to opreport to get such a symbol breakdown? I searched for this »oprofile "symbol breakdown"« and the hits did not contain any information on what options to use. Reading the manual page (man opreport) and searching for »symbol« also just brought the -l option to my attention.

I just read HowToUseOProfile again were it says in step 5 »Generate a per-symbol break down of the profile data:« to use opreport -l /usr/bin/pulseaudio whose output I provided in my report. Or did I do anything wrong. I have the package with debug symbols installed (pulseaudio-dbg 0.9.21-1).

Could you please point me to some instruction on how to generate the information you need.

in reply to: ↑ 8   Changed 2 years ago by PaulePanter

Replying to PaulePanter:

Replying to PaulePanter:

Replying to PaulePanter:

Replying to lennart:

A per symbol breakdown would be good.

What options do I have to pass to opreport to get such a symbol breakdown? I searched for this »oprofile "symbol breakdown"« and the hits did not contain any information on what options to use. Reading the manual page (man opreport) and searching for »symbol« also just brought the -l option to my attention.

I just read HowToUseOProfile again were it says in step 5 »Generate a per-symbol break down of the profile data:« to use opreport -l /usr/bin/pulseaudio whose output I provided in my report. Or did I do anything wrong. I have the package with debug symbols installed (pulseaudio-dbg 0.9.21-1).

Could you please point me to some instruction on how to generate the information you need.

Thanks to Ford_Perfect on the IRC channel, it was pointed out to me, that there seems to be some problems with the debugging symbols. I try to straighten this out [1] and will submit the OProfile symbol breakdown afterward.

[1] http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=565373

in reply to: ↑ 1   Changed 2 years ago by PaulePanter

Replying to lennart:

A per symbol breakdown would be good.

With the great help in the #oprofile IRC channel I was told that you maybe need the output of oprofile -l. You can find the full output in pastebin. Here is an excerpt. 

$ oprofile -l
[ warnings ]
CPU: AMD64 processors, speed 1800 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               app name                 symbol name
707224   20.0892  libpulsecore-0.9.21.so   libpulsecore-0.9.21.so   peaks_resample
579277   16.4548  libpulsecore-0.9.21.so   libpulsecore-0.9.21.so   remap_channels_matrix_c
383113   10.8826  libpulsecore-0.9.21.so   libpulsecore-0.9.21.so   pa_sconv_s16le_to_float32ne
196477    5.5811  libc-2.10.2.so           libc-2.10.2.so           memcpy
101982    2.8969  libc-2.10.2.so           libc-2.10.2.so           memset
53118     1.5089  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so do_something
46831     1.3303  libpthread-2.10.2.so     libpthread-2.10.2.so     pthread_mutex_lock
39875     1.1327  libdbus-1.so.3.4.0       libdbus-1.so.3.4.0       /lib/libdbus-1.so.3.4.0
35026     0.9949  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memblock_unref
28470     0.8087  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so __i686.get_pc_thunk.bx
25617     0.7277  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_flist_pop
23618     0.6709  libxaa.so                libxaa.so                /usr/lib/xorg/modules/libxaa.so
23385     0.6643  libpthread-2.10.2.so     libpthread-2.10.2.so     pthread_mutex_unlock
23029     0.6542  oprofiled                oprofiled                /usr/bin/oprofiled
22709     0.6451  libpthread-2.10.2.so     libpthread-2.10.2.so     __pthread_mutex_unlock_usercnt
22080     0.6272  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_flist_push
21888     0.6217  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so enable_mainloop_sources
20619     0.5857  libglib-2.0.so.0.2200.4  libglib-2.0.so.0.2200.4  g_main_context_prepare
18747     0.5325  libglib-2.0.so.0.2200.4  libglib-2.0.so.0.2200.4  g_main_context_check
18574     0.5276  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memblockq_push
18368     0.5218  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so callback
17780     0.5051  gnome-volume-control.pulse gnome-volume-control.pulse /usr/bin/gnome-volume-control.pulse
17264     0.4904  libpulse.so.0.12.2       libpulse.so.0.12.2       pa_mainloop_dispatch
15501     0.4403  libasound.so.2.0.0       libasound.so.2.0.0       /usr/lib/libasound.so.2.0.0
14998     0.4260  [vdso] (tgid:29071 range:0xf77e0000-0xf77e1000) gnome-volume-control.pulse [vdso] (tgid:29071 range:0xf77e0000-0xf77e1000)
14866     0.4223  libxcb.so.1.1.0          libxcb.so.1.1.0          /usr/lib/libxcb.so.1.1.0
14781     0.4199  libpthread-2.10.2.so     libpthread-2.10.2.so     __i686.get_pc_thunk.bx
14624     0.4154  libpulse-mainloop-glib.so.0.0.4 libpulse-mainloop-glib.so.0.0.4 /usr/lib/libpulse-mainloop-glib.so.0.0.4
14614     0.4151  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_pstream_ref
13719     0.3897  libc-2.10.2.so           libc-2.10.2.so           __i686.get_pc_thunk.bx
13635     0.3873  libpulsecore-0.9.21.so   libpulsecore-0.9.21.so   pa_resampler_run
13379     0.3800  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_run_once
13233     0.3759  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_iochannel_is_readable
10810     0.3071  libglib-2.0.so.0.2200.4  libglib-2.0.so.0.2200.4  g_main_context_iterate
10782     0.3063  libpixman-1.so.0.16.4    libpixman-1.so.0.16.4    /usr/lib/libpixman-1.so.0.16.4
10339     0.2937  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_once_begin
10052     0.2855  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memblock_ref
9931      0.2821  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_iochannel_read_with_creds
9907      0.2814  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_pstream_unref
9843      0.2796  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_mcalign_pop
9817      0.2789  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_queue_pop
9815      0.2788  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memchunk_reset
9612      0.2730  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memblock_release
9174      0.2606  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so fix_current_read
9115      0.2589  libgobject-2.0.so.0.2200.4 libgobject-2.0.so.0.2200.4 signal_emit_unlocked_R
9050      0.2571  libglib-2.0.so.0.2200.4  libglib-2.0.so.0.2200.4  g_slice_free1
9033      0.2566  libglib-2.0.so.0.2200.4  libglib-2.0.so.0.2200.4  g_main_context_dispatch
9000      0.2557  libc-2.10.2.so           libc-2.10.2.so           ppoll
8841      0.2511  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_mutex_lock
8792      0.2497  libpulsecommon-0.9.21.so libpulsecommon-0.9.21.so pa_memblockq_peek
[…]

I hope that is the information you need.

Thanks,

Paul

Changed 2 years ago by PaulePanter

$ LANG=C pulseaudio -vvvvv 2> /tmp/20100202--pa.log # gnome-volume-control started in other terminal.

follow-up: ↓ 12   Changed 2 years ago by PaulePanter

I forgot to attach the log as written down in Community or Troubleshooting and had some problems generating them (see #785, mistake on my part). 

$ pulseaudio -k # `autospawn = 0` in `~/.pulse/client.conf`
$ LANG=C pulseaudio -vvvvv # `gnome-volume-control` started in other terminal. ConsoleKit messages removed.
[…]
I: alsa-source.c: Increasing wakeup watermark to 361.50 ms
W: ratelimit.c: 52071 events suppressed
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
I: alsa-source.c: Overrun!
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
W: ratelimit.c: 107245 events suppressed
I: alsa-source.c: Overrun!
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
I: alsa-source.c: Overrun!
D: memblock.c: Pool full
D: memblock.c: Pool full
D: alsa-source.c: hwbuf_unused=0
D: alsa-source.c: setting avail_min=443
D: module-suspend-on-idle.c: Source alsa_input.pci-0000_20_01.0.analog-stereo becomes idle, timeout in 5 seconds.
D: module-suspend-on-idle.c: Source alsa_input.pci-0000_20_01.0.analog-stereo becomes idle, timeout in 5 seconds.
D: core.c: Hmm, no streams around, trying to vacuum.
[…]

I attached the whole log file.

in reply to: ↑ 11   Changed 2 years ago by PaulePanter

Replying to PaulePanter:

[…] 

$ pulseaudio -k # `autospawn = 0` in `~/.pulse/client.conf`
$ LANG=C pulseaudio -vvvvv # `gnome-volume-control` started in other terminal. ConsoleKit messages removed.
[…]
I: alsa-source.c: Increasing wakeup watermark to 361.50 ms
W: ratelimit.c: 52071 events suppressed
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
D: memblock.c: Pool full
I: alsa-source.c: Overrun!
[…]

[…]

I searched for this error message on the WWW and did get some responses that this might be related to the ALSA driver. Can you confirm that?

I added the following options to load with the snd_hda_intel module. 

$ more /etc/modprobe.d/snd-hda-intel.conf 
options snd_hda_intel position_fix=1

No starting gnome-volume-manager does not give a high CPU load anymore and behaves as expected. The problem now is, when there is high load on the system as opening an application the audio is not useable anymore (strange noises instead of music in MPlayer for example) and the application needs to be restarted.

I also find the following in the output dmesg. 

$ dmesg
[…]
[ 3625.517773] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517794] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517814] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517835] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517856] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517877] hda-intel: spurious response 0xe0160:0x0, last cmd=0x1f0004
[ 3625.517898] hda-intel: spurious response 0x1:0x0, last cmd=0x1f0004
[ 3625.517919] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517940] hda-intel: spurious response 0x0:0x0, last cmd=0x1f0004
[ 3625.517960] hda-intel: spurious response 0x20025:0x0, last cmd=0x1f0004

Is that a known problem? Is my only option to report this to the ALSA guys?

Note: See TracTickets for help on using tickets.