[pulseaudio-discuss] SOLVED Re: RTP stream sample rate and latency problem "Sample rates too different, not adjusting"
Chris Beat
misc.stuff at action.ms
Fri Jun 24 07:11:28 UTC 2022
On 17/06/2022 21:54, Chris Beat wrote:
> Hi,
>
> in my setup I have a Raspberry with an old USB soundcard as a RTP sender and an old netbook as the
> RTP receiver. I use the netbook to connect a bluetooth speaker to it.
>
> If important: this is unicast RTP.
>
> If I start streaming music on the sender side, it takes a long time until I get output on the
> receiver side (with "long" I mean magnitude of: several seconds, up to minutes), and also the
> "pitch" of the music is audible lower / slower than what I can hear on the sending device.
>
> Troubleshooting steps so far:
>
> If I start the pulseaudio daemon on the sender side (with module-rtp-send), then on the receiver
> side, I get this message in the log (about every 5 seconds):
>
> "Sample rates too different, not adjusting (44100 vs. 57567)."
>
> The 57567 value slowly increases in time.
>
> I also noticed that on the receiver side, the sink-input "Buffer Latency" quickly increases over
> time, as seen here for example:
>
>
> ~$ pactl list sink-inputs
> Sink Input #0
> Driver: module-loopback.c
> Owner Module: 7
> Client: n/a
> Sink: 1
> Sample Specification: s16le 2ch 44103Hz
> 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\""
> Corked: no
> Mute: no
> Volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
> balance 0.00
> Buffer Latency: 135137 usec
> Sink Latency: 69810 usec
> Resample method: speex-float-1
> Properties:
> media.role = "abstract"
> media.name = "Loopback from Monitor of NullSink"
> media.icon_name = "audio-input-microphone"
>
> Sink Input #1
> Driver: module-rtp-recv.c
> Owner Module: 10
> Client: n/a
> Sink: 0
> Sample Specification: s16be 2ch 44100Hz
> Channel Map: front-left,front-right
> Format: pcm, format.sample_format = "\"s16be\"" format.rate = "44100" format.channels = "2"
> Corked: no
> Mute: no
> Volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
> balance 0.00
> Buffer Latency: 13670815 usec
> Sink Latency: 6885 usec
> Resample method: speex-float-1
> Properties:
> media.role = "stream"
> media.name = "RTP Stream (PulseAudio RTP Stream on raspberrypi)"
> rtp.session = "PulseAudio RTP Stream on raspberrypi"
> rtp.origin = "pi 3864408555 0 IN IP4 192.168.2.30"
> rtp.payload = "10"
> ~$
>
>
>
>
> Here the "Buffer Latency" is already almost 14 seconds, this is only shortly (1-2 minutes) after a
> restart of the daemon.
>
> Any idea on how to either solve this quick and dirty, or troubleshoot further?
>
>
> some information from the two devices:
>
>
> #### Raspberry RTP sender BEGIN INFO ####
> pi at raspberrypi:~ $ pulseaudio --version
> pulseaudio 14.2
> pi at raspberrypi:~ $ pacmd dump
> ### Configuration dump generated at Fri Jun 17 21:49:17 2022
>
> load-module module-udev-detect
> load-module module-alsa-card device_id="1" name="usb-041e_USB_Audio-00"
> card_name="alsa_card.usb-041e_USB_Audio-00" namereg_fail=false tsched=yes fixed_latency_range=no
> ignore_dB=no deferred_volume=yes use_ucm=yes avoid_resampling=no
> card_properties="module-udev-detect.discovered=1"
> load-module module-native-protocol-unix
> load-module module-systemd-login
> load-module module-rtp-send source=alsa_input.usb-041e_USB_Audio-00.iec958-stereo
> destination_ip=192.168.2.15
> load-module module-rtp-recv sap_address=192.168.2.30
> load-module module-cli-protocol-unix
>
> set-sink-volume alsa_output.usb-041e_USB_Audio-00.iec958-stereo 0x10000
> set-sink-mute alsa_output.usb-041e_USB_Audio-00.iec958-stereo no
> suspend-sink alsa_output.usb-041e_USB_Audio-00.iec958-stereo no
>
> set-source-volume alsa_output.usb-041e_USB_Audio-00.iec958-stereo.monitor 0x10000
> set-source-mute alsa_output.usb-041e_USB_Audio-00.iec958-stereo.monitor no
> suspend-source alsa_output.usb-041e_USB_Audio-00.iec958-stereo.monitor no
> set-source-volume alsa_input.usb-041e_USB_Audio-00.iec958-stereo 0x10000
> set-source-mute alsa_input.usb-041e_USB_Audio-00.iec958-stereo no
> suspend-source alsa_input.usb-041e_USB_Audio-00.iec958-stereo no
>
> set-card-profile alsa_card.usb-041e_USB_Audio-00 output:iec958-stereo+input:iec958-stereo
>
> set-default-sink alsa_output.usb-041e_USB_Audio-00.iec958-stereo
> set-default-source alsa_input.usb-041e_USB_Audio-00.iec958-stereo
>
> ### EOF
> pi at raspberrypi:~ $
>
> #### Raspberry RTP sender END INFO ####
>
>
>
> #### Netbook RTP receiver BEGIN INFO ####
> xxx at netbook:~$ pulseaudio --version
> pulseaudio 14.2
> xxx at netbook:~$ pacmd dump
> ### Configuration dump generated at Fri Jun 17 21:49:46 2022
>
> load-module module-bluetooth-policy
> load-module module-bluetooth-discover
> load-module module-bluez5-discover
> load-module module-native-protocol-unix
> load-module module-systemd-login
> load-module module-null-sink sink_name="NullSink" sink_properties="device.description='NullSink'"
> load-module module-null-sink sink_name="NullSinkDel" sink_properties="device.description='NullSinkDel'"
> load-module module-loopback latency_msec=200 adjust_time=1 source=NullSink.monitor sink=NullSinkDel
> source_dont_move=yes sink_dont_move=yes
> load-module module-rtp-send source=NullSink.monitor destination_ip=192.168.2.230
> load-module module-rtp-send source=NullSink.monitor destination_ip=192.168.2.30
> load-module module-rtp-recv sink=NullSink sap_address=192.168.2.15
> load-module module-cli-protocol-unix
>
> set-sink-volume NullSink 0x10000
> set-sink-mute NullSink no
> suspend-sink NullSink no
> set-sink-volume NullSinkDel 0x10000
> set-sink-mute NullSinkDel no
> suspend-sink NullSinkDel no
>
> set-source-volume NullSink.monitor 0x10000
> set-source-mute NullSink.monitor no
> suspend-source NullSink.monitor no
> set-source-volume NullSinkDel.monitor 0x10000
> set-source-mute NullSinkDel.monitor no
> suspend-source NullSinkDel.monitor no
>
> set-default-sink NullSink
> set-default-source NullSink.monitor
>
> ### EOF
> xxx at netbook:~$
>
>
>
>
> ##### ... some logging with log level "debug":
> xxx at netbook:~$ systemctl --user restart pulseaudio;journalctl --follow
> Hint: You are currently not seeing messages from other users and the system.
> Users in groups 'adm', 'systemd-journal' can see all messages.
> Pass -q to turn off this notice.
> -- Journal begins at Thu 2022-06-16 13:05:00 CEST. --
> Jun 17 21:50:29 netbook pulseaudio[16443]: Bluetooth Headset Backend API support using the native
> backend
> Jun 17 21:50:29 netbook pulseaudio[16443]: Registering Profile /Profile/HSPAGProfile
> 00001112-0000-1000-8000-00805f9b34fb
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Failed to register as a handsfree audio agent with ofono:
> org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files
> Jun 17 21:50:29 netbook pulseaudio[16443]: oFono is running: no
> Jun 17 21:50:29 netbook pulseaudio[16443]: Registering Profile /Profile/HSPHSProfile
> 00001108-0000-1000-8000-00805f9b34fb
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci1
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Properties changed in adapter /org/bluez/hci0
> Jun 17 21:50:29 netbook pulseaudio[16443]: Loopback overall latency is 1809.60 ms + 200.00 ms +
> -1870.11 ms = 139.39 ms
> Jun 17 21:50:29 netbook pulseaudio[16443]: Loopback latency at base rate is 139.39 ms
> Jun 17 21:50:29 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 43721 Hz.
> Jun 17 21:50:30 netbook pulseaudio[16443]: Loopback overall latency is 808.51 ms + 201.73 ms +
> -868.96 ms = 141.12 ms
> Jun 17 21:50:30 netbook pulseaudio[16443]: Loopback latency at base rate is 139.39 ms
> Jun 17 21:50:30 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 43721 Hz.
> Jun 17 21:50:31 netbook pulseaudio[16443]: Got signal SIGUSR2.
> Jun 17 21:50:31 netbook pulseaudio[16443]: Loaded "module-cli-protocol-unix" (index: #11; argument:
> "").
> Jun 17 21:50:31 netbook pulseaudio[16443]: Created 2 "UNIX socket client"
> Jun 17 21:50:31 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:31 netbook pulseaudio[16443]: Freed 2 "UNIX socket client"
> Jun 17 21:50:31 netbook pulseaudio[16443]: Adding 64911 usec of silence to queue
> Jun 17 21:50:31 netbook pulseaudio[16443]: Dropping 7296 usec of audio from queue
> Jun 17 21:50:31 netbook pulseaudio[16443]: Adding 66649 usec of silence to queue
> Jun 17 21:50:31 netbook pulseaudio[16443]: Dropping 65483 usec of audio from queue
> Jun 17 21:50:31 netbook pulseaudio[16443]: Loopback overall latency is 9.41 ms + 197.98 ms + -6.14
> ms = 201.12 ms
> Jun 17 21:50:31 netbook pulseaudio[16443]: Loopback latency at base rate is 199.42 ms
> Jun 17 21:50:31 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44075 Hz.
> Jun 17 21:50:32 netbook pulseaudio[16443]: Loopback overall latency is 22.47 ms + 180.94 ms + -3.18
> ms = 200.10 ms
> Jun 17 21:50:32 netbook pulseaudio[16443]: Loopback latency at base rate is 200.00 ms
> Jun 17 21:50:32 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44099 Hz.
> Jun 17 21:50:33 netbook pulseaudio[16443]: Negotiated format: pcm, format.sample_format =
> "\"s16be\"" format.rate = "44100" format.channels = "2"
> Jun 17 21:50:33 netbook pulseaudio[16443]: Resampler:
> Jun 17 21:50:33 netbook pulseaudio[16443]: rate 44100 -> 44100 (method speex-float-1)
> Jun 17 21:50:33 netbook pulseaudio[16443]: format s16be -> s16le (intermediate float32le)
> Jun 17 21:50:33 netbook pulseaudio[16443]: channels 2 -> 2 (resampling 2)
> Jun 17 21:50:33 netbook pulseaudio[16443]: Choosing speex quality setting 1.
> Jun 17 21:50:33 netbook pulseaudio[16443]: memblockq requested: maxlength=33554432, tlength=0,
> base=4, prebuf=0, minreq=1 maxrewind=0
> Jun 17 21:50:33 netbook pulseaudio[16443]: memblockq sanitized: maxlength=33554432,
> tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
> Jun 17 21:50:33 netbook pulseaudio[16443]: Created input 1 "RTP Stream (PulseAudio RTP Stream on
> raspberrypi)" on NullSink with sample spec s16be 2ch 44100Hz and channel map front-left,front-right
> Jun 17 21:50:33 netbook pulseaudio[16443]: media.role = "stream"
> Jun 17 21:50:33 netbook pulseaudio[16443]: media.name = "RTP Stream (PulseAudio RTP Stream on
> raspberrypi)"
> Jun 17 21:50:33 netbook pulseaudio[16443]: rtp.session = "PulseAudio RTP Stream on raspberrypi"
> Jun 17 21:50:33 netbook pulseaudio[16443]: rtp.origin = "pi 3864408555 0 IN IP4 192.168.2.30"
> Jun 17 21:50:33 netbook pulseaudio[16443]: rtp.payload = "10"
> Jun 17 21:50:33 netbook pulseaudio[16443]: memblockq requested: maxlength=41943040,
> tlength=41943040, base=4, prebuf=44100, minreq=0 maxrewind=0
> Jun 17 21:50:33 netbook pulseaudio[16443]: memblockq sanitized: maxlength=41943040,
> tlength=41943040, base=4, prebuf=44100, minreq=4 maxrewind=0
> Jun 17 21:50:33 netbook pulseaudio[16443]: Initialising native RTP backend for receive
> Jun 17 21:50:33 netbook pulseaudio[16443]: NullSink: state: IDLE -> RUNNING
> Jun 17 21:50:33 netbook pulseaudio[16443]: New session 'PulseAudio RTP Stream on raspberrypi'
> Jun 17 21:50:33 netbook pulseaudio[16443]: Loopback overall latency is 34.92 ms + 166.38 ms + -1.16
> ms = 200.02 ms
> Jun 17 21:50:33 netbook pulseaudio[16443]: Loopback latency at base rate is 200.02 ms
> Jun 17 21:50:33 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44100 Hz.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Requesting rewind due to end of underrun
> Jun 17 21:50:34 netbook pulseaudio[16443]: Requested to rewind 1276 bytes.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Processing rewind...
> Jun 17 21:50:34 netbook pulseaudio[16443]: Have to rewind 844 bytes on render memblockq.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Processing rewind...
> Jun 17 21:50:34 netbook pulseaudio[16443]: Have to rewind 844 bytes on implementor.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Rewound 844 bytes.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Created 3 "Native client (UNIX socket client)"
> Jun 17 21:50:34 netbook pulseaudio[16443]: Protocol version: remote 34, local 34
> Jun 17 21:50:34 netbook pulseaudio[16443]: Got credentials: uid=1000 gid=1000 success=1
> Jun 17 21:50:34 netbook pulseaudio[16443]: SHM possible: yes
> Jun 17 21:50:34 netbook pulseaudio[16443]: Negotiated SHM: yes
> Jun 17 21:50:34 netbook pulseaudio[16443]: Memfd possible: yes
> Jun 17 21:50:34 netbook pulseaudio[16443]: Negotiated SHM type: shared memfd
> Jun 17 21:50:34 netbook pulseaudio[16443]: Using shared memfd memory pool with 1024 slots of size
> 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65496
> Jun 17 21:50:34 netbook pulseaudio[16443]: SHM block is 65496 bytes, ringbuffer capacity is 2 *
> 32724 bytes
> Jun 17 21:50:34 netbook pulseaudio[16443]: Enabling srbchannel...
> Jun 17 21:50:34 netbook pulseaudio[16443]: Client enabled srbchannel.
> Jun 17 21:50:34 netbook pulseaudio[16443]: Loopback overall latency is 16.89 ms + 186.78 ms + -3.16
> ms = 200.07 ms
> Jun 17 21:50:34 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:34 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:35 netbook pulseaudio[16443]: Loopback overall latency is 17.65 ms + 185.75 ms + -3.13
> ms = 200.08 ms
> Jun 17 21:50:35 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:50:35 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:36 netbook pulseaudio[16443]: Created 4 "UNIX socket client"
> Jun 17 21:50:36 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:36 netbook pulseaudio[16443]: Freed 4 "UNIX socket client"
> Jun 17 21:50:36 netbook pulseaudio[16443]: Loopback overall latency is 11.43 ms + 194.07 ms + -5.25
> ms = 200.08 ms
> Jun 17 21:50:36 netbook pulseaudio[16443]: Loopback latency at base rate is 200.10 ms
> Jun 17 21:50:36 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44104 Hz.
> Jun 17 21:50:37 netbook pulseaudio[16443]: Loopback overall latency is 53.79 ms + 152.23 ms + -5.77
> ms = 200.03 ms
> Jun 17 21:50:37 netbook pulseaudio[16443]: Loopback latency at base rate is 200.05 ms
> Jun 17 21:50:37 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:38 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:50:38 netbook pulseaudio[16443]: wi=5449433 ri=4810884
> Jun 17 21:50:38 netbook pulseaudio[16443]: Write index deviates by 675.86 ms, expected 500.00 ms
> Jun 17 21:50:38 netbook pulseaudio[16443]: Estimated target rate: 45708 Hz, using average of 44132
> Hz (α=0.020)
> Jun 17 21:50:38 netbook pulseaudio[16443]: New rate of 44520 Hz not within 2‰ of 44100 Hz, forcing
> smaller adjustment
> Jun 17 21:50:38 netbook pulseaudio[16443]: Updated sampling rate to 44188 Hz.
> Jun 17 21:50:38 netbook pulseaudio[16443]: Loopback overall latency is 42.72 ms + 162.49 ms + -4.97
> ms = 200.05 ms
> Jun 17 21:50:38 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:50:38 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:40 netbook pulseaudio[16443]: Loopback overall latency is 84.10 ms + 127.52 ms + -1.09
> ms = 200.07 ms
> Jun 17 21:50:40 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:40 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:40 netbook pulseaudio[16443]: Loopback overall latency is 7.98 ms + 195.27 ms + -2.82
> ms = 200.06 ms
> Jun 17 21:50:40 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:40 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:41 netbook pulseaudio[16443]: Created 5 "UNIX socket client"
> Jun 17 21:50:41 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:41 netbook pulseaudio[16443]: Freed 5 "UNIX socket client"
> Jun 17 21:50:42 netbook pulseaudio[16443]: Loopback overall latency is 113.44 ms + 92.47 ms + -5.71
> ms = 200.05 ms
> Jun 17 21:50:42 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:50:42 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:42 netbook pulseaudio[16443]: Loopback overall latency is 36.06 ms + 170.92 ms + -6.71
> ms = 200.07 ms
> Jun 17 21:50:42 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:42 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:43 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:50:43 netbook pulseaudio[16443]: wi=10869919 ri=9971938
> Jun 17 21:50:43 netbook pulseaudio[16443]: Write index deviates by 1103.29 ms, expected 500.00 ms
> Jun 17 21:50:43 netbook pulseaudio[16443]: Estimated target rate: 48319 Hz, using average of 47481
> Hz (α=0.800)
> Jun 17 21:50:43 netbook pulseaudio[16443]: New rate of 48913 Hz not within 2‰ of 44188 Hz, forcing
> smaller adjustment
> Jun 17 21:50:43 netbook pulseaudio[16443]: Updated sampling rate to 44276 Hz.
> Jun 17 21:50:44 netbook pulseaudio[16443]: Loopback overall latency is 27.73 ms + 179.24 ms + -6.69
> ms = 200.06 ms
> Jun 17 21:50:44 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:44 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:45 netbook pulseaudio[16443]: Loopback overall latency is 67.12 ms + 137.04 ms + -3.94
> ms = 200.07 ms
> Jun 17 21:50:45 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:50:45 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:46 netbook pulseaudio[16443]: Loopback overall latency is 52.23 ms + 154.50 ms + -6.38
> ms = 200.06 ms
> Jun 17 21:50:46 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:46 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:46 netbook pulseaudio[16443]: Created 6 "UNIX socket client"
> Jun 17 21:50:46 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:46 netbook pulseaudio[16443]: Freed 6 "UNIX socket client"
> Jun 17 21:50:47 netbook pulseaudio[16443]: Loopback overall latency is 91.12 ms + 114.17 ms + -5.09
> ms = 200.07 ms
> Jun 17 21:50:47 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:50:47 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:48 netbook pulseaudio[16443]: Loopback overall latency is 13.57 ms + 187.67 ms + -0.99
> ms = 200.05 ms
> Jun 17 21:50:48 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:50:48 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:48 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:50:48 netbook pulseaudio[16443]: wi=16276086 ri=15112476
> Jun 17 21:50:48 netbook pulseaudio[16443]: Write index deviates by 1517.74 ms, expected 500.00 ms
> Jun 17 21:50:48 netbook pulseaudio[16443]: Estimated target rate: 48278 Hz, using average of 48118
> Hz (α=0.800)
> Jun 17 21:50:48 netbook pulseaudio[16443]: New rate of 50567 Hz not within 2‰ of 44276 Hz, forcing
> smaller adjustment
> Jun 17 21:50:48 netbook pulseaudio[16443]: Updated sampling rate to 44364 Hz.
> Jun 17 21:50:49 netbook pulseaudio[16443]: Loopback overall latency is 112.12 ms + 92.47 ms + -4.10
> ms = 200.07 ms
> Jun 17 21:50:49 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:49 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:49 netbook pulseaudio[16443]: Checking for dead streams ...
> Jun 17 21:50:50 netbook pulseaudio[16443]: Loopback overall latency is 36.12 ms + 170.17 ms + -5.68
> ms = 200.07 ms
> Jun 17 21:50:50 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:50:50 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:51 netbook pulseaudio[16443]: Loopback overall latency is 23.89 ms + 178.51 ms + -1.99
> ms = 200.06 ms
> Jun 17 21:50:51 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:51 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:51 netbook pulseaudio[16443]: Created 7 "UNIX socket client"
> Jun 17 21:50:51 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:51 netbook pulseaudio[16443]: Freed 7 "UNIX socket client"
> Jun 17 21:50:52 netbook pulseaudio[16443]: Loopback overall latency is 60.66 ms + 143.91 ms + -4.37
> ms = 200.03 ms
> Jun 17 21:50:52 netbook pulseaudio[16443]: Loopback latency at base rate is 200.04 ms
> Jun 17 21:50:52 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44101 Hz.
> Jun 17 21:50:53 netbook pulseaudio[16443]: Loopback overall latency is 43.40 ms + 161.38 ms + -4.42
> ms = 200.07 ms
> Jun 17 21:50:53 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:53 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:53 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:50:53 netbook pulseaudio[16443]: wi=21653593 ri=19864755
> Jun 17 21:50:53 netbook pulseaudio[16443]: Write index deviates by 1930.43 ms, expected 500.00 ms
> Jun 17 21:50:53 netbook pulseaudio[16443]: Estimated target rate: 48355 Hz, using average of 48308
> Hz (α=0.800)
> Jun 17 21:50:53 netbook pulseaudio[16443]: New rate of 51762 Hz not within 2‰ of 44364 Hz, forcing
> smaller adjustment
> Jun 17 21:50:53 netbook pulseaudio[16443]: Updated sampling rate to 44452 Hz.
> Jun 17 21:50:54 netbook pulseaudio[16443]: Loopback overall latency is 79.90 ms + 126.77 ms + 19.11
> ms = 200.06 ms
> Jun 17 21:50:54 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:50:54 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:55 netbook pulseaudio[16443]: Loopback overall latency is 60.98 ms + 141.99 ms + -2.55
> ms = 200.06 ms
> Jun 17 21:50:55 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:55 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:56 netbook pulseaudio[16443]: Loopback overall latency is 99.91 ms + 106.93 ms + -6.17
> ms = 200.06 ms
> Jun 17 21:50:56 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:56 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:57 netbook pulseaudio[16443]: Loopback overall latency is 14.16 ms + 191.51 ms + -5.25
> ms = 200.07 ms
> Jun 17 21:50:57 netbook pulseaudio[16443]: Loopback latency at base rate is 200.09 ms
> Jun 17 21:50:57 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:50:57 netbook pulseaudio[16443]: Created 8 "UNIX socket client"
> Jun 17 21:50:57 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:50:57 netbook pulseaudio[16443]: Freed 8 "UNIX socket client"
> Jun 17 21:50:58 netbook pulseaudio[16443]: Loopback overall latency is 110.92 ms + 92.47 ms + -3.02
> ms = 200.04 ms
> Jun 17 21:50:58 netbook pulseaudio[16443]: Loopback latency at base rate is 200.05 ms
> Jun 17 21:50:58 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:50:58 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:50:58 netbook pulseaudio[16443]: wi=27017007 ri=24965355
> Jun 17 21:50:58 netbook pulseaudio[16443]: Write index deviates by 2329.21 ms, expected 500.00 ms
> Jun 17 21:50:58 netbook pulseaudio[16443]: Estimated target rate: 48305 Hz, using average of 48305
> Hz (α=0.766)
> Jun 17 21:50:58 netbook pulseaudio[16443]: New rate of 52723 Hz not within 2‰ of 44452 Hz, forcing
> smaller adjustment
> Jun 17 21:50:58 netbook pulseaudio[16443]: Updated sampling rate to 44540 Hz.
> Jun 17 21:50:59 netbook pulseaudio[16443]: Loopback overall latency is 34.18 ms + 172.49 ms + -6.24
> ms = 200.06 ms
> Jun 17 21:50:59 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:50:59 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:00 netbook pulseaudio[16443]: Loopback overall latency is 14.60 ms + 189.56 ms + -3.72
> ms = 200.08 ms
> Jun 17 21:51:00 netbook pulseaudio[16443]: Loopback latency at base rate is 200.09 ms
> Jun 17 21:51:00 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:01 netbook pulseaudio[16443]: Loopback overall latency is 45.65 ms + 154.96 ms + -0.27
> ms = 200.07 ms
> Jun 17 21:51:01 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:51:01 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:02 netbook pulseaudio[16443]: Loopback overall latency is 29.38 ms + 177.79 ms + -6.01
> ms = 200.06 ms
> Jun 17 21:51:02 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:02 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:02 netbook pulseaudio[16443]: Created 9 "UNIX socket client"
> Jun 17 21:51:02 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:51:02 netbook pulseaudio[16443]: Freed 9 "UNIX socket client"
> Jun 17 21:51:03 netbook pulseaudio[16443]: Loopback overall latency is 60.80 ms + 143.21 ms + -3.67
> ms = 200.06 ms
> Jun 17 21:51:03 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:03 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:03 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:51:03 netbook pulseaudio[16443]: wi=32359227 ri=29679389
> Jun 17 21:51:03 netbook pulseaudio[16443]: Write index deviates by 2716.14 ms, expected 500.00 ms
> Jun 17 21:51:03 netbook pulseaudio[16443]: Estimated target rate: 48276 Hz, using average of 48305
> Hz (α=0.020)
> Jun 17 21:51:03 netbook pulseaudio[16443]: New rate of 53657 Hz not within 2‰ of 44540 Hz, forcing
> smaller adjustment
> Jun 17 21:51:03 netbook pulseaudio[16443]: Updated sampling rate to 44629 Hz.
> Jun 17 21:51:04 netbook pulseaudio[16443]: Loopback overall latency is 40.84 ms + 160.65 ms + -1.13
> ms = 200.07 ms
> Jun 17 21:51:04 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:51:04 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:05 netbook pulseaudio[16443]: Loopback overall latency is 71.02 ms + 125.66 ms + 24.74
> ms = 200.06 ms
> Jun 17 21:51:05 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:05 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:06 netbook pulseaudio[16443]: Loopback overall latency is 52.80 ms + 148.52 ms + -0.89
> ms = 200.07 ms
> Jun 17 21:51:06 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:51:06 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:07 netbook pulseaudio[16443]: Loopback overall latency is 81.70 ms + 121.15 ms + -2.26
> ms = 200.06 ms
> Jun 17 21:51:07 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:51:07 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:07 netbook pulseaudio[16443]: Created 10 "UNIX socket client"
> Jun 17 21:51:07 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:51:07 netbook pulseaudio[16443]: Freed 10 "UNIX socket client"
> Jun 17 21:51:08 netbook pulseaudio[16443]: Loopback overall latency is 59.26 ms + 145.80 ms + -4.70
> ms = 200.07 ms
> Jun 17 21:51:08 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:08 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:08 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:51:08 netbook pulseaudio[16443]: wi=37672365 ri=34739743
> Jun 17 21:51:08 netbook pulseaudio[16443]: Write index deviates by 3087.23 ms, expected 500.00 ms
> Jun 17 21:51:08 netbook pulseaudio[16443]: Estimated target rate: 48207 Hz, using average of 48231
> Hz (α=0.754)
> Jun 17 21:51:08 netbook pulseaudio[16443]: New rate of 54470 Hz not within 2‰ of 44629 Hz, forcing
> smaller adjustment
> Jun 17 21:51:08 netbook pulseaudio[16443]: Updated sampling rate to 44718 Hz.
> Jun 17 21:51:09 netbook pulseaudio[16443]: Loopback overall latency is 89.25 ms + 118.43 ms + -7.31
> ms = 200.05 ms
> Jun 17 21:51:09 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:51:09 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:09 netbook pulseaudio[16443]: Checking for dead streams ...
> Jun 17 21:51:10 netbook pulseaudio[16443]: Loopback overall latency is 3.94 ms + 200.35 ms + -4.00
> ms = 200.06 ms
> Jun 17 21:51:10 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:10 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:11 netbook pulseaudio[16443]: Loopback overall latency is 97.22 ms + 106.93 ms + -3.73
> ms = 200.05 ms
> Jun 17 21:51:11 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:51:11 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:12 netbook pulseaudio[16443]: Loopback overall latency is 5.98 ms + 197.63 ms + -3.16
> ms = 200.06 ms
> Jun 17 21:51:12 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:12 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:12 netbook pulseaudio[16443]: Created 11 "UNIX socket client"
> Jun 17 21:51:12 netbook pulseaudio[16443]: CLI got EOF from user.
> Jun 17 21:51:12 netbook pulseaudio[16443]: Freed 11 "UNIX socket client"
> Jun 17 21:51:13 netbook pulseaudio[16443]: Loopback overall latency is 100.24 ms + 106.93 ms + -6.56
> ms = 200.05 ms
> Jun 17 21:51:13 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:51:13 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:13 netbook pulseaudio[16443]: Updating sample rate
> Jun 17 21:51:13 netbook pulseaudio[16443]: wi=42964354 ri=39779954
> Jun 17 21:51:13 netbook pulseaudio[16443]: Write index deviates by 3443.80 ms, expected 500.00 ms
> Jun 17 21:51:13 netbook pulseaudio[16443]: Estimated target rate: 48152 Hz, using average of 48170
> Hz (α=0.767)
> Jun 17 21:51:13 netbook pulseaudio[16443]: Sample rates too different, not adjusting (44100 vs. 55260).
> Jun 17 21:51:13 netbook pulseaudio[16443]: Updated sampling rate to 44100 Hz.
> Jun 17 21:51:14 netbook pulseaudio[16443]: Loopback overall latency is 14.48 ms + 193.12 ms + -6.78
> ms = 200.06 ms
> Jun 17 21:51:14 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:14 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:15 netbook pulseaudio[16443]: Loopback overall latency is 110.20 ms + 92.47 ms + -2.32
> ms = 200.05 ms
> Jun 17 21:51:15 netbook pulseaudio[16443]: Loopback latency at base rate is 200.06 ms
> Jun 17 21:51:15 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44102 Hz.
> Jun 17 21:51:16 netbook pulseaudio[16443]: Loopback overall latency is 40.60 ms + 164.05 ms + -4.18
> ms = 200.07 ms
> Jun 17 21:51:16 netbook pulseaudio[16443]: Loopback latency at base rate is 200.08 ms
> Jun 17 21:51:16 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> Jun 17 21:51:17 netbook pulseaudio[16443]: Loopback overall latency is 33.51 ms + 172.37 ms + -5.57
> ms = 200.06 ms
> Jun 17 21:51:17 netbook pulseaudio[16443]: Loopback latency at base rate is 200.07 ms
> Jun 17 21:51:17 netbook pulseaudio[16443]: [NullSinkDel] Updated sampling rate to 44103 Hz.
> ^C
> xxx at netbook:~$
>
>
>
>
>
> #### Netbook RTP receiver END INFO ####
>
>
>
>
>
Hi, I solved this - cause of the problem was a mismatch with the sample rate of the source...
## sender side:
Source #3
State: RUNNING
Name: alsa_input.usb-041e_USB_Audio-00.iec958-stereo
Description: SoundBlaster MP3+ Digital Stereo (IEC958)
Driver: module-alsa-card.c
Sample Specification: s16le 2ch 48000Hz
^^^^
Source Output #0
Driver: module-rtp-send.c
Owner Module: 4
Client: n/a
Source: 3
Sample Specification: s16be 2ch 44100Hz
^^^
Channel Map: front-left,front-right
Format: pcm, format.sample_format = "\"s16be\"" format.rate = "44100" format.channels = "2"
format.channel_map = "\"front-left,front-right\""
Corked: no
Mute: no
Volume: front-left: 65536 / 100% / 0,00 dB, front-right: 65536 / 100% / 0,00 dB
balance 0,00
Buffer Latency: 1655 usec
Source Latency: 1196 usec
Resample method: copy
Properties:
media.name = "RTP Monitor Stream"
rtp.source = "0.0.0.0"
rtp.destination = "192.168.2.15"
rtp.mtu = "1280"
rtp.port = "46750"
rtp.ttl = "1"
## receiver side:
Sink Input #50
Driver: module-rtp-recv.c
Owner Module: 25
Client: n/a
Sink: 1
Sample Specification: s16be 2ch 44364Hz
Channel Map: front-left,front-right
Format: pcm, format.sample_format = "\"s16be\"" format.rate = "44100" format.channels = "2"
Corked: no
Mute: no
Volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
Buffer Latency: 1679994 usec
Sink Latency: 36922 usec
Resample method: speex-float-1
Properties:
media.role = "stream"
media.name = "RTP Stream (PulseAudio RTP Stream on raspberrypi)"
rtp.session = "PulseAudio RTP Stream on raspberrypi"
rtp.origin = "pi 3864982388 0 IN IP4 192.168.2.30"
rtp.payload = "10"
module-stream-restore.id = "sink-input-by-media-role:stream"
SOLUTION:
If I load relevant modules with an explicit rate value of 48000, everything works as expected:
## On sender side:
pacmd load-module module-rtp-send source=alsa_input.usb-041e_USB_Audio-00.iec958-stereo
destination_ip=192.168.2.30 rate=48000
## on receiver side:
pacmd load-module module-rtp-recv sink=NullSink sap_address=192.168.2.15
=> works as expected on receiver side.
Sorry for not noticing something probably rather obvious...
Also apologies for a probably stupid question: should modules like module-rtp-send or
module-loopback not automatically recognize the sample rate of the source and either use the same
value or re-sample?
Kind regards.
More information about the pulseaudio-discuss
mailing list