Maybe the new kernel has enabled some new sample rate that doesn't match the audio that you're playing, so pulseaudio has to do resampling that it didn't previously need to do?

Could you attach the output of "pactl list" in both cases (old kernel with low cpu use, new kernel with high cpu use)?

Hi,
Wherein reported are the reports that you asked me.
Debian wheezy with kernel 3.12.25 :

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.25+ #29 PREEMPT Sun Sep 21 08:38:08 CEST 2014 armv6l GNU/Linux


pi@raspberrypi ~ $ pactl list
Module #0
	Name: module-alsa-card
	Argument: device_id="0" name="platform-snd-hifiberry-amp.0" card_name="alsa_card.platform-snd-hifiberry-amp.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes card_properties="module-udev-detect.discovered=1"
	Usage counter: 3
	Properties:
		module.author = "Lennart Poettering"
		module.description = "ALSA Card"
		module.version = "2.0"

Module #1
	Name: module-udev-detect
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Detect available audio hardware and load matching drivers"
		module.version = "2.0"

Module #2
	Name: module-native-protocol-unix
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (UNIX sockets)"
		module.version = "2.0"

Module #3
	Name: module-stream-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute/device state of streams"
		module.version = "2.0"

Module #4
	Name: module-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute state of devices"
		module.version = "2.0"

Module #5
	Name: module-default-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the default sink and source"
		module.version = "2.0"

Module #6
	Name: module-dbus-protocol
	Argument: access=local
	Usage counter: n/a
	Properties:
		module.author = "Tanu Kaskinen"
		module.description = "D-Bus interface"
		module.version = "2.0"

Module #7
	Name: module-rescue-streams
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "When a sink/source is removed, try to move their streams to the default sink/source"
		module.version = "2.0"

Module #8
	Name: module-always-sink
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Colin Guthrie"
		module.description = "Always keeps at least one sink loaded even if it's a null one"
		module.version = "2.0"

Module #9
	Name: module-position-event-sounds
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Position event sounds between L and R depending on the position on screen of the widget triggering them."
		module.version = "2.0"

Module #10
	Name: module-native-protocol-tcp
	Argument: auth-ip-acl=127.0.0.1;192.168.0.0/24 auth-anonymous=1
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (TCP sockets)"
		module.version = "2.0"

Module #11
	Name: module-zeroconf-publish
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "mDNS/DNS-SD Service Publisher"
		module.version = "2.0"

Sink #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Description: snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0:  70% 1:  70%
	        balance 0.00
	Base Volume: 100%
	Monitor Source: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Latency: 104494 usec, configured 105000 usec
	Flags: HARDWARE HW_VOLUME_CTRL LATENCY 
	Properties:
		alsa.resolution_bits = "16"
		device.api = "alsa"
		device.class = "sound"
		alsa.class = "generic"
		alsa.subclass = "generic-mix"
		alsa.name = ""
		alsa.id = "HifiBerry AMP HiFi tas5713-hifi-0"
		alsa.subdevice = "0"
		alsa.subdevice_name = "subdevice #0"
		alsa.device = "0"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "front:0"
		device.buffering.buffer_size = "352800"
		device.buffering.fragment_size = "176400"
		device.access_mode = "mmap+timer"
		device.profile.name = "analog-stereo"
		device.profile.description = "Analog Stereo"
		device.description = "snd_rpi_hifiberry_amp Analog Stereo"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Ports:
		analog-output: Analog Output (priority: 9900)
	Active Port: analog-output
	Formats:
		pcm

Source #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Description: Monitor of snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Base Volume: 100%
	             0.00 dB
	Monitor of Sink: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Latency: 0 usec, configured 2000000 usec
	Flags: DECIBEL_VOLUME LATENCY 
	Properties:
		device.description = "Monitor of snd_rpi_hifiberry_amp Analog Stereo"
		device.class = "monitor"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Formats:
		pcm

Sink Input #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 0
	Sink: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 0 usec
	Sink Latency: 82373 usec
	Resample method: n/a
	Properties:
		media.name = "Shairport Stream"
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2218"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"

Source Output #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 4
	Source: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 58775 usec
	Source Latency: 0 usec
	Resample method: n/a
	Properties:
		media.name = "cimpulse"
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2341"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "source-output-by-application-name:cimpulse"

Client #0
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2218"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #4
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2341"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #7
	Driver: protocol-native.c
	Owner Module: 10
	Properties:
		application.name = "pactl"
		native-protocol.peer = "TCP/IP client from 127.0.0.1:43601"
		native-protocol.version = "26"
		application.process.id = "2677"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "pactl"
		application.language = "en_GB.UTF-8"
		window.x11.display = ":0.0"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		application.process.session_id = "d3670ff77a0bb988a953e7f053a3f4e7-1411426031.986903-1502075250"

Card #0
	Name: alsa_card.platform-snd-hifiberry-amp.0
	Driver: module-alsa-card.c
	Owner Module: 0
	Properties:
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		device.description = "snd_rpi_hifiberry_amp"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Profiles:
		output:analog-stereo: Analog Stereo Output (sinks: 1, sources: 0, priority. 6000)
		off: Off (sinks: 0, sources: 0, priority. 0)
	Active Profile: output:analog-stereo
	Ports:
		analog-output: Analog Output (priority: 9900)
			Part of profile(s): output:analog-stereo

CPU usage by pulseaudio without streaming audio before and after with streaming audio:

pi@raspberrypi ~ $ top

top - 00:49:54 up 3 min,  2 users,  load average: 0.77, 0.54, 0.23
Tasks:  99 total,   1 running,  98 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.1 us,  3.4 sy,  1.0 ni, 92.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    447988 total,   177748 used,   270240 free,    23140 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    78768 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2140 pulse      9 -11 88304 8956 3584 S   2.3  2.0   0:15.71 pulseaudio        
 2392 root      20   0 23944  15m 4776 S   1.6  3.6   0:06.13 Xorg              
 2650 pi        20   0  4672 1368 1020 R   1.3  0.3   0:00.22 top               
 2341 root      30  10 91464 2264 1816 S   1.0  0.5   0:01.99 LightSone         
 2609 pi        20   0  113m  10m 8424 S   0.7  2.4   0:03.12 lxterminal        
   39 root      20   0     0    0    0 S   0.3  0.0   0:01.29 mmcqd/0           
  230 root      20   0     0    0    0 S   0.3  0.0   0:01.87 usb-storage       
  268 root      20   0     0    0    0 S   0.3  0.0   0:00.41 kworker/0:2       
 2263 root      20   0     0    0    0 S   0.3  0.0   0:00.30 RTW_CMD_THREAD   


pi@raspberrypi ~ $ top

top - 00:48:22 up 2 min,  2 users,  load average: 0.64, 0.35, 0.14
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
%Cpu(s): 17.3 us, 13.1 sy,  0.7 ni, 67.8 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem:    447988 total,   147380 used,   300608 free,    14412 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    69540 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2140 pulse      9 -11 88304 7864 3584 S  15.3  1.8   0:05.05 pulseaudio        
 2218 pi        20   0  115m 3896 2412 S  11.7  0.9   0:02.37 shairport         
 2392 root      20   0 17412  10m 4076 S   2.0  2.3   0:02.13 Xorg              
 2627 pi        20   0  4672 1368 1020 R   1.3  0.3   0:00.30 top               
 2341 root      30  10 91464 2264 1816 S   1.0  0.5   0:00.97 LightSone         
    6 root      20   0     0    0    0 S   0.3  0.0   0:00.27 kworker/u2:0      
  268 root      20   0     0    0    0 S   0.3  0.0   0:00.15 kworker/0:2       
 2263 root      20   0     0    0    0 S   0.3  0.0   0:00.15 RTW_CMD_THREAD    
 2498 pi        20   0  103m 8708 6896 S   0.3  1.9   0:01.42 lxpanel           
 2609 pi        20   0  112m 9568 7444 S   0.3  2.1   0:01.02 lxterminal        

Debian wheezy with kernel 3.12.28 :

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.28+ #713 PREEMPT Fri Sep 19 16:43:32 BST 2014 armv6l GNU/Linux



pi@raspberrypi ~ $ pactl list
Module #0
	Name: module-alsa-card
	Argument: device_id="0" name="platform-snd-hifiberry-amp.0" card_name="alsa_card.platform-snd-hifiberry-amp.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes card_properties="module-udev-detect.discovered=1"
	Usage counter: 3
	Properties:
		module.author = "Lennart Poettering"
		module.description = "ALSA Card"
		module.version = "2.0"

Module #1
	Name: module-udev-detect
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Detect available audio hardware and load matching drivers"
		module.version = "2.0"

Module #2
	Name: module-native-protocol-unix
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (UNIX sockets)"
		module.version = "2.0"

Module #3
	Name: module-stream-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute/device state of streams"
		module.version = "2.0"

Module #4
	Name: module-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute state of devices"
		module.version = "2.0"

Module #5
	Name: module-default-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the default sink and source"
		module.version = "2.0"

Module #6
	Name: module-dbus-protocol
	Argument: access=local
	Usage counter: n/a
	Properties:
		module.author = "Tanu Kaskinen"
		module.description = "D-Bus interface"
		module.version = "2.0"

Module #7
	Name: module-rescue-streams
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "When a sink/source is removed, try to move their streams to the default sink/source"
		module.version = "2.0"

Module #8
	Name: module-always-sink
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Colin Guthrie"
		module.description = "Always keeps at least one sink loaded even if it's a null one"
		module.version = "2.0"

Module #9
	Name: module-position-event-sounds
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Position event sounds between L and R depending on the position on screen of the widget triggering them."
		module.version = "2.0"

Module #10
	Name: module-native-protocol-tcp
	Argument: auth-ip-acl=127.0.0.1;192.168.0.0/24 auth-anonymous=1
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (TCP sockets)"
		module.version = "2.0"

Module #11
	Name: module-zeroconf-publish
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "mDNS/DNS-SD Service Publisher"
		module.version = "2.0"

Sink #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Description: snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0:  70% 1:  70%
	        balance 0.00
	Base Volume: 100%
	Monitor Source: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Latency: 887328 usec, configured 756000 usec
	Flags: HARDWARE HW_VOLUME_CTRL LATENCY 
	Properties:
		alsa.resolution_bits = "16"
		device.api = "alsa"
		device.class = "sound"
		alsa.class = "generic"
		alsa.subclass = "generic-mix"
		alsa.name = ""
		alsa.id = "HifiBerry AMP HiFi tas5713-hifi-0"
		alsa.subdevice = "0"
		alsa.subdevice_name = "subdevice #0"
		alsa.device = "0"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "front:0"
		device.buffering.buffer_size = "352800"
		device.buffering.fragment_size = "176400"
		device.access_mode = "mmap+timer"
		device.profile.name = "analog-stereo"
		device.profile.description = "Analog Stereo"
		device.description = "snd_rpi_hifiberry_amp Analog Stereo"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Ports:
		analog-output: Analog Output (priority: 9900)
	Active Port: analog-output
	Formats:
		pcm

Source #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Description: Monitor of snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Base Volume: 100%
	             0.00 dB
	Monitor of Sink: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Latency: 0 usec, configured 2000000 usec
	Flags: DECIBEL_VOLUME LATENCY 
	Properties:
		device.description = "Monitor of snd_rpi_hifiberry_amp Analog Stereo"
		device.class = "monitor"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Formats:
		pcm

Sink Input #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 0
	Sink: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 0 usec
	Sink Latency: 810395 usec
	Resample method: n/a
	Properties:
		media.name = "Shairport Stream"
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2162"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"

Source Output #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 4
	Source: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 795986 usec
	Source Latency: 0 usec
	Resample method: n/a
	Properties:
		media.name = "cimpulse"
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2280"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "source-output-by-application-name:cimpulse"

Client #0
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2162"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #4
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2280"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #7
	Driver: protocol-native.c
	Owner Module: 10
	Properties:
		application.name = "pactl"
		native-protocol.peer = "TCP/IP client from 127.0.0.1:37702"
		native-protocol.version = "26"
		application.process.id = "2624"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "pactl"
		application.language = "en_GB.UTF-8"
		window.x11.display = ":0.0"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		application.process.session_id = "d3670ff77a0bb988a953e7f053a3f4e7-1412248712.131666-566053987"

Card #0
	Name: alsa_card.platform-snd-hifiberry-amp.0
	Driver: module-alsa-card.c
	Owner Module: 0
	Properties:
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		device.description = "snd_rpi_hifiberry_amp"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Profiles:
		output:analog-stereo: Analog Stereo Output (sinks: 1, sources: 0, priority. 6000)
		off: Off (sinks: 0, sources: 0, priority. 0)
	Active Profile: output:analog-stereo
	Ports:
		analog-output: Analog Output (priority: 9900)
			Part of profile(s): output:analog-stereo


