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@raspberrypi:~ $ pulseaudio --version
pulseaudio 14.2
pi@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@raspberrypi:~ $
#### Raspberry RTP sender END INFO ####
#### Netbook RTP receiver BEGIN INFO ####
xxx@netbook:~$ pulseaudio --version
pulseaudio 14.2
xxx@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@netbook:~$
##### ... some logging with log level "debug":
xxx@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@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.