CPU usage by pulseaudio without streaming audio before and after with streaming audio:


pi@raspberrypi ~ $ top

top - 13:20:09 up 2 min,  2 users,  load average: 0.84, 0.65, 0.27
Tasks:  99 total,   1 running,  98 sleeping,   0 stopped,   0 zombie
%Cpu(s): 11.7 us,  7.2 sy,  2.8 ni, 77.9 id,  0.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    447864 total,   177192 used,   270672 free,    24216 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    80724 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2103 pulse      9 -11 88336 8296 3592 S  13.4  1.9   0:21.52 pulseaudio        
 2280 root      30  10 91464 2284 1836 S   4.2  0.5   0:05.24 LightSone         
 2605 pi        20   0  4672 1380 1032 R   2.0  0.3   0:00.33 top               
 2356 root      20   0 22916  14m 4852 S   1.6  3.3   0:04.51 Xorg              
 2515 pi        20   0  104m 9732 7324 S   0.3  2.2   0:02.22 lxpanel           
 2586 pi        20   0  114m  10m 8532 S   0.3  2.4   0:01.70 lxterminal     


pi@raspberrypi ~ $ top

top - 13:23:06 up 5 min,  2 users,  load average: 1.26, 0.78, 0.38
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
%Cpu(s): 51.6 us, 39.9 sy,  0.3 ni,  0.0 id,  0.0 wa,  0.0 hi,  8.2 si,  0.0 st
KiB Mem:    447864 total,   209352 used,   238512 free,    24312 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    81488 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                                                               
 2103 pulse      9 -11 88336  35m 3604 S  58.0  8.1   0:53.72 pulseaudio                                                                            
 2162 pi        20   0  115m 4172 2756 S  34.1  0.9   0:06.71 shairport                                                                             
 2280 root      30  10 91464 2304 1856 S   2.2  0.5   0:12.51 LightSone                                                                             
 2356 root      20   0 25648  17m 5108 S   2.2  4.0   0:17.51 Xorg                                                                                  
 2638 pi        20   0  4672 1380 1032 R   1.3  0.3   0:00.58 top                                                                                   
 2586 pi        20   0  114m  10m 8672 S   0.9  2.5   0:06.94 lxterminal                                                                            
    3 root      20   0     0    0    0 S   0.3  0.0   0:01.06 ksoftirqd/0                                                                           
    4 root      20   0     0    0    0 S   0.3  0.0   0:00.33 kworker/0:0                                                                           
 2236 root      20   0     0    0    0 S   0.3  0.0   0:00.51 RTW_CMD_THREAD                                                                        
 2515 pi        20   0  104m 9796 7388 S   0.3  2.2   0:03.05 lxpanel                                                                               



Best regards.

(In reply to Tanu Kaskinen from comment #1)
> Maybe the new kernel has enabled some new sample rate that doesn't match the
> audio that you're playing, so pulseaudio has to do resampling that it didn't
> previously need to do?
> 
> Could you attach the output of "pactl list" in both cases (old kernel with
> low cpu use, new kernel with high cpu use)?

Hi,
Wherein reported are the reports that you asked me.
Debian wheezy with kernel 3.12.25 :

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.25+ #29 PREEMPT Sun Sep 21 08:38:08 CEST 2014 armv6l GNU/Linux


pi@raspberrypi ~ $ pactl list
Module #0
	Name: module-alsa-card
	Argument: device_id="0" name="platform-snd-hifiberry-amp.0" card_name="alsa_card.platform-snd-hifiberry-amp.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes card_properties="module-udev-detect.discovered=1"
	Usage counter: 3
	Properties:
		module.author = "Lennart Poettering"
		module.description = "ALSA Card"
		module.version = "2.0"

Module #1
	Name: module-udev-detect
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Detect available audio hardware and load matching drivers"
		module.version = "2.0"

Module #2
	Name: module-native-protocol-unix
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (UNIX sockets)"
		module.version = "2.0"

Module #3
	Name: module-stream-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute/device state of streams"
		module.version = "2.0"

Module #4
	Name: module-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute state of devices"
		module.version = "2.0"

Module #5
	Name: module-default-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the default sink and source"
		module.version = "2.0"

Module #6
	Name: module-dbus-protocol
	Argument: access=local
	Usage counter: n/a
	Properties:
		module.author = "Tanu Kaskinen"
		module.description = "D-Bus interface"
		module.version = "2.0"

Module #7
	Name: module-rescue-streams
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "When a sink/source is removed, try to move their streams to the default sink/source"
		module.version = "2.0"

Module #8
	Name: module-always-sink
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Colin Guthrie"
		module.description = "Always keeps at least one sink loaded even if it's a null one"
		module.version = "2.0"

Module #9
	Name: module-position-event-sounds
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Position event sounds between L and R depending on the position on screen of the widget triggering them."
		module.version = "2.0"

Module #10
	Name: module-native-protocol-tcp
	Argument: auth-ip-acl=127.0.0.1;192.168.0.0/24 auth-anonymous=1
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (TCP sockets)"
		module.version = "2.0"

Module #11
	Name: module-zeroconf-publish
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "mDNS/DNS-SD Service Publisher"
		module.version = "2.0"

Sink #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Description: snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0:  70% 1:  70%
	        balance 0.00
	Base Volume: 100%
	Monitor Source: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Latency: 104494 usec, configured 105000 usec
	Flags: HARDWARE HW_VOLUME_CTRL LATENCY 
	Properties:
		alsa.resolution_bits = "16"
		device.api = "alsa"
		device.class = "sound"
		alsa.class = "generic"
		alsa.subclass = "generic-mix"
		alsa.name = ""
		alsa.id = "HifiBerry AMP HiFi tas5713-hifi-0"
		alsa.subdevice = "0"
		alsa.subdevice_name = "subdevice #0"
		alsa.device = "0"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "front:0"
		device.buffering.buffer_size = "352800"
		device.buffering.fragment_size = "176400"
		device.access_mode = "mmap+timer"
		device.profile.name = "analog-stereo"
		device.profile.description = "Analog Stereo"
		device.description = "snd_rpi_hifiberry_amp Analog Stereo"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Ports:
		analog-output: Analog Output (priority: 9900)
	Active Port: analog-output
	Formats:
		pcm

Source #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Description: Monitor of snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Base Volume: 100%
	             0.00 dB
	Monitor of Sink: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Latency: 0 usec, configured 2000000 usec
	Flags: DECIBEL_VOLUME LATENCY 
	Properties:
		device.description = "Monitor of snd_rpi_hifiberry_amp Analog Stereo"
		device.class = "monitor"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Formats:
		pcm

Sink Input #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 0
	Sink: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 0 usec
	Sink Latency: 82373 usec
	Resample method: n/a
	Properties:
		media.name = "Shairport Stream"
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2218"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"

Source Output #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 4
	Source: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 58775 usec
	Source Latency: 0 usec
	Resample method: n/a
	Properties:
		media.name = "cimpulse"
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2341"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "source-output-by-application-name:cimpulse"

Client #0
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2218"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #4
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2341"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #7
	Driver: protocol-native.c
	Owner Module: 10
	Properties:
		application.name = "pactl"
		native-protocol.peer = "TCP/IP client from 127.0.0.1:43601"
		native-protocol.version = "26"
		application.process.id = "2677"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "pactl"
		application.language = "en_GB.UTF-8"
		window.x11.display = ":0.0"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		application.process.session_id = "d3670ff77a0bb988a953e7f053a3f4e7-1411426031.986903-1502075250"

Card #0
	Name: alsa_card.platform-snd-hifiberry-amp.0
	Driver: module-alsa-card.c
	Owner Module: 0
	Properties:
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		device.description = "snd_rpi_hifiberry_amp"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Profiles:
		output:analog-stereo: Analog Stereo Output (sinks: 1, sources: 0, priority. 6000)
		off: Off (sinks: 0, sources: 0, priority. 0)
	Active Profile: output:analog-stereo
	Ports:
		analog-output: Analog Output (priority: 9900)
			Part of profile(s): output:analog-stereo

CPU usage by pulseaudio without streaming audio before and after with streaming audio:

pi@raspberrypi ~ $ top

top - 00:49:54 up 3 min,  2 users,  load average: 0.77, 0.54, 0.23
Tasks:  99 total,   1 running,  98 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.1 us,  3.4 sy,  1.0 ni, 92.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    447988 total,   177748 used,   270240 free,    23140 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    78768 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2140 pulse      9 -11 88304 8956 3584 S   2.3  2.0   0:15.71 pulseaudio        
 2392 root      20   0 23944  15m 4776 S   1.6  3.6   0:06.13 Xorg              
 2650 pi        20   0  4672 1368 1020 R   1.3  0.3   0:00.22 top               
 2341 root      30  10 91464 2264 1816 S   1.0  0.5   0:01.99 LightSone         
 2609 pi        20   0  113m  10m 8424 S   0.7  2.4   0:03.12 lxterminal        
   39 root      20   0     0    0    0 S   0.3  0.0   0:01.29 mmcqd/0           
  230 root      20   0     0    0    0 S   0.3  0.0   0:01.87 usb-storage       
  268 root      20   0     0    0    0 S   0.3  0.0   0:00.41 kworker/0:2       
 2263 root      20   0     0    0    0 S   0.3  0.0   0:00.30 RTW_CMD_THREAD   


pi@raspberrypi ~ $ top

top - 00:48:22 up 2 min,  2 users,  load average: 0.64, 0.35, 0.14
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
%Cpu(s): 17.3 us, 13.1 sy,  0.7 ni, 67.8 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem:    447988 total,   147380 used,   300608 free,    14412 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    69540 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2140 pulse      9 -11 88304 7864 3584 S  15.3  1.8   0:05.05 pulseaudio        
 2218 pi        20   0  115m 3896 2412 S  11.7  0.9   0:02.37 shairport         
 2392 root      20   0 17412  10m 4076 S   2.0  2.3   0:02.13 Xorg              
 2627 pi        20   0  4672 1368 1020 R   1.3  0.3   0:00.30 top               
 2341 root      30  10 91464 2264 1816 S   1.0  0.5   0:00.97 LightSone         
    6 root      20   0     0    0    0 S   0.3  0.0   0:00.27 kworker/u2:0      
  268 root      20   0     0    0    0 S   0.3  0.0   0:00.15 kworker/0:2       
 2263 root      20   0     0    0    0 S   0.3  0.0   0:00.15 RTW_CMD_THREAD    
 2498 pi        20   0  103m 8708 6896 S   0.3  1.9   0:01.42 lxpanel           
 2609 pi        20   0  112m 9568 7444 S   0.3  2.1   0:01.02 lxterminal        

Debian wheezy with kernel 3.12.28 :

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.28+ #713 PREEMPT Fri Sep 19 16:43:32 BST 2014 armv6l GNU/Linux



pi@raspberrypi ~ $ pactl list
Module #0
	Name: module-alsa-card
	Argument: device_id="0" name="platform-snd-hifiberry-amp.0" card_name="alsa_card.platform-snd-hifiberry-amp.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes card_properties="module-udev-detect.discovered=1"
	Usage counter: 3
	Properties:
		module.author = "Lennart Poettering"
		module.description = "ALSA Card"
		module.version = "2.0"

Module #1
	Name: module-udev-detect
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Detect available audio hardware and load matching drivers"
		module.version = "2.0"

Module #2
	Name: module-native-protocol-unix
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (UNIX sockets)"
		module.version = "2.0"

Module #3
	Name: module-stream-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute/device state of streams"
		module.version = "2.0"

Module #4
	Name: module-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the volume/mute state of devices"
		module.version = "2.0"

Module #5
	Name: module-default-device-restore
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Automatically restore the default sink and source"
		module.version = "2.0"

Module #6
	Name: module-dbus-protocol
	Argument: access=local
	Usage counter: n/a
	Properties:
		module.author = "Tanu Kaskinen"
		module.description = "D-Bus interface"
		module.version = "2.0"

Module #7
	Name: module-rescue-streams
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "When a sink/source is removed, try to move their streams to the default sink/source"
		module.version = "2.0"

Module #8
	Name: module-always-sink
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Colin Guthrie"
		module.description = "Always keeps at least one sink loaded even if it's a null one"
		module.version = "2.0"

Module #9
	Name: module-position-event-sounds
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Position event sounds between L and R depending on the position on screen of the widget triggering them."
		module.version = "2.0"

Module #10
	Name: module-native-protocol-tcp
	Argument: auth-ip-acl=127.0.0.1;192.168.0.0/24 auth-anonymous=1
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "Native protocol (TCP sockets)"
		module.version = "2.0"

Module #11
	Name: module-zeroconf-publish
	Argument: 
	Usage counter: n/a
	Properties:
		module.author = "Lennart Poettering"
		module.description = "mDNS/DNS-SD Service Publisher"
		module.version = "2.0"

Sink #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Description: snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0:  70% 1:  70%
	        balance 0.00
	Base Volume: 100%
	Monitor Source: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Latency: 887328 usec, configured 756000 usec
	Flags: HARDWARE HW_VOLUME_CTRL LATENCY 
	Properties:
		alsa.resolution_bits = "16"
		device.api = "alsa"
		device.class = "sound"
		alsa.class = "generic"
		alsa.subclass = "generic-mix"
		alsa.name = ""
		alsa.id = "HifiBerry AMP HiFi tas5713-hifi-0"
		alsa.subdevice = "0"
		alsa.subdevice_name = "subdevice #0"
		alsa.device = "0"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "front:0"
		device.buffering.buffer_size = "352800"
		device.buffering.fragment_size = "176400"
		device.access_mode = "mmap+timer"
		device.profile.name = "analog-stereo"
		device.profile.description = "Analog Stereo"
		device.description = "snd_rpi_hifiberry_amp Analog Stereo"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Ports:
		analog-output: Analog Output (priority: 9900)
	Active Port: analog-output
	Formats:
		pcm

Source #0
	State: RUNNING
	Name: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo.monitor
	Description: Monitor of snd_rpi_hifiberry_amp Analog Stereo
	Driver: module-alsa-card.c
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Owner Module: 0
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Base Volume: 100%
	             0.00 dB
	Monitor of Sink: alsa_output.platform-snd-hifiberry-amp.0.analog-stereo
	Latency: 0 usec, configured 2000000 usec
	Flags: DECIBEL_VOLUME LATENCY 
	Properties:
		device.description = "Monitor of snd_rpi_hifiberry_amp Analog Stereo"
		device.class = "monitor"
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Formats:
		pcm

Sink Input #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 0
	Sink: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 0 usec
	Sink Latency: 810395 usec
	Resample method: n/a
	Properties:
		media.name = "Shairport Stream"
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2162"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"

Source Output #0
	Driver: protocol-native.c
	Owner Module: 2
	Client: 4
	Source: 0
	Sample Specification: s16le 2ch 44100Hz
	Channel Map: front-left,front-right
	Format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
	Mute: no
	Volume: 0: 100% 1: 100%
	        0: 0.00 dB 1: 0.00 dB
	        balance 0.00
	Buffer Latency: 795986 usec
	Source Latency: 0 usec
	Resample method: n/a
	Properties:
		media.name = "cimpulse"
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2280"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		module-stream-restore.id = "source-output-by-application-name:cimpulse"

Client #0
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "AirAni-b35336"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2162"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "shairport"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #4
	Driver: protocol-native.c
	Owner Module: 2
	Properties:
		application.name = "cimpulse"
		native-protocol.peer = "UNIX socket client"
		native-protocol.version = "26"
		application.process.id = "2280"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "LightSone"
		application.language = "C"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"

Client #7
	Driver: protocol-native.c
	Owner Module: 10
	Properties:
		application.name = "pactl"
		native-protocol.peer = "TCP/IP client from 127.0.0.1:37702"
		native-protocol.version = "26"
		application.process.id = "2624"
		application.process.user = "pi"
		application.process.host = "raspberrypi"
		application.process.binary = "pactl"
		application.language = "en_GB.UTF-8"
		window.x11.display = ":0.0"
		application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
		application.process.session_id = "d3670ff77a0bb988a953e7f053a3f4e7-1412248712.131666-566053987"

Card #0
	Name: alsa_card.platform-snd-hifiberry-amp.0
	Driver: module-alsa-card.c
	Owner Module: 0
	Properties:
		alsa.card = "0"
		alsa.card_name = "snd_rpi_hifiberry_amp"
		alsa.long_card_name = "snd_rpi_hifiberry_amp"
		alsa.driver_name = "snd_soc_hifiberry_amp"
		device.bus_path = "platform-snd-hifiberry-amp.0"
		sysfs.path = "/devices/platform/snd-hifiberry-amp.0/sound/card0"
		device.string = "0"
		device.description = "snd_rpi_hifiberry_amp"
		module-udev-detect.discovered = "1"
		device.icon_name = "audio-card"
	Profiles:
		output:analog-stereo: Analog Stereo Output (sinks: 1, sources: 0, priority. 6000)
		off: Off (sinks: 0, sources: 0, priority. 0)
	Active Profile: output:analog-stereo
	Ports:
		analog-output: Analog Output (priority: 9900)
			Part of profile(s): output:analog-stereo


CPU usage by pulseaudio without streaming audio before and after with streaming audio:


pi@raspberrypi ~ $ top

top - 13:20:09 up 2 min,  2 users,  load average: 0.84, 0.65, 0.27
Tasks:  99 total,   1 running,  98 sleeping,   0 stopped,   0 zombie
%Cpu(s): 11.7 us,  7.2 sy,  2.8 ni, 77.9 id,  0.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    447864 total,   177192 used,   270672 free,    24216 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    80724 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2103 pulse      9 -11 88336 8296 3592 S  13.4  1.9   0:21.52 pulseaudio        
 2280 root      30  10 91464 2284 1836 S   4.2  0.5   0:05.24 LightSone         
 2605 pi        20   0  4672 1380 1032 R   2.0  0.3   0:00.33 top               
 2356 root      20   0 22916  14m 4852 S   1.6  3.3   0:04.51 Xorg              
 2515 pi        20   0  104m 9732 7324 S   0.3  2.2   0:02.22 lxpanel           
 2586 pi        20   0  114m  10m 8532 S   0.3  2.4   0:01.70 lxterminal     


pi@raspberrypi ~ $ top

top - 13:23:06 up 5 min,  2 users,  load average: 1.26, 0.78, 0.38
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
%Cpu(s): 51.6 us, 39.9 sy,  0.3 ni,  0.0 id,  0.0 wa,  0.0 hi,  8.2 si,  0.0 st
KiB Mem:    447864 total,   209352 used,   238512 free,    24312 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    81488 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                                                               
 2103 pulse      9 -11 88336  35m 3604 S  58.0  8.1   0:53.72 pulseaudio                                                                            
 2162 pi        20   0  115m 4172 2756 S  34.1  0.9   0:06.71 shairport                                                                             
 2280 root      30  10 91464 2304 1856 S   2.2  0.5   0:12.51 LightSone                                                                             
 2356 root      20   0 25648  17m 5108 S   2.2  4.0   0:17.51 Xorg                                                                                  
 2638 pi        20   0  4672 1380 1032 R   1.3  0.3   0:00.58 top                                                                                   
 2586 pi        20   0  114m  10m 8672 S   0.9  2.5   0:06.94 lxterminal                                                                            
    3 root      20   0     0    0    0 S   0.3  0.0   0:01.06 ksoftirqd/0                                                                           
    4 root      20   0     0    0    0 S   0.3  0.0   0:00.33 kworker/0:0                                                                           
 2236 root      20   0     0    0    0 S   0.3  0.0   0:00.51 RTW_CMD_THREAD                                                                        
 2515 pi        20   0  104m 9796 7388 S   0.3  2.2   0:03.05 lxpanel                                                                               



Best regards.

Created attachment 107248 [details] [review]
pactl list

Wherein reported are the reports of pactl list that you asked me.

Sample rates have not changed between the different kernel releases. If seems, that the high CPU load does not come from resampling.

(In reply to HiFiBerry from comment #5)
> Sample rates have not changed between the different kernel releases. If
> seems, that the high CPU load does not come from resampling.

So where is the problem? Do you need other information or report? Tell me what I must do to overcome the problem?

(In reply to HiFiBerry from comment #5)
> Sample rates have not changed between the different kernel releases. If
> seems, that the high CPU load does not come from resampling.

Do you need more information from the manufacturer HiFiBerry?

One important difference is that the configured sink latency is much lower with 3.12.25 than with 3.12.28. I don't know how the kernel could affect that, though, except by varying the maximum sink buffer size, but in this case it seems that with both kernels the sink buffer size is the same.

The configured sink latency is determined by what applications request. In this case there are shairport and LightSone connected to the sink (LightSone is actually connected to the monitor source of the sink, but if LightSone requests low latency from the source, that request will propagate to the monitored sink also). If shairport or LightSone have different latency configuration between the kernels, that would explain the difference in the configured sink latency. (The configured latency of the monitor source is the same in both cases, though, which suggests that LightSone is not to blame here). To get information about what latencies the applications request, you could attach (as an attachment, not in the comment!) the verbose log of pulseaudio in both cases. See https://wiki.ubuntu.com/PulseAudio/Log for instructions.

It's unexpected that lower latency leads to lower cpu use. Is it possible that the cpu runs at a lower speed with 3.12.28, causing higher figures in top? Here is some information about cpu speed scaling on Raspberry Pi: http://with-raspberrypi.blogspot.com/2014/03/cpu-frequency.html

Created attachment 107431 [details]
Pulseaudio Verbose Log with kernel 3.12.25

In the log file shows the pulseaudio verbose log with Debian Wheezy kernel 3.12.25. In this case the use of the cpu by pulseaudio is correct.

Created attachment 107432 [details]
Pulseaudio Verbose Log with Kernel 3.12.29

In the log file shows the pulseaudio verbose log with Debian Wheezy kernel 3:12:29. In this case the use of the cpu by pulseaudio is very high.

About the frequency of the CPU, I have checked the parameters of current, max and min cpu freq, these are the results:

pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_cur_freq
700000
pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq
700000
pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_min_freq
700000

I have also tried to change the configuration parameters of the CPU /boot/config.txt, in this manner: 

# Meaningful word.. This means 'enable cpu freq scaling'
force_turbo=0
# Set lowest cpu freq. By default, it's 700.
arm_freq_min=700

or

#uncomment to overclock the arm. 700 MHz is the default.
arm_freq=800

# for more options see http://elinux.org/RPi_config.txt

# Meaningful word.. This means 'enable cpu freq scaling'
force_turbo=0
# Set lowest cpu freq. By default, it's 700.
arm_freq_min=800

with these results:

pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_cur_freq
700000
pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq
800000
pi@raspberrypi ~ $ sudo cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_min_freq
700000


but the problem of the excessive use of cpu by pulseaudio remains and persists. I do not think it is due to a low cpu speed setting.





(In reply to Tanu Kaskinen from comment #8)
> One important difference is that the configured sink latency is much lower
> with 3.12.25 than with 3.12.28. I don't know how the kernel could affect
> that, though, except by varying the maximum sink buffer size, but in this
> case it seems that with both kernels the sink buffer size is the same.
> 
> The configured sink latency is determined by what applications request. In
> this case there are shairport and LightSone connected to the sink (LightSone
> is actually connected to the monitor source of the sink, but if LightSone
> requests low latency from the source, that request will propagate to the
> monitored sink also). If shairport or LightSone have different latency
> configuration between the kernels, that would explain the difference in the
> configured sink latency. (The configured latency of the monitor source is
> the same in both cases, though, which suggests that LightSone is not to
> blame here). To get information about what latencies the applications
> request, you could attach (as an attachment, not in the comment!) the
> verbose log of pulseaudio in both cases. See
> https://wiki.ubuntu.com/PulseAudio/Log for instructions.
> 
> It's unexpected that lower latency leads to lower cpu use. Is it possible
> that the cpu runs at a lower speed with 3.12.28, causing higher figures in
> top? Here is some information about cpu speed scaling on Raspberry Pi:
> http://with-raspberrypi.blogspot.com/2014/03/cpu-frequency.html

 1.215|   0.000) I: [pulseaudio] alsa-util.c: cannot disable ALSA period wakeups
(   1.216|   0.000) D: [pulseaudio] alsa-util.c: Maximum hw buffer size is 2972 ms
(   1.217|   0.001) I: [pulseaudio] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   1.219|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 88200 samples).
(   1.220|   0.001) I: [pulseaudio] alsa-util.c: ALSA period wakeups were not disabled
(   1.221|   0.000) I: [pulseaudio] alsa-sink.c: Successfully opened device front:0.
(   1.221|   0.000) I: [pulseaudio] alsa-sink.c: Selected mapping 'Analog Stereo' (analog-stereo).
(   1.222|   0.000) I: [pulseaudio] alsa-sink.c: Successfully enabled mmap() mode.
(   1.222|   0.000) I: [pulseaudio] alsa-sink.c: Successfully enabled timer-based scheduling mode.



can the sound card report dma residue? 

pulseaudio seem ignore 

1.217|   0.001) I: [pulseaudio] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)

seem enable timer scheduling when sound card cannot disable period wakeup?

  1.258|   0.004) I: [alsa-sink] alsa-sink.c: Starting playback.
(   1.259|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   1.260|   0.001) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   1.261|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.


snd_pcm_start was called at 1.258, it is strange that pulseaudio start cutting sleep time at 1.259

@Raymond: No idea about DMA residue. As far as I know, the Raspberry Pi I2S driver directly access the DMA controller. The code for this can be found here:
https://github.com/raspberrypi/linux/blob/rpi-3.12.y/sound/soc/bcm/bcm2708-i2s.c

It seems, that there was some work on the DMA driver itself:
https://github.com/raspberrypi/linux/blob/rpi-3.12.y/arch/arm/mach-bcm2708/dma.c

Best regards
Daniel

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/soc/soc-generic-dmaengine-pcm.c?id=93b943edfc5e439f7b843535e0bb0f7d2371f67f

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/soc/soc-generic-dmaengine-pcm.c?id=478028e088d6a94666d8a776be2cd2291faf3bbd

if your sound card can report dma residue, your sound card pointer callback need to read the value from hardware register

if your sound card cannot report dma residue, pcm pointer callback of your driver return hwptr position which increment by one period in tne interrupt handler

Now I ask HiFiBerry, for me it is an unknown area.



(In reply to Raymond from comment #16)
> if your sound card cannot report dma residue, pcm pointer callback of your
> driver return hwptr position which increment by one period in tne interrupt
> handler

Created attachment 107467 [details]
Same issue playing a wav file. Pulseaudio verbose log

If it can be useful, I have the exact same problem simply playing a song in wav format with paplay. The command is: 

sudo -u pi paplay --volume=50000 /home/pi/Desperado.wav

If I play the song with pulseaudio running as a daemon, the CPU used by pulseaudio squirts to 87%, and there is no sound, but if I run it with: 

LANG=C pulseaudio -vvvv --log-time=1 > ~/pulseverbose.log 2>&1

the song feels latencies, sobs and accelerated. 
I enclose the pulseaudio verbose log, hoping it will be useful.

static const struct snd_pcm_hardware bcm2708_pcm_hardware = {
	.info			= SNDRV_PCM_INFO_INTERLEAVED |
					  SNDRV_PCM_INFO_JOINT_DUPLEX,


http://mailman.alsa-project.org/pipermail/alsa-devel/2007-December/004801.html

seem driver has specific playback /capture behaviour when using SNDRV_PCM_INFO_JOINT_DUPLEX

Hi Raymond,

the low-level Raspbery Pi I2S driver is able to record/playback at the same time. As the I2S interface shares the clocks for input and output, sample rates and bits per sample must be the same for playback and recording. This is my understanding about this flag.

However in this case, the sound card is playback only, it does not even provide an input to ALSA. Therefore there is only a playback stream.

I'm not sure how this is related to the CPU issue. Can you explain?

Best regards
Daniel

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/include/linux/dmaengine.h

* @DMA_RESIDUE_GRANULARITY_SEGMENT: Residue is updated after each successfully
 *  completed segment of the transfer (For cyclic transfers this is after each
 *  period). This is typically implemented by having the hardware generate an
 *  interrupt after each transferred segment and then the drivers updates the
 *  outstanding residue by the size of the segment. Another possibility is if
 *  the hardware supports scatter-gather and the segment descriptor has a field
 *  which gets set after the segment has been completed. The driver then counts
 *  the number of segments without the flag set to compute the residue.
 * @DMA_RESIDUE_GRANULARITY_BURST: Residue is updated after each transferred
 *  burst. This is typically only supported if the hardware has a progress
 *  register of some sort (E.g. a register with the current read/write address
 *  or a register with the amount of bursts/beats/bytes that have been
 *  transferred or still need to be transferred).
 */

enum dma_residue_granularity {
	DMA_RESIDUE_GRANULARITY_DESCRIPTOR = 0,
	DMA_RESIDUE_GRANULARITY_SEGMENT = 1,
	DMA_RESIDUE_GRANULARITY_BURST = 2,



timer scheduling require at least two hardware feature

DMA_RESIDUE_GRANULARITY_BURST

and

SNDRV_PCM_INFO_NO_PERIOD_WAKEUP

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/log/?qt=grep&q=period+wakeup

I think, the Raspberry Pi CPU does not have hardware support for this. Having a look at the DMA code, there is no support for it.

What does this mean with respect to pusleaudio?

http://0pointer.de/blog/projects/pulse-glitch-free.html

image 1 is correct only if sound card can report dma residue, which provide more accurate position than period boundary

if sound card cannot report dma residue, hwptr just increment by period size/time,  your cannot rewind when using two periods per buffer


http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa/alsa-util.c?id=826c8f69d34ef49e86fe0ab6c93c1ffba8916131

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/?id=ab69a4904b5dd4d7cd6996587ba066bca8d13838



 timer scheduling is enabled by default since pulseaudio assume all sound card can report dma residue

What does this mean for this specific problem? The high CPU usage happens only at the newest kernels, it had worked before. Therefore I would not expect that this missing hardware feature is the reason.
Any idea?

I have the exact same problem with the HiFiBerry Dac. Also in this case the use of the CPU by pulseaudio skip to excessive values ​​with the newer kernel (3.12.28/29) compared to the old kernel (3.12.25). Below I will report /etc/modules setup and reports.
I think it's definitely a pulseaudio problem of the underlying I2S subsystem service.


# /etc/modules: kernel modules to load at boot time.
#
# This file contains the names of kernel modules that should be loaded
# at boot time, one per line. Lines beginning with "#" are ignored.
# Parameters can be specified after the module name.

i2c-bcm2708
i2c-dev

snd_soc_bcm2708
bcm2708_dmaengine
snd_soc_pcm5102a
snd_soc_hifiberry_dac



pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.29+ #714 PREEMPT Wed Oct 1 23:11:38 BST 2014 armv6l GNU/Linux


pi@raspberrypi ~ $ top

top - 10:38:46 up 2 min,  2 users,  load average: 1.14, 0.52, 0.20
Tasks:  95 total,   1 running,  94 sleeping,   0 stopped,   0 zombie
%Cpu(s): 15.3 us, 10.8 sy,  3.1 ni, 70.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    447864 total,   150008 used,   297856 free,    15008 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    71172 cached

waiting...

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2219 pulse      9 -11 88336 8656 3552 S  13.7  1.9   0:15.47 pulseaudio        
 2629 pi        20   0  124m  11m 9508 S   4.9  2.6   0:01.76 pcmanfm           
 2393 root      30  10 91464 2304 1856 S   4.6  0.5   0:03.76 LightSone         
 2507 root      20   0 20068  12m 4252 S   2.0  2.8   0:02.37 Xorg              
 2675 pi        20   0  4672 1376 1032 R   1.3  0.3   0:00.43 top               
 2664 pi        20   0  113m 9820 7676 S   0.7  2.2   0:01.20 lxterminal        
    4 root      20   0     0    0    0 S   0.3  0.0   0:00.10 kworker/0:0       
 2153 avahi     20   0  3384 1664 1396 S   0.3  0.4   0:00.16 avahi-daemon      
 2628 pi        20   0  103m 8956 7132 S   0.3  2.0   0:01.43 lxpanel           

streaming...

pi@raspberrypi ~ $ top

top - 10:41:08 up 4 min,  2 users,  load average: 1.61, 0.87, 0.38
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
%Cpu(s): 57.0 us, 37.6 sy,  1.9 ni,  0.0 id,  0.0 wa,  0.0 hi,  3.5 si,  0.0 st
KiB Mem:    447864 total,   198268 used,   249596 free,    16064 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    81420 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                          
 2219 pulse      9 -11 88336  36m 3552 S  57.7  8.3   0:45.57 pulseaudio                                       
 2284 pi        20   0  117m 5000 2744 S  35.2  1.1   0:09.15 shairport                                        
 2507 root      20   0 23504  15m 4984 S   2.2  3.5   0:08.82 Xorg                                             
 2393 root      30  10 91464 2304 1856 S   1.9  0.5   0:09.09 LightSone                                        
 2695 pi        20   0  4672 1380 1032 R   1.6  0.3   0:00.93 top                                              
 2664 pi        20   0  114m  10m 8600 S   1.0  2.5   0:04.02 lxterminal                                       





(In reply to Raymond from comment #23)
> http://0pointer.de/blog/projects/pulse-glitch-free.html
> 
> image 1 is correct only if sound card can report dma residue, which provide
> more accurate position than period boundary
> 
> if sound card cannot report dma residue, hwptr just increment by period
> size/time,  your cannot rewind when using two periods per buffer
> 
> 
> http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa/
> alsa-util.c?id=826c8f69d34ef49e86fe0ab6c93c1ffba8916131
> 
> https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/
> ?id=ab69a4904b5dd4d7cd6996587ba066bca8d13838
> 
> 
> 
>  timer scheduling is enabled by default since pulseaudio assume all sound
> card can report dma residue

(alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)



do the driver has enough constraints to finalize the parameters when pulseaudio only set maximum buffer size? 


do this mean it support Non integer (e.g.3.7 ) periods per buffer since there is no constraint 

snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);

http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa/alsa-util.c?id=3c73e2130fd65e147c487b0b84c1a8b6a8afa04c

Dear Raymond,
the same failed error is present in both pulseaudio verbose log with Kernell 3.12.25 and 3.12.28, in the same situations. Do you think this is to create the bug?

Kernel 3.12.25

1)
(   1.321|   0.001) I: [pulseaudio] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   1.322|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 88200 samples).
2)
(   9.113|   0.001) I: [alsa-sink] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   9.115|   0.001) D: [alsa-sink] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 44100 samples).

Kernel 3.12.28
1)
(   1.217|   0.001) I: [pulseaudio] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   1.219|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 88200 samples).
2)
(   9.358|   0.001) I: [alsa-sink] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   9.359|   0.001) D: [alsa-sink] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 44100 samples).




(In reply to Raymond from comment #26)
> (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
> 
> 
> 
> do the driver has enough constraints to finalize the parameters when
> pulseaudio only set maximum buffer size? 
> 
> 
> do this mean it support Non integer (e.g.3.7 ) periods per buffer since
> there is no constraint 
> 
> snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
> 
> http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa/
> alsa-util.c?id=3c73e2130fd65e147c487b0b84c1a8b6a8afa04c

(   1.219|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 88200 samples).


this is one period per buffer 

.periods_min =1



but your source are

double buffering 

.periods_min =2

pulseaudio need to provide debug info about the number of frames written when it call snd_pcm_start

since work_done must be at least the size of fifo buffer or twice the dma brust size 


/*             pa_log_debug("work_done = %i", work_done); */

            if (work_done) {

                if (u->first) {
-                    pa_log_info("Starting playback.");
+                    pa_log_info("Starting playback %d ", work_done);
                    snd_pcm_start(u->pcm_handle);

                    pa_smoother_resume(u->smoother, pa_rtclock_now(), true);

                    u->first = false;
                }

                update_smoother(u);
            }

http://mailman.alsa-project.org/pipermail/alsa-devel/2014-September/081501.html

you can try Alexander's pcm_avail.c to find out whether you sound card can report DMA_RESIDUE_GRANULARITY_SEGMENT or DMA_RESIDUE_GRANULARITY_BURST ?

(In reply to Alessandro Ferri from comment #18)
> Created attachment 107467 [details]
> Same issue playing a wav file. Pulseaudio verbose log
> 
> If it can be useful, I have the exact same problem simply playing a song in
> wav format with paplay. The command is: 
> 
> sudo -u pi paplay --volume=50000 /home/pi/Desperado.wav
> 
> If I play the song with pulseaudio running as a daemon, the CPU used by
> pulseaudio squirts to 87%, and there is no sound, but if I run it with: 
> 
> LANG=C pulseaudio -vvvv --log-time=1 > ~/pulseverbose.log 2>&1
> 
> the song feels latencies, sobs and accelerated. 
> I enclose the pulseaudio verbose log, hoping it will be useful.


seem still using 44100Hz to set buffer size after rate chjanged to 48000Hz


476|   0.000) I: [pulseaudio] sink-input.c: Rate changed to 48000 Hz
(   9.476|   0.000) D: [pulseaudio] module-stream-restore.c: Not restoring volume for sink input sink-input-by-application-name:paplay, because already set.
(   9.476|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.platform-snd-hifiberry-amp.0.analog-stereo is 0x0000, resuming
(   9.481|   0.004) D: [pulseaudio] reserve-wrap.c: Successfully acquired reservation lock on device 'Audio0'
(   9.482|   0.000) I: [alsa-sink] alsa-sink.c: Trying resume...
(   9.487|   0.004) I: [alsa-sink] alsa-util.c: cannot disable ALSA period wakeups
(   9.488|   0.000) D: [alsa-sink] alsa-util.c: Maximum hw buffer size is 2730 ms
(   9.489|   0.001) I: [alsa-sink] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)
(   9.491|   0.001) D: [alsa-sink] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 44100 samples).

I have downloaded and compiled the file by Alexander E. Patrakov. I attach the report generated by the program. I'll do that when I compiled the file it gave me the following error

"asoundlib.h: No such file or directory" 

I had to run the command: 
export LD_LIBRARY_PATH = / usr / local / lib 
in order to compile the test file.



(In reply to Raymond from comment #30)
> http://mailman.alsa-project.org/pipermail/alsa-devel/2014-September/081501.
> html
> 
> you can try Alexander's pcm_avail.c to find out whether you sound card can
> report DMA_RESIDUE_GRANULARITY_SEGMENT or DMA_RESIDUE_GRANULARITY_BURST ?

Created attachment 107650 [details]
Report generated by Alexander E. Patrakov program test

Report generated by Alexander E. Patrakov test program run with the following commands: 

./attachment 
sudo u pi ./attachment

(In reply to Raymond from comment #29)
> pulseaudio need to provide debug info about the number of frames written
> when it call snd_pcm_start
> 
> since work_done must be at least the size of fifo buffer or twice the dma
> brust size 
> 
> 
> /*             pa_log_debug("work_done = %i", work_done); */
> 
>             if (work_done) {
> 
>                 if (u->first) {
> -                    pa_log_info("Starting playback.");
> +                    pa_log_info("Starting playback %d ", work_done);
>                     snd_pcm_start(u->pcm_handle);
> 
>                     pa_smoother_resume(u->smoother, pa_rtclock_now(), true);
> 
>                     u->first = false;
>                 }
> 
>                 update_smoother(u);
>             }



Dear Raymond, 
I'm sorry, but I can not understand the suggestions that you send me. I download pulseaudio from the Debian Wheezy official repository of RaspberryPi, so I do not have the source code of pulseaudio. At the moment I can modify the startup parameters of the demon from /etc/pulse/daemon.conf or I can change load modules and parameters from /etc/pulse/system.pa. If I have to download the source code and compile it by changing some parts, I need you to tell me and show me all the specifications for how to do it,  which version of the code download, how to compile etc...

Best regards.

is it possible to print the time or elasped time between two successive result?

seem the sound card can provide 4 frames granularity except the first few results

(In reply to Raymond from comment #35)
> is it possible to print the time or elasped time between two successive
> result?
> 
> seem the sound card can provide 4 frames granularity except the first few
> results

Cause I can understand better, as an example:

[...]
  hw_ptr       : 0
Playing silence
time: x0:y0:z0; elapsed time x0-00:y0-00:z0-00; Available: 32, loop iteration: 0
time: x1:y1:z1; elapsed time x1-x0:y1-y0:z1-z0; Available: 44, loop iteration: 1
time: x2:y2:z2; elapsed time x2-x1:y2-y1:z2-z1; Available: 48, loop iteration: 2
time: x3:y3:z3; elapsed time x3-x2:y3-y2:z3-z2; Available: 52, loop iteration: 3
[...]

this is what you need?

http://cgit.freedesktop.org/pulseaudio/pulseaudio/tree/src/tests/alsa-time-test.c

similar to alsa-time-test.c

the purpose is to check the elapsed time and the difference in frames are constant

if the granularity is 4 frames, this mean that the driver cannot support period time 10ms which is 441 frames when rate is 44100Hz

https://github.com/raspberrypi/linux/blob/rpi-3.12.y/sound/soc/codecs/tas5713.c

volume control has  dB scale, this won't force pulseaudio to use software volume

refer to datasheet, there is a 64 * 32 bits FIFO between APB interface and Serialiser (I2S)

this mean data first write must not less than fifo size (start threshold must also greater than the dma brust size) before call snd_pcm_start()

Created attachment 107782 [details]
pcm_avail-time-test c code

Dear Raymond and Daniel,
attached the c code modified with reports on time as required by Raymond. In the following attachment I will attach the report of the program pcm_avail-time-test. I would like your confirm that the code is error-free and that it is as required.

Created attachment 107783 [details]
Report of cpm_avail-time-test

In the attached report of the program pcm_avail-time-test.c

@Raymond: Is there that anything you still need at this point?

@Raymond: do you still need the change documented in comment #29?

although there is bug in the program

1) start threshold is period size, this mean start time is earlier 
2) only need to get the time when printing the result
3) seem missing the last result 4096


the result look like bug in driver
1) if period size is 1024, result should include 1024, 2048, 3072 and 4096
2) the variation of elasped time seem quite large from 110 to 9158 us

the other possibity is your CPU seem not fast enough to run the program since the difference in iterations are 1

s - last_us=112	 now_us - start_us=32414	 0	 Available: 1588	 loop iteration: 179
now_us - last_us=7105	 now_us - start_us=39519	 0	 Available: 1928	 loop iteration: 180
now_us - last_us=244	 now_us - start_us=39763	 0	 Available: 1940	 loop iteration: 181

now_us - last_us=159	 now_us - start_us=41709	 0	 Available: 2032	 loop iteration: 197
now_us - last_us=7846	 now_us - start_us=49555	 0	 Available: 2408	 loop iteration: 198
now_us - last_us=281	 now_us - start_us=49836	 0	 Available: 2424	 loop iteration: 199

now_us - last_us=114	 now_us - start_us=62036	 0	 Available: 3008	 loop iteration: 282
now_us - last_us=7508	 now_us - start_us=69544	 0	 Available: 3368	 loop iteration: 283


are those high elasped time related to the log file write ?

just store the results and print the result at the end

Created attachment 107857 [details]
Report of pcm_avail-time-test.c with Kernel 3.12.25+ #29

Following the report of the program pcm_avail-time-test.c, run with Kernell 3.12.25 (where everything works fine).
I want to remind everyone that pulseaudio+shairport+myprogram work well with kernel 3.12.25+ # 29, while from the kernel 3.12.28+ generates the issue of high CPU usage by pulseuadio.

This looks like the behavior of the test program is the same on both kernels. The Raspberry Pi CPU is not very powerful. Maybe this is the reason for the problem of the test program?

I do not think it is a problem of CPU power. The CPU, in theory, must process the same information with both the kernel (3.12.25+ 3.12.29+). What then is burdening the CPU with the kernel 3.12.29+? Which other process was introduced after the version 3.12.25+ of the kernel?

(In reply to HiFiBerry from comment #49)
> This looks like the behavior of the test program is the same on both
> kernels. The Raspberry Pi CPU is not very powerful. Maybe this is the reason
> for the problem of the test program?

have you ask alexander to analyse your result ?

his program use hugh amount of cpu if your sound card report 4 frames granularity than 8 frames 

it call snd_pcm_abailable () 1024 times instead of 512 times

have you ask alexander to analyse your result ?

his program use hugh amount of cpu if your sound card report 4 frames granularity than 8 frames 

it call snd_pcm_abailable () 1024 times instead of 512 times

can aplay run without underrun when using hw device ?

for buffer size 4096, 2048, 1024, 512, 256, 128, 64,... 

aplay -v -D hw:0,0 --buffer-size=4096 stereo.wav

Created attachment 107896 [details]
Report of aplay -v -D hw:0,0 --buffer-size=4096 stereo.wav with Kernel 3.12.25+ #29

outcome prompted with: 
aplay -v -D hw:0,0 --buffer-size=4096 Desperado.wav
for buffer size 4096, 2048, 1024, 512, 256, 128, 64,...

with the kernel: Kernel 3.12.25+

Created attachment 107897 [details]
Report of aplay -v -D hw:0,0 --buffer-size=4096 stereo.wav with Kernel 3.12.29+

outcome prompted with: 
aplay -v -D hw:0,0 --buffer-size=4096 Desperado.wav
for buffer size 4096, 2048, 1024, 512, 256, 128, 64,...

with the kernel:Kernel 3.12.29

Hi Reymond, 
I have attached two reports. The first run with the Kernel 3.12.25+ and the second with the Kernel 3.12.29+. I can summarize to you that the behavior is the same with both kernel without exception: up to a buffer_size of 1024, there are no underrun, with lower buffer_size start underrun more and more frequent.
I want to specify that the song played has the following codecs:
Desperado.wav codec=uncompressed-integer Bitrate(kb/s)=512

(In reply to Alessandro Ferri from comment #55)
> Created attachment 107897 [details]
> Report of aplay -v -D hw:0,0 --buffer-size=4096 stereo.wav with Kernel
> 3.12.29+
> 
> outcome prompted with: 
> aplay -v -D hw:0,0 --buffer-size=4096 Desperado.wav
> for buffer size 4096, 2048, 1024, 512, 256, 128, 64,...
> 
> with the kernel:Kernel 3.12.29

seem your program have bugs

1) no clock time 
2) elapsed time between two successive result seem not correct 



now_us - last_us=196	 now_us - start_us=288	 0	 Available: 48	 loop iteration: 1
now_us - last_us=120	 now_us - start_us=408	 0	 Available: 56	 loop iteration: 2
now_us - last_us=114	 now_us - start_us=522	 0	 Available: 64	 loop iteration: 3
now_us - last_us=18	 now_us - start_us=653	 0	 Available: 72	 loop iteration: 5
now_us - last_us=11	 now_us - start_us=799	 0	 Available: 80	 loop iteration: 9
now_us - last_us=13	 now_us - start_us=974	 0	 Available: 88	 loop iteration: 15
now_us - last_us=14	 now_us - start_us=1135	 0	 Available: 96	 loop iteration: 20

I have also attached the code of the program: 

pcm_avail-time-test.c created by Alessandro Ferri on 2014-10-13 15:07 UTC

https://bugs.freedesktop.org/attachment.cgi?id=107782

you can look at the code and see where is the bug? I can get other prints to verify the code.



(In reply to Raymond from comment #57)
> seem your program have bugs
> 
> 1) no clock time 
> 2) elapsed time between two successive result seem not correct 
> 
> 
> 
> now_us - last_us=196	 now_us - start_us=288	 0	 Available: 48	 loop
> iteration: 1
> now_us - last_us=120	 now_us - start_us=408	 0	 Available: 56	 loop
> iteration: 2
> now_us - last_us=114	 now_us - start_us=522	 0	 Available: 64	 loop
> iteration: 3
> now_us - last_us=18	 now_us - start_us=653	 0	 Available: 72	 loop
> iteration: 5
> now_us - last_us=11	 now_us - start_us=799	 0	 Available: 80	 loop
> iteration: 9
> now_us - last_us=13	 now_us - start_us=974	 0	 Available: 88	 loop
> iteration: 15
> now_us - last_us=14	 now_us - start_us=1135	 0	 Available: 96	 loop
> iteration: 20

your value are the time difference between iteration instead of time difference between different abail


-      now_us = timespec_us(&now);
-    	timestamp_us = timespec_us(&timestamp);

		if (avail1 < 0)
			break;
		if (avail != avail1) {

+           now_us = timespec_us(&now);
+       	timestamp_us = timespec_us(&timestamp);


			fprintf(stderr, "now_us - last_us=%llu\t now_us - start_us=%llu\t %llu\t Available: %d\t loop iteration: %d\n",
				(unsigned long long) (now_us - last_us),
				(unsigned long long) (now_us - start_us),
				(unsigned long long) (timestamp_us ? timestamp_us - start_us : 0),
				(int)avail1, j);

Created attachment 107918 [details]
pcm_avail-time-test_RevII c code

Hi Raymonf 
I am attaching the code in c of what you asked me about the changes. Please you can check if it matches?
In the next attachment I show you the program prints.

Created attachment 107919 [details]
Report of pcm_avail-time-test_RevII

Hi Raymond,
I am attaching the prints of the code that I attached earlier. Let me know if there are bugs.

http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src?id=4df443bbe682055a41e7c2248877dcc7682a69b8

timer scheduling mode require driver provide accurate hwptr position

if your driver did not provide dB scale, this force pulseaudio to use software volume

any volume change by user force pulseaudio to perform rewind

the safeguard is 256bytes (i.e. 64 frames)

your result indicate the hwptr may remain unchanged for more than 400 frames



now_us-last_us=164	 now_us-start_us=70447	 time_us-start_us=70426	 time_us-last_time=164	 time_us-start_time=70389	 Available: 3416	 loop iteration: 301
now_us-last_us=8858	 now_us-start_us=79305	 time_us-start_us=79275	 time_us-last_time=8849	 time_us-start_time=79238	 Available: 3840	 loop iteration: 302
now_us-last_us=258	 now_us-start_us=79563	 time_us-start_us=79539	 time_us-last_time=264	 time_us-start_time=79502	 Available: 3852	 loop iteration: 303

@Raymond: the problem does not occur on volume changes, but always. 

@Alessandro: Can you run the test code again on the kernel that is working?

Created attachment 107976 [details]
Report of pcm_avail-time-test_RevII with Kernel 3.12.25+

The following is the report obtained by printing the program pcm_avail-time-test_RevII performed with the Kernel 3.12.25+ (remember where everything works fine).

@Daniel: I've attached the file that you have requested.

(In reply to HiFiBerry from comment #63)
> @Raymond: the problem does not occur on volume changes, but always. 
> 
> @Alessandro: Can you run the test code again on the kernel that is working?

if you think the bug is related to kernel

you need to check whether hwptr is correct on period update 

and report bug at

https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers

CONFIG_SND_PCM_XRUN_DEBUG, CONFIG_SND_VERBOSE_PROCFS, CONFIG_SND_DEBUG options must be enabled in your kernel

www.alsa-project.org/main/index.php/XRUN_Debug

 # Enable basic debugging and dump stack, check hardware pointer on the period update
 # Usefull to just see, if PCM stream is stopped for a reason (usually wrong audio process timing from scheduler)
 # And to check the values from driver
 echo 11 > /proc/asound/card0/pcm0p/xrun_debug

I do not know if the bug is related to the kernel or pulseaudio or another. In relation to this, I expect a reply from HiFiBerry. I was counting on you to know where is the issue. 
For you, where is the bug? and how can I fix it.

(In reply to Raymond from comment #66)
> if you think the bug is related to kernel
> 
> you need to check whether hwptr is correct on period update 
> 
> and report bug at
> 
> https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers
> 
> CONFIG_SND_PCM_XRUN_DEBUG, CONFIG_SND_VERBOSE_PROCFS, CONFIG_SND_DEBUG
> options must be enabled in your kernel
> 
> www.alsa-project.org/main/index.php/XRUN_Debug
> 
>  # Enable basic debugging and dump stack, check hardware pointer on the
> period update
>  # Usefull to just see, if PCM stream is stopped for a reason (usually wrong
> audio process timing from scheduler)
>  # And to check the values from driver
>  echo 11 > /proc/asound/card0/pcm0p/xrun_debug

the first thing is check any error message in system log since 22 is Invalid argument

(   1.217|   0.001) I: [pulseaudio] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_HW_PARAMS failed (-22)



https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/sound/soc/soc-pcm.c

as aplay can only run without underrun when buffer time above 23ms

this mean the way of increasing minimal latency  from 1ms is too agressive



(  11.678|   0.257) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 1.00 ms
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.935|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 2.00 ms
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.192|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 4.00 ms
(  12.193|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  12.193|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  12.193|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.193|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  12.194|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  12.194|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.449|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 8.00 ms
(  12.450|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  12.450|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  12.450|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.450|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  12.451|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  12.451|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.706|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 16.00 ms


if you think the bug is related to pulseaudo




http://colin.guthr.ie/2010/09/compiling-and-running-pulseaudio-from-git/

you get high cpu usage because pulseaudio keep the sleeping time remain at 20ms


638|   0.254) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 355.99 ms
(  28.895|   0.256) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 376.00 ms
(  28.895|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 376.00ms
(  28.895|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=286476
(  28.895|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=72502
(  28.896|   0.000) D: [alsa-sink] protocol-native.c: max_request changed, trying to update from 71616 to 73380.
(  28.896|   0.000) D: [alsa-sink] protocol-native.c: Notifying client about increased tlength
(  28.897|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 376.00ms
(  28.897|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=286476
(  28.897|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=72502
(  29.152|   0.254) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 365.99 ms
(  29.409|   0.257) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 386.00 ms

latency seem fixed at 105ms 3.12.25 with 30ms wakeup



126|   0.000) I: [pulseaudio] sink-input.c:     media.name = "Shairport Stream"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.name = "AirAni-b35336"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.version = "26"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.id = "4160"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.user = "pi"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.host = "raspberrypi"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.binary = "shairport"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.language = "C"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     window.x11.display = ":0.0"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
(   9.126|   0.000) I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"
(   9.139|   0.012) I: [pulseaudio] protocol-native.c: Requested tlength=250.00 ms, minreq=20.00 ms
(   9.139|   0.000) D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
(   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   9.149|   0.008) D: [pulseaudio] protocol-native.c: Requested latency=105.00 ms, Received latency=105.00 ms
(   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528 maxrewind=0
(   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528 maxrewind=0
(   9.150|   0.000) I: [pulseaudio] protocol-native.c: Final latency 250.01 ms = 105.01 ms + 2*20.00 ms + 105.00 ms
(   9.150|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   9.151|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(   9.151|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(   9.151|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=87319
(   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requesting rewind due to latency change.
(   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 352800 bytes.
(   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Limited to 347040 bytes.
(   9.153|   0.000) D: [alsa-sink] alsa-sink.c: before: 86760
(   9.153|   0.000) D: [alsa-sink] alsa-sink.c: after: 86760
(   9.153|   0.000) D: [alsa-sink] alsa-sink.c: Rewound 347040 bytes.
(   9.153|   0.000) D: [alsa-sink] sink.c: Processing rewind...
(   9.154|   0.000) D: [alsa-sink] sink-input.c: Have to rewind 347040 bytes on render memblockq.
(   9.154|   0.000) D: [alsa-sink] source.c: Processing rewind...
(   9.155|   0.001) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(   9.156|   0.000) D: [pulseaudio] reserve-wrap.c: Device lock status of reserve-monitor-wrapper@Audio0 changed: not busy
(   9.159|   0.002) D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream added for object /org/pulseaudio/core1/playback_stream0
(  11.862|   2.703) I: [alsa-sink] alsa-sink.c: Underrun!
(  11.863|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 30.00 ms

I think this is a substantial difference in the behavior of pulseaudio 
compared to the two Kernel. 
With kernel 3:12:29 increasing steadily up to 745.99 ms: 

(55 620 | 0000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 745.99 ms 

With kernel is 3:12:25 fix one time to 30 ms: 

(11.863 | 0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 30.00 ms 

The same thing with minimal latency: 
With kernel 3:12:25 no increasing latency, with kernel 3.12.29 Increasing latency up to: 



(48 424 | 0256) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 756.00 ms




(In reply to Raymond from comment #71)
> 
> latency seem fixed at 105ms 3.12.25 with 30ms wakeup
> 
> 
> 
> 126|   0.000) I: [pulseaudio] sink-input.c:     media.name = "Shairport
> Stream"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.name =
> "AirAni-b35336"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.peer =
> "UNIX socket client"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> native-protocol.version = "26"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.id
> = "4160"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.user = "pi"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.host = "raspberrypi"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.binary = "shairport"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.language =
> "C"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     window.x11.display =
> ":0.0"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"
> (   9.139|   0.012) I: [pulseaudio] protocol-native.c: Requested
> tlength=250.00 ms, minreq=20.00 ms
> (   9.139|   0.000) D: [pulseaudio] protocol-native.c: Adjust latency mode
> enabled, configuring sink latency to half of overall latency.
> (   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.149|   0.008) D: [pulseaudio] protocol-native.c: Requested
> latency=105.00 ms, Received latency=105.00 ms
> (   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq requested:
> maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528
> maxrewind=0
> (   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized:
> maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528
> maxrewind=0
> (   9.150|   0.000) I: [pulseaudio] protocol-native.c: Final latency 250.01
> ms = 105.01 ms + 2*20.00 ms + 105.00 ms
> (   9.150|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=87319
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requesting rewind due to
> latency change.
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 352800
> bytes.
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Limited to 347040 bytes.
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: before: 86760
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: after: 86760
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: Rewound 347040 bytes.
> (   9.153|   0.000) D: [alsa-sink] sink.c: Processing rewind...
> (   9.154|   0.000) D: [alsa-sink] sink-input.c: Have to rewind 347040 bytes
> on render memblockq.
> (   9.154|   0.000) D: [alsa-sink] source.c: Processing rewind...
> (   9.155|   0.001) D: [pulseaudio] core-subscribe.c: Dropped redundant
> event due to change event.
> (   9.156|   0.000) D: [pulseaudio] reserve-wrap.c: Device lock status of
> reserve-monitor-wrapper@Audio0 changed: not busy
> (   9.159|   0.002) D: [pulseaudio] protocol-dbus.c: Interface
> org.PulseAudio.Core1.Stream added for object
> /org/pulseaudio/core1/playback_stream0
> (  11.862|   2.703) I: [alsa-sink] alsa-sink.c: Underrun!
> (  11.863|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark
> to 30.00 ms

@Alessandro: This is very interesting and it should help to figure out which change in the kernel caused this.
@Raymond: Is there a test that can be done to figure out why this happens only with the new kernel?

Hi Raymond,
Following your comment I have tried to run the following test. 
On /etc/pulse/system.pa I added the following line: 

load-module module-alsa-card device_id=0 tsched=true tsched_buffer_size=256072 tsched_buffer_watermark=120268
 
With this new setup, the CPU usage from pulseaudio is reduced by (without new line): 

pi@raspberrypi ~ $ top

top - 14:54:41 up 2 min,  2 users,  load average: 1.55, 0.62, 0.23
Tasks:  92 total,   1 running,  91 sleeping,   0 stopped,   0 zombie
%Cpu(s): 52.1 us, 26.1 sy,  0.0 ni, 18.9 id,  0.0 wa,  0.0 hi,  2.9 si,  0.0 st
KiB Mem:    447856 total,   137808 used,   310048 free,    14860 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    67372 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2337 pulse      9 -11 87984 4832 3532 S  58.7  1.1   0:21.36 pulseaudio        
 2416 pi        20   0  117m 5176 2424 S  16.7  1.2   0:05.73 shairport         
 2527 root      20   0 22004  10m 4664 S   1.6  2.5   0:02.85 Xorg              
 2742 pi        20   0  4668 1384 1040 R   1.3  0.3   0:00.80 top               

to with the new line:

pi@raspberrypi ~ $ top

top - 14:42:30 up 2 min,  2 users,  load average: 1.27, 0.56, 0.22
Tasks:  93 total,   2 running,  91 sleeping,   0 stopped,   0 zombie
%Cpu(s): 40.4 us, 24.6 sy,  0.0 ni, 32.0 id,  0.0 wa,  0.0 hi,  3.0 si,  0.0 st
KiB Mem:    447856 total,   136800 used,   311056 free,    14868 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    67812 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2369 pi        20   0  150m 4760 3632 R  42.7  1.1   0:15.26 pulseaudio        
 2365 pi        20   0  115m 3940 2544 S  19.0  0.9   0:06.01 shairport         
 2666 root      20   0 22004  10m 4664 S   1.6  2.5   0:02.85 Xorg              
 2757 pi        20   0  4672 1384 1040 R   1.6  0.3   0:00.90 top               

That is substantially decreased from 58% to 42% of CPU.
This could be a good clue?
I have tried to change the parameters in this way:

tsched_buffer_size=1024288
tsched_buffer_watermark=481072

tsched_buffer_size=512144
tsched_buffer_watermark=240536

but there are not differences.
I attach again the report of pulseaudio Log verbose. What configuration should I use and which modules to establish 30 ms wakeup watermark and the minimal latency?

Best regards.

(In reply to Raymond from comment #71)
> 
> latency seem fixed at 105ms 3.12.25 with 30ms wakeup
> 
> 
> 
> 126|   0.000) I: [pulseaudio] sink-input.c:     media.name = "Shairport
> Stream"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.name =
> "AirAni-b35336"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.peer =
> "UNIX socket client"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> native-protocol.version = "26"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.process.id
> = "4160"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.user = "pi"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.host = "raspberrypi"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.binary = "shairport"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     application.language =
> "C"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:     window.x11.display =
> ":0.0"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> application.process.machine_id = "d3670ff77a0bb988a953e7f053a3f4e7"
> (   9.126|   0.000) I: [pulseaudio] sink-input.c:    
> module-stream-restore.id = "sink-input-by-application-name:AirAni-b35336"
> (   9.139|   0.012) I: [pulseaudio] protocol-native.c: Requested
> tlength=250.00 ms, minreq=20.00 ms
> (   9.139|   0.000) D: [pulseaudio] protocol-native.c: Adjust latency mode
> enabled, configuring sink latency to half of overall latency.
> (   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.140|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.149|   0.008) D: [pulseaudio] protocol-native.c: Requested
> latency=105.00 ms, Received latency=105.00 ms
> (   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq requested:
> maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528
> maxrewind=0
> (   9.149|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized:
> maxlength=4194304, tlength=25580, base=4, prebuf=22056, minreq=3528
> maxrewind=0
> (   9.150|   0.000) I: [pulseaudio] protocol-native.c: Final latency 250.01
> ms = 105.01 ms + 2*20.00 ms + 105.00 ms
> (   9.150|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the
> initial iterations by half.
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
> (   9.151|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=87319
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requesting rewind due to
> latency change.
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 352800
> bytes.
> (   9.152|   0.000) D: [alsa-sink] alsa-sink.c: Limited to 347040 bytes.
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: before: 86760
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: after: 86760
> (   9.153|   0.000) D: [alsa-sink] alsa-sink.c: Rewound 347040 bytes.
> (   9.153|   0.000) D: [alsa-sink] sink.c: Processing rewind...
> (   9.154|   0.000) D: [alsa-sink] sink-input.c: Have to rewind 347040 bytes
> on render memblockq.
> (   9.154|   0.000) D: [alsa-sink] source.c: Processing rewind...
> (   9.155|   0.001) D: [pulseaudio] core-subscribe.c: Dropped redundant
> event due to change event.
> (   9.156|   0.000) D: [pulseaudio] reserve-wrap.c: Device lock status of
> reserve-monitor-wrapper@Audio0 changed: not busy
> (   9.159|   0.002) D: [pulseaudio] protocol-dbus.c: Interface
> org.PulseAudio.Core1.Stream added for object
> /org/pulseaudio/core1/playback_stream0
> (  11.862|   2.703) I: [alsa-sink] alsa-sink.c: Underrun!
> (  11.863|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark
> to 30.00 ms

Created attachment 108118 [details]
New test Report of pulse audio verbose Log

New report of pulseaudio verbose Log with load module:

module-alsa-card device_id=0 tsched=true tsched_buffer_size=256072 tsched_buffer_watermark=120268

do you mean you cannot find any alsa error messages in system log ?


http://www.freedesktop.org/wiki/Software/PulseAudio/Notes/3.0/

any reason to use timer scheduling

if your sound card does not support disable period wakeup since the io thread will be wakup when hwptr at period bounary 

cpu won't sleep 1980 ms and wakeup 20ms before the buffer is empty

Hi Raymond, 
can you tell me, please, how to print the system log, so I'll attach and I will send.

Regards.

(In reply to Raymond from comment #76)
> do you mean you cannot find any alsa error messages in system log ?
> 
> 
> http://www.freedesktop.org/wiki/Software/PulseAudio/Notes/3.0/
> 
> any reason to use timer scheduling
> 
> if your sound card does not support disable period wakeup since the io
> thread will be wakup when hwptr at period bounary 
> 
> cpu won't sleep 1980 ms and wakeup 20ms before the buffer is empty

Hi Raymond, 
I have attached a series of system log. I do not know if that's what you ask of me, possibly let me know if you have other requests

Regards.


(In reply to Raymond from comment #76)
> do you mean you cannot find any alsa error messages in system log ?
> 
> 
> http://www.freedesktop.org/wiki/Software/PulseAudio/Notes/3.0/
> 
> any reason to use timer scheduling
> 
> if your sound card does not support disable period wakeup since the io
> thread will be wakup when hwptr at period bounary 
> 
> cpu won't sleep 1980 ms and wakeup 20ms before the buffer is empty

Created attachment 108159 [details]
dmesg log file

Hi Raymond, 
attached the file /var/log/dmesg

Created attachment 108160 [details]
kern.log file

Hi Raymond, 
attached the file /var/log/kern.log

Created attachment 108161 [details]
syslog file

Hi Raymond, 
attached the file /var/log/syslog

Created attachment 108162 [details]
user.log

Hi Raymond, 
attached the file /var/log/user.log

> any reason to use timer scheduling
> 
> if your sound card does not support disable period wakeup since the io
> thread will be wakup when hwptr at period bounary 
> 
> cpu won't sleep 1980 ms and wakeup 20ms before the buffer is empty

Can this be disabled? If yes, how?

 1.132|   0.000) D: [pulseaudio] alsa-util.c: Hardware PCM card 0 'snd_rpi_hifiberry_amp' device 0 subdevice 0
(   1.132|   0.000) D: [pulseaudio] alsa-util.c: Its setup is:
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   stream       : PLAYBACK
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   access       : RW_INTERLEAVED
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   format       : S16_LE
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   subformat    : STD
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   channels     : 2
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   rate         : 44100
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   exact rate   : 44100 (44100/1)
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   msbits       : 16
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   buffer_size  : 4408
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   period_size  : 1102
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   period_time  : 24988
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   tstamp_mode  : ENABLE
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   period_step  : 1
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   avail_min    : 1102
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   period_event : 1
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   start_threshold  : -1
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   stop_threshold   : 1155530752
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   silence_threshold: 0
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   silence_size : 0
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   boundary     : 1155530752
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   appl_ptr     : 0
(   1.132|   0.000) D: [pulseaudio] alsa-util.c:   hw_ptr       : 0
(   1.137|   0.005) D: [pulseaudio] alsa-sink.c: Read hardware volume: 0:  67% 1:  67%
(   1.138|   0.000) D: [alsa-sink] alsa-sink.c: Thread starting up
(   1.138|   0.000) D: [alsa-sink] core-util.c: SCHED_RR|SCHED_RESET_ON_FORK worked.
(   1.138|   0.000) I: [alsa-sink] core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5.
(   1.139|   0.000) I: [alsa-sink] alsa-sink.c: Starting playback.
(   1.139|   0.000) I: [alsa-sink] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_START failed (-77)


you got another error when you change some values of hw_param


you have to ask the author/maintainer of the sound card driver

does aplay work with non power 2 period size ?

aplay -v -D hw:0,0 --buffer-size=4408 stereo.wav


 1.102|   0.000) D: [pulseaudio] alsa-util.c: Trying hw:0 with SND_PCM_NO_AUTO_FORMAT ...
(   1.106|   0.003) D: [pulseaudio] alsa-util.c: Managed to open hw:0
(   1.107|   0.001) D: [pulseaudio] alsa-util.c: Maximum hw buffer size is 2972 ms
(   1.108|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to 4408 samples), period size second (to 1102 samples).
(   1.109|   0.001) I: [pulseaudio] alsa-sink.c: Successfully opened device hw:0.
(   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Selected mapping 'Analog Stereo' (analog-stereo).
(   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Device doesn't support mmap(), falling back to UNIX read/write mode.
(   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Cannot enable timer-based scheduling, falling back to sound IRQ scheduling.
(   1.112|   0.001) I: [pulseaudio] alsa-util.c: Successfully attached to mixer 'hw:0'


it is strange that mmap is not supported


it is no easy to find a fragment time which can be converted to power two period size

Hi Raymond,
I do not know this topic that I am about to expose is a clue that it is worthwhile, but I checked the modules loaded by the two kernel with lsmod, these are the results: 

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.25+ #29 PREEMPT Sun Sep 21 08:38:08 CEST 2014 armv6l GNU/Linux

pi@raspberrypi ~ $ lsmod
OK	Module                  Size  Used by
V	snd_soc_hifiberry_amp   2003  0 
——>	bcm2708_dmaengine       5224  1 
—->	virt_dma                2301  1 bcm2708_dmaengine
—->	i2c_dev                 5257  0 
V	sg                     19336  0 
V	snd_soc_pcm512x         8959  0 
V	snd_soc_tas5713         5581  1 
V	snd_soc_wm8804          7865  0 
V	snd_soc_bcm2708_i2s     6031  2 
V	regmap_mmio             2818  1 snd_soc_bcm2708_i2s
V	8192cu                552678  0 
V	snd_soc_core          128158  5 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_hifiberry_amp,snd_soc_tas5713,snd_soc_bcm2708_i2s
V	snd_compress            8240  1 snd_soc_core
V	regmap_i2c              1657  4 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_core,snd_soc_tas5713
V	snd_pcm_dmaengine       5481  1 snd_soc_core
V	regmap_spi              1913  3 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_core
V	snd_pcm                81534  3 snd_soc_core,snd_pcm_dmaengine
V	snd_page_alloc          5168  1 snd_pcm
V	snd_seq                54501  0 
V	snd_seq_device          6485  1 snd_seq
V	snd_timer              20353  2 snd_pcm,snd_seq
V	leds_gpio               2055  0 
V	led_class               4119  1 leds_gpio
V	snd                    61860  9 snd_soc_core,snd_timer,snd_pcm,snd_seq,snd_seq_device,snd_compress
X	spi_bcm2708             4808  0 
V	i2c_bcm2708             4715  0 
V	joydev                  9108  0 
V	evdev                  10484  8 

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.30+ #717 PREEMPT Fri Oct 17 18:46:31 BST 2014 armv6l GNU/Linux

pi@raspberrypi ~ $ lsmod
OK	Module                  Size  Used by
V	sg                     19877  0 
V	snd_soc_hifiberry_amp   2003  0 
V	snd_soc_wm8804          7932  0 
V	snd_soc_tas5713         5573  1 
V	snd_soc_pcm512x         9034  0 
V	snd_soc_bcm2708_i2s     6210  2 
V	regmap_mmio             2818  1 snd_soc_bcm2708_i2s
V	8192cu                550797  0 
V	snd_soc_core          127849  5 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_hifiberry_amp,snd_soc_tas5713,snd_soc_bcm2708_i2s
V	snd_compress            8259  1 snd_soc_core
V	regmap_i2c              1661  4 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_core,snd_soc_tas5713
V	snd_pcm_dmaengine       5505  1 snd_soc_core
V	regmap_spi              1913  3 snd_soc_pcm512x,snd_soc_wm8804,snd_soc_core
V	snd_pcm                83845  3 snd_soc_core,snd_pcm_dmaengine
V	snd_page_alloc          5132  1 snd_pcm
V	snd_seq                55484  0 
V	snd_seq_device          6469  1 snd_seq
V	snd_timer              20998  3 snd_pcm,snd_seq
V	leds_gpio               2079  0 
V	led_class               4118  1 leds_gpio
V	snd                    62252  10 snd_soc_core,snd_timer,snd_pcm,snd_seq,snd_seq_device,snd_compress
V	evdev                  10661  8 
V	joydev                  9257  0 
V	i2c_bcm2708             4943  0 

There are a difference into the kernel 3.12.30+ in following modules,

——>	bcm2708_dmaengine       5224  1 
—->	virt_dma                2301  1 bcm2708_dmaengine
—->	i2c_dev                 5257  0 

Which are instead present in Kernell 3.12.25+
This probably means that the bcm2708_dmaengine driver has been moved from a module to a integrated part of the kernel between 3.12.25 and 3.12.30. It seems, that the whole DMA subsystem has been changed in the last months.

Do not you think that pulseaudio should be updated to follow updates Kernell?


Regards.




(In reply to Raymond from comment #85)
> does aplay work with non power 2 period size ?
> 
> aplay -v -D hw:0,0 --buffer-size=4408 stereo.wav
> 
> 
>  1.102|   0.000) D: [pulseaudio] alsa-util.c: Trying hw:0 with
> SND_PCM_NO_AUTO_FORMAT ...
> (   1.106|   0.003) D: [pulseaudio] alsa-util.c: Managed to open hw:0
> (   1.107|   0.001) D: [pulseaudio] alsa-util.c: Maximum hw buffer size is
> 2972 ms
> (   1.108|   0.001) D: [pulseaudio] alsa-util.c: Set buffer size first (to
> 4408 samples), period size second (to 1102 samples).
> (   1.109|   0.001) I: [pulseaudio] alsa-sink.c: Successfully opened device
> hw:0.
> (   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Selected mapping 'Analog
> Stereo' (analog-stereo).
> (   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Device doesn't support
> mmap(), falling back to UNIX read/write mode.
> (   1.110|   0.000) I: [pulseaudio] alsa-sink.c: Cannot enable timer-based
> scheduling, falling back to sound IRQ scheduling.
> (   1.112|   0.001) I: [pulseaudio] alsa-util.c: Successfully attached to
> mixer 'hw:0'
> 
> 
> it is strange that mmap is not supported
> 
> 
> it is no easy to find a fragment time which can be converted to power two
> period size

do you mean aplay work with any period size ?

441, 

not multiple of 8 frames , 

or only two  power n

http://lists.freedesktop.org/archives/pulseaudio-discuss/2014-October/022019.html

seem  you may need to set fragment time to 80ms

I have looked into the program output. All I can say is that synchronizing the hardware pointer position to userspace became more expensive in the new kernel, but it still works and is not expensive enough to cause such high CPU usage in PulseAudio.

623|   0.237) D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
(   9.623|   0.000) I: [alsa-sink] alsa-sink.c: Underrun!
(   9.623|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 30.00 ms
(   9.879|   0.256) D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
(   9.880|   0.000) I: [alsa-sink] alsa-sink.c: Underrun!

how do pulseaudio revover these underruns?

seem appl_ptr is really behind hwptr and need snd_pcm_dump to verify

http://cgit.freedesktop.org/pulseaudio/pulseaudio/tree/src/modules/alsa/alsa-sink.c

there was PA_DEBUG_TRAP 


(   9.880|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 40.00 ms
(  10.136|   0.256) D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
(  10.137|   0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 50.00 ms
(  10.393|   0.256) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 60.00 ms
(  10.650|   0.256) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 70.00 ms
(  10.907|   0.256) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 80.00 ms
(  11.164|   0.256) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 90.00 ms
(  11.421|   0.256) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 94.99 ms

seem no longer support 105ms anymore


(  11.678|   0.257) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 1.00 ms
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.679|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.680|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.935|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 2.00 ms
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.936|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=334280
(  11.937|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=84012
(  12.192|   0.255) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 4.00 ms
(  12.193|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 105.00ms





    if (n_bytes <= u->hwbuf_size)
        left_to_play = u->hwbuf_size - n_bytes;
    else {

        /* We got a dropout. What a mess! */
        left_to_play = 0;
        underrun = true;

#if 0
        PA_DEBUG_TRAP;
#endif

        if (!u->first && !u->after_rewind)
            if (pa_log_ratelimit(PA_LOG_INFO))
                pa_log_info("Underrun!");
    }

(In reply to Raymond from comment #88)
> http://lists.freedesktop.org/archives/pulseaudio-discuss/2014-October/022019.
> html
> 
> seem  you may need to set fragment time to 80ms

Hi Raymond,
I made the changes to the set up of /etc/pulse/daemon.con that you have required. There are not differences in the use of cpu by pulseaudio, following the results. I will attach the file daemon.conf.

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.12.30+ #717 PREEMPT Fri Oct 17 18:46:31 BST 2014 armv6l GNU/Linux

pi@raspberrypi ~ $ top
top - 10:10:52 up 2 min,  2 users,  load average: 2.06, 0.87, 0.33
Tasks:  92 total,   1 running,  91 sleeping,   0 stopped,   0 zombie
%Cpu(s): 46.8 us, 28.9 sy,  0.0 ni, 20.0 id,  0.0 wa,  0.0 hi,  4.3 si,  0.0 st
KiB Mem:    447856 total,   137784 used,   310072 free,    14892 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    68368 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2335 pulse      9 -11 87984 4836 3532 S  56.5  1.1   0:25.69 pulseaudio        
 2401 pi        20   0  115m 3816 2420 S  17.5  0.9   0:07.07 shairport         
 2579 root      20   0 22292  11m 4844 S   1.6  2.6   0:03.42 Xorg              
 2757 pi        20   0  4668 1380 1036 R   1.3  0.3   0:00.55 top               


Like I mentioned I have noticed a slight improvement just by adding the following line to /etc/pulse/system.pa:

load-module module-alsa-card device_id=0 tsched=true tsched_buffer_size=256072 tsched_buffer_watermark=120268

This is the results:

pi@raspberrypi ~ $ top
top - 10:05:31 up 3 min,  2 users,  load average: 1.01, 0.55, 0.23
Tasks:  93 total,   2 running,  91 sleeping,   0 stopped,   0 zombie
%Cpu(s): 41.1 us, 22.8 sy,  0.0 ni, 33.8 id,  0.0 wa,  0.0 hi,  2.3 si,  0.0 st
KiB Mem:    447856 total,   137228 used,   310628 free,    14912 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    68012 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2404 pi        20   0  150m 4764 3632 R  40.2  1.1   0:21.11 pulseaudio        
 2400 pi        20   0  115m 3988 2588 S  18.4  0.9   0:07.99 shairport         
 2675 root      20   0 22004  11m 4844 S   1.6  2.5   0:02.42 Xorg              
 2766 pi        20   0  4672 1380 1036 R   1.6  0.3   0:00.53 top               

ut changing the values ​​of

tsched_buffer_size=
tsched_buffer_watermark=

there are no differences

Created attachment 108288 [details]
D/etc/pulse/daemon.conf change set-up to default-fragment-size-msec

This is the file /etc/pulse/daemon.conf with only change set-up to default-fragment-size-msec

I ha

(In reply to Raymond from comment #87)
> do you mean aplay work with any period size ?
> 
> 441, 
> 
> not multiple of 8 frames , 
> 
> or only two  power n

I've attached the results for aplay. Basically aplay also works with different -buffer-size not multiples of 8 frame or two power n.

Created attachment 108291 [details]
Report of aplay -v -D hw:0,0 --buffer-size not multiples of 8 frame or two power n stereo.wav with Kernel 3.12.29+

Report of --buffer-size not multiples of 8 frame or two power. Basically there are no underruns above -buffer-size = 512.

you need to use 44100Hz wav file to test the period size 441

your aplay result indicate the your sound card cannot select exactly 10 ms period time since your driver seem have a constraints which limit the period size must be multiple of eight


this mean you won't get the default 25ms fragment time 



 the proposed default 5ms seem unlikely to work when your hwptr can remained unchanged for more than 9ms

https://wiki.debian.org/PulseAudio

you need to remove the leading semicolon if you want to change any parameter

(In reply to Raymond from comment #95)
> you need to use 44100Hz wav file to test the period size 441
> 
> your aplay result indicate the your sound card cannot select exactly 10 ms
> period time since your driver seem have a constraints which limit the period
> size must be multiple of eight
> 
> 
> this mean you won't get the default 25ms fragment time 
> 
> 
> 
>  the proposed default 5ms seem unlikely to work when your hwptr can remained
> unchanged for more than 9ms

I thank you for telling me to remove the leading semicolon. I want to do again the test, how I should set up the following parameters in /etc/pulse/daemon.conf:

default-fragments = ?
default-fragment-size-msec = 80 ?

and also possibly others. 
I will send you another aplay test with 44100Hz wav file.

Regards.

(In reply to Raymond from comment #96)
> https://wiki.debian.org/PulseAudio
> 
> you need to remove the leading semicolon if you want to change any parameter

Hi Raymond
these are the results obtained by setting the parameter, without the leading semicolon on /etc/pulse/daemon.conf: 

default-fragment-size-msec = 80 

As can be seen there is an improvement albeit minimal, but not sufficient. In Kernel 3.12.25+ pulseaudio used at most 13% of the CPU.

pi@raspberrypi ~ $ top
top - 09:42:23 up 2 min,  2 users,  load average: 1.36, 0.63, 0.24
Tasks:  92 total,   1 running,  91 sleeping,   0 stopped,   0 zombie
%Cpu(s): 39.6 us, 26.8 sy,  0.0 ni, 29.4 id,  0.0 wa,  0.0 hi,  4.2 si,  0.0 st
KiB Mem:    447856 total,   137048 used,   310808 free,    14876 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    67500 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2337 pulse      9 -11 87984 5132 3532 S  49.8  1.1   0:26.73 pulseaudio        
 2416 pi        20   0  115m 3928 2532 S  15.9  0.9   0:08.62 shairport         
 2524 root      20   0 22264  10m 4660 S   1.3  2.5   0:03.13 Xorg              
 2739 pi        20   0  4672 1380 1036 R   1.3  0.3   0:01.12 top               
 2728 pi        20   0  113m 9932 7696 S   0.6  2.2   0:01.52 lxterminal

Created attachment 108341 [details]
Report of aplay -v -D hw:0,0 --buffer-size not multiples of 8 frame or two power n stereo.wav rate 44100

Hi Raymond
questi sono i risultati di aplay ottenuti invece con un 44100Hz wav file. Conditions remaining unchanged.

(In reply to Raymond from comment #95)
> you need to use 44100Hz wav file to test the period size 441
> 
> your aplay result indicate the your sound card cannot select exactly 10 ms
> period time since your driver seem have a constraints which limit the period
> size must be multiple of eight
> 
> 
> this mean you won't get the default 25ms fragment time 
> 
> 
> 
>  the proposed default 5ms seem unlikely to work when your hwptr can remained
> unchanged for more than 9ms

I have attached a new file.

try

aplay -v -D hw:0,0 --dump-hwparams --period-time=10000 any44100hzstereo.wav


you need to ask  Florian (author of bcm2835_i2s.c)

1) .periods_min * .period_bytes_min or .buffer_bytes_min seem less than the size of fifo 
2) are there any timeout loop  which cause hwptr remain unchanged for more than 9ms ?

should be --dump-hw-params instead of --dump-hwparams

3) whether the hardware support disable period wake up ?

(In reply to Raymond from comment #101)
> try
> 
> aplay -v -D hw:0,0 --dump-hwparams --period-time=10000 any44100hzstereo.wav
> 
> 
> you need to ask  Florian (author of bcm2835_i2s.c)
> 
> 1) .periods_min * .period_bytes_min or .buffer_bytes_min seem less than the
> size of fifo 
> 2) are there any timeout loop  which cause hwptr remain unchanged for more
> than 9ms ?

To run aplay --dump-hw-params I have to compile all the alsa-util 1.0.28 and alsa-lib 1.0.28. I thought it was easier, however missing many dependencies. 

You know an easier way? or give me a link or address to contact Florian. 
I wanted you instead show a possibly related issue. 
If I run the command paplay -v Europa.wav:

pi@raspberrypi ~ $ paplay -v Europa.wav
Opening a playback stream with sample specification 's16le 2ch 44100Hz' and channel map 'front-left,front-right'.
Connection established.
Stream successfully created.
Buffer metrics: maxlength=4194304, tlength=352800, prebuf=349276, minreq=3528
Using sample spec 's16le 2ch 44100Hz', channel map 'front-left,front-right'.
Connected to device alsa_output.platform-snd-hifiberry-amp.0.analog-stereo (0, not suspended).
Stream started.
^CGot signal, exiting.cy: 2288469 usec.

pi@raspberrypi ~ $ top

top - 16:08:16 up 8 min,  3 users,  load average: 0.71, 0.71, 0.37
Tasks:  93 total,   1 running,  92 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7.2 us,  9.4 sy,  0.0 ni, 83.1 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
KiB Mem:    447856 total,   154452 used,   293404 free,    15052 buffers
KiB Swap:   102396 total,        0 used,   102396 free,    78044 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND           
 2355 pulse      9 -11 87984 5824 3540 S   7.9  1.3   1:03.57 pulseaudio        
 2606 root      20   0 26376  15m 4760 S   2.0  3.5   0:10.32 Xorg              
 2772 pi        20   0  4668 1388 1040 R   1.3  0.3   0:04.61 top               
 2900 pi        20   0 83540 2764 2264 S   1.3  0.6   0:00.64 paplay            
 2761 pi        20   0  113m 9.9m 7708 S   0.7  2.3   0:04.76 lxterminal       

feel good music and as you can see above the CPU usage from pulseaudio is normal. 
While if I run: 

pi@raspberrypi ~ $ paplay -v Desperado.wav
Opening a playback stream with sample specification 's16le 2ch 48000Hz' and channel map 'front-left,front-right'.
Connection established.
Stream successfully created.
Buffer metrics: maxlength=4194304, tlength=384000, prebuf=380164, minreq=3840
Using sample spec 's16le 2ch 48000Hz', channel map 'front-left,front-right'.
Connected to device alsa_output.platform-snd-hifiberry-amp.0.analog-stereo (0, suspended).
^CGot signal, exiting.cy: 2000000 usec.   

the application crashes before start reading and I not hear anything, also pulseaudio will abort and I need to restart it again. The only difference between the two wav files is that the first has a sampling rate 44100Hz and the second 48000Hz.
what do you think about?

http://git.alsa-project.org/?p=alsa-lib.git;a=tree;f=src/conf/ucm;hb=HEAD

some soc driver have specific ucm conf when they have more than one playback device and volume control and swtch with non stanard name

@Raymond: The HiFiBerry SOC drivers for the Raspberry Pi do not have an ucm configuration. There is only a single playback device.

http://git.alsa-project.org/?p=alsa-utils.git;a=commitdiff;h=2d105e0f18a82783ea69e2dbe9da7aeb7d3c1346;hp=53107e1e3146e3687e571b2c31f9d271623c5411

it just one line code which can add to pcm_avail.c after 


err = snd_pcm_hw_params_any(handle, params);

snd_pcm_hw_params_dump(params, log);

email address of the author can be found in the source code of the driver

-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/136.