[pulseaudio-discuss] Rate/Timing issues when streaming over BT from iPhone.....

alex at apics.co.uk alex at apics.co.uk
Sun Jul 25 10:09:32 PDT 2010


Hi All,
        I've setup pulse audio to stream music from my iPhone (connected 
using BlueTooth) and output it, using module-loopback.... This is working 
fine, the only issue I have appears to be related the bitrate/timing 
etc... The music is very crackly, and is playing back too slowly.... I've 
tried changing a number of options, but haven't been able to resolve it. 
I've tried lots of different combinations of the 'rate' option, but none 
helped...  Any help really would be much appreciated, please find debug 
output below, along with the script I'm executing:

Script:
#!/usr/bin/pulseaudio -vvvnF
load-module module-alsa-sink device=default:CARD=Live sink_name=output 
rate=48000
load-module module-bluetooth-device address="XX:XX:XX:XX:XX:XX" 
path="/org/bluez/1662/hci0/dev_XX_XX_XX_XX_XX_XX" profile="a2dp_source" 
auto_connect=yes name=input rate=44100
load-module module-loopback source=1 sink=0 rate=44100

Output:
# ./iphone.sh 2>&1 |grep -v "Coud not peek into queue"
method return sender=:1.7 -> dest=:1.183 reply_serial=2
W: main.c: This program is not intended to be run as root (unless --system 
is specified).
D: core-rtclock.c: Timer slack is set to 50 us.
D: core-util.c: setpriority() worked.
I: core-util.c: Successfully gained nice level -11.
I: main.c: This is PulseAudio 0.9.21
D: main.c: Compilation host: x86_64-pc-linux-gnu
D: main.c: Compilation CFLAGS: -g -O2 -g -Wall -O2 -Wall -W -Wextra -pipe 
-Wno-long-long -Winline -Wvla -Wno-overlength-strings 
-Wunsafe-loop-optimizations -Wundef -Wformat=2 -Wlogical-op -Wsign-compare 
-Wformat-security -Wmissing-include-dirs -Wformat-nonliteral 
-Wold-style-definition -Wpointer-arith -Winit-self 
-Wdeclaration-after-statement -Wfloat-equal -Wmissing-prototypes 
-Wstrict-prototypes -Wredundant-decls -Wmissing-declarations 
-Wmissing-noreturn -Wshadow -Wendif-labels -Wcast-align 
-Wstrict-aliasing=2 -Wwrite-strings -Wno-unused-parameter -ffast-math 
-Wp,-D_FORTIFY_SOURCE=2 -fno-common -fdiagnostics-show-option
D: main.c: Running on host: Linux x86_64 2.6.28-20090120-2 #4 SMP Tue Jan 
20 20:51:16 GMT 2009
D: main.c: Found 2 CPUs.
I: main.c: Page size is 4096 bytes
D: main.c: Compiled with Valgrind support: no
D: main.c: Running in valgrind mode: no
D: main.c: Running in VM: no
D: main.c: Optimized build: yes
D: main.c: All asserts enabled.
I: main.c: Machine ID is 1d51cc52a374b4f5c5300a73497633ec.
I: main.c: Using runtime directory 
/root/.pulse/1d51cc52a374b4f5c5300a73497633ec-runtime.
I: main.c: Using state directory /root/.pulse.
I: main.c: Using modules directory /usr/lib/pulse-0.9.21/modules.
I: main.c: Running in system mode: no
I: main.c: Dude, your kernel stinks! The chef's recommendation today is 
Linux with high-resolution timers enabled!
I: cpu-x86.c: CPU flags: MMX SSE SSE2 SSE3 MMXEXT 3DNOW 3DNOWEXT 
I: svolume_mmx.c: Initialising MMX optimized functions.
I: remap_mmx.c: Initialising MMX optimized remappers.
I: svolume_sse.c: Initialising SSE2 optimized functions.
I: remap_sse.c: Initialising SSE2 optimized remappers.
I: sconv_sse.c: Initialising SSE2 optimized conversions.
D: memblock.c: Using shared memory pool with 1024 slots of size 64.0 KiB 
each, total size is 64.0 MiB, maximum usable slot size is 65472
N: alsa-util.c: Disabling timer-based scheduling because high-resolution 
timers are not available from the kernel.
D: alsa-util.c: Trying default:CARD=Live with SND_PCM_NO_AUTO_FORMAT ...
D: alsa-util.c: Managed to open default:CARD=Live
D: alsa-util.c: Maximum hw buffer size is 341 ms
D: alsa-util.c: Set buffer size first (to 4800 samples), period size 
second (to 1200 samples).
I: alsa-sink.c: Successfully opened device default:CARD=Live.
I: alsa-sink.c: Successfully enabled mmap() mode.
E: udev-util.c: Failed to get card object.
I: sink.c: Created sink 0 "output" with sample spec s16le 2ch 48000Hz and 
channel map front-left,front-right
I: sink.c:     alsa.resolution_bits = "16"
I: sink.c:     device.api = "alsa"
I: sink.c:     device.class = "sound"
I: sink.c:     alsa.class = "generic"
I: sink.c:     alsa.subclass = "generic-mix"
I: sink.c:     alsa.name = "ADC Capture/Standard PCM Playback"
I: sink.c:     alsa.id = "emu10k1"
I: sink.c:     alsa.subdevice = "1"
I: sink.c:     alsa.subdevice_name = "subdevice #1"
I: sink.c:     alsa.device = "0"
I: sink.c:     alsa.card = "1"
I: sink.c:     alsa.card_name = "SB Live 5.1 Dell OEM [SB0220]"
I: sink.c:     alsa.long_card_name = "SB Live 5.1 Dell OEM [SB0220] 
(rev.10, serial:0x80661102) at 0xfe00, irq 17"
I: sink.c:     device.string = "default:CARD=Live"
I: sink.c:     device.buffering.buffer_size = "19200"
I: sink.c:     device.buffering.fragment_size = "4800"
I: sink.c:     device.access_mode = "mmap"
I: sink.c:     device.description = "SB Live 5.1 Dell OEM [SB0220]"
I: sink.c:     device.icon_name = "audio-card"
I: source.c: Created source 0 "output.monitor" with sample spec s16le 2ch 
48000Hz and channel map front-left,front-right
I: source.c:     device.description = "Monitor of SB Live 5.1 Dell OEM 
[SB0220]"
I: source.c:     device.class = "monitor"
I: source.c:     device.icon_name = "audio-input-microphone"
I: alsa-sink.c: Using 4.0 fragments of size 4800 bytes (25.00ms), buffer 
size is 19200 bytes (100.00ms)
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=1
D: alsa-util.c: snd_pcm_dump():
D: alsa-util.c: Plug PCM: Hardware PCM card 1 'SB Live 5.1 Dell OEM 
[SB0220]' device 0 subdevice 1
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 48000
D: alsa-util.c:   exact rate   : 48000 (48000/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 4800
D: alsa-util.c:   period_size  : 1200
D: alsa-util.c:   period_time  : 25000
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 1200
D: alsa-util.c:   period_event : 1
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 5404319552844595200
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 5404319552844595200
D: alsa-util.c:   appl_ptr     : 0
D: alsa-util.c:   hw_ptr       : 0
D: alsa-sink.c: Thread starting up
D: core-util.c: SCHED_RR worked.
I: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with 
priority 5.
I: alsa-sink.c: Starting playback.
I: module.c: Loaded "module-alsa-sink" (index: #0; argument: 
"device=default:CARD=Live sink_name=output rate=48000").
D: dbus-util.c: Successfully connected to D-Bus system bus 
31a0b73c23303d610695e65d4c4bf0f4 as :1.184
D: bluetooth-util.c: dbus: interface=org.freedesktop.DBus, 
path=/org/freedesktop/DBus, member=NameAcquired
I: card.c: Created 0 "bluez_card.input"
D: module-bluetooth-device.c: Connected to the bluetooth audio service
D: module-bluetooth-device.c: Sending BT_REQUEST -> BT_GET_CAPABILITIES
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_GET_CAPABILITIES
D: module-bluetooth-device.c: Payload size is 37 6
D: module-bluetooth-device.c: Sending BT_REQUEST -> BT_GET_CAPABILITIES
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_GET_CAPABILITIES
D: module-bluetooth-device.c: Payload size is 13 6
D: module-bluetooth-device.c: Got device capabilities
D: module-bluetooth-device.c: Sending BT_REQUEST -> BT_OPEN
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_OPEN
D: module-bluetooth-device.c: Sending BT_REQUEST -> BT_SET_CONFIGURATION
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_SET_CONFIGURATION
I: module-bluetooth-device.c: SBC parameters:
I: module-bluetooth-device.c:   allocation=0
I: module-bluetooth-device.c:   subbands=1
I: module-bluetooth-device.c:   blocks=3
I: module-bluetooth-device.c:   bitpool=53
D: module-bluetooth-device.c: Connection to the device configured
D: module-bluetooth-device.c: Got the stream socket
I: source.c: Created source 1 "bluez_source.input" with sample spec s16le 
2ch 44100Hz and channel map front-left,front-right
I: source.c:     bluetooth.protocol = "a2dp_source"
I: source.c:     device.description = "Alex s iPhone"
I: source.c:     device.string = "64:B9:E8:19:DD:FA"
I: source.c:     device.api = "bluez"
I: source.c:     device.class = "sound"
I: source.c:     device.bus = "bluetooth"
I: source.c:     bluez.path = "/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA"
I: source.c:     bluez.class = "0x7a020c"
I: source.c:     bluez.name = "Alex’s iPhone"
I: source.c:     device.icon_name = "audio-card-bluetooth"
D: module-bluetooth-device.c: IO Thread starting up
D: core-util.c: SCHED_RR worked.
I: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with 
priority 5.
D: module-bluetooth-device.c: Sending BT_REQUEST -> BT_START_STREAM
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_START_STREAM
D: module-bluetooth-device.c: Trying to receive message from audio 
service...
D: module-bluetooth-device.c: Received BT_RESPONSE <- BT_NEW_STREAM
D: module-bluetooth-device.c: Stream properly set up, we're ready to roll!
I: module.c: Loaded "module-bluetooth-device" (index: #1; argument: 
"address="64:B9:E8:19:DD:FA" 
path="/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA" profile="a2dp_source" 
auto_connect=yes name=input rate=44100").
I: resampler.c: Using resampler 'speex-float-3'
I: resampler.c: Using float32le as working format.
I: resampler.c: Choosing speex quality setting 3.
D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, 
base=4, prebuf=0, minreq=1 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, 
base=4, prebuf=0, minreq=4 maxrewind=0
I: sink-input.c: Created input 0 "Loopback of Alex s iPhone" on output 
with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: sink-input.c:     media.name = "Loopback of Alex s iPhone"
I: sink-input.c:     media.icon_name = "audio-card-bluetooth"
I: sink-input.c:     media.role = "abstract"
D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, 
base=4, prebuf=0, minreq=1 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, 
base=4, prebuf=0, minreq=4 maxrewind=0
I: source-output.c: Created output 0 "Loopback to SB Live 5.1 Dell OEM 
[SB0220]" on bluez_source.input with sample spec s16le 2ch 44100Hz and 
channel map front-left,front-right
I: source-output.c:     media.name = "Loopback to SB Live 5.1 Dell OEM 
[SB0220]"
I: source-output.c:     media.icon_name = "audio-card"
I: source-output.c:     media.role = "abstract"
D: memblockq.c: memblockq requested: maxlength=16777216, tlength=16777216, 
base=4, prebuf=0, minreq=0 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=16777216, tlength=16777216, 
base=4, prebuf=0, minreq=4 maxrewind=0
I: module-loopback.c: Max request changed
I: module-loopback.c: Skipping 0 bytes
I: module.c: Loaded "module-loopback" (index: #2; argument: "source=1 
sink=0 rate=44100").
D: dbus-util.c: Successfully connected to D-Bus session bus 
bafbc610e152dc455df317b44c4c6b3e as :1.1
D: main.c: Got org.pulseaudio.Server!
I: main.c: Daemon startup complete.
I: module-loopback.c: Loopback overall latency is 100.04 ms + 0.00 ms + 
39.51 ms = 139.55 ms
I: module-loopback.c: Should buffer 35280 bytes, buffered at minimum 0 
bytes
I: module-loopback.c: Old rate 44100 Hz, new rate 43218 Hz
D: bluetooth-util.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
D: module-bluetooth-device.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
D: bluetooth-util.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
D: module-bluetooth-device.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
I: main.c: Got signal SIGUSR2.
I: module.c: Loaded "module-cli-protocol-unix" (index: #3; argument: "").
I: module-loopback.c: Loopback overall latency is 99.98 ms + 0.00 ms + 
39.51 ms = 139.49 ms
I: module-loopback.c: Should buffer 34576 bytes, buffered at minimum 0 
bytes
I: module-loopback.c: Old rate 43218 Hz, new rate 43236 Hz
I: client.c: Created 0 "UNIX socket client"
D: bluetooth-util.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
D: module-bluetooth-device.c: dbus: interface=org.bluez.AudioSource, 
path=/org/bluez/1662/hci0/dev_64_B9_E8_19_DD_FA, member=PropertyChanged
I: module-loopback.c: Loopback overall latency is 99.99 ms + 400.66 ms + 
42.02 ms = 542.67 ms
I: module-loopback.c: Should buffer 34592 bytes, buffered at minimum 2560 
bytes
I: module-loopback.c: Old rate 43236 Hz, new rate 43300 Hz
I: module-loopback.c: Loopback overall latency is 99.98 ms + 806.05 ms + 
39.69 ms = 945.71 ms
I: module-loopback.c: Should buffer 34640 bytes, buffered at minimum 69240 
bytes
I: module-loopback.c: Old rate 43300 Hz, new rate 44965 Hz
I: module-loopback.c: Loopback overall latency is 99.98 ms + 781.78 ms + 
40.83 ms = 922.60 ms
I: module-loopback.c: Should buffer 35976 bytes, buffered at minimum 
134708 bytes
I: module-loopback.c: Old rate 44965 Hz, new rate 46568 Hz
I: module-loopback.c: Loopback overall latency is 99.98 ms + 429.80 ms + 
40.62 ms = 570.40 ms
I: module-loopback.c: Should buffer 37256 bytes, buffered at minimum 79028 
bytes
I: module-loopback.c: Old rate 46568 Hz, new rate 45144 Hz
I: module-loopback.c: Loopback overall latency is 100.00 ms + 409.27 ms + 
41.85 ms = 551.11 ms
I: module-loopback.c: Should buffer 36120 bytes, buffered at minimum 73904 
bytes
I: module-loopback.c: Old rate 45144 Hz, new rate 45044 Hz
I: main.c: Daemon shutdown initiated.
I: module.c: Unloading "module-alsa-sink" (index: #0).
D: alsa-sink.c: Requested to rewind 19200 bytes.
D: alsa-sink.c: Limited to 19184 bytes.
D: alsa-sink.c: before: 4796
D: alsa-sink.c: after: 4795
D: alsa-sink.c: Rewound 19180 bytes.
D: sink.c: Processing rewind...
D: source.c: Processing rewind...
D: core.c: Hmm, no streams around, trying to vacuum.
I: sink-input.c: Freeing input 0 "Loopback of Alex s iPhone"
I: source-output.c: Freeing output 0 "Loopback to SB Live 5.1 Dell OEM 
[SB0220]"
D: alsa-sink.c: Thread shutting down
I: sink.c: Freeing sink 0 "output"
I: source.c: Freeing source 0 "output.monitor"
I: module.c: Unloaded "module-alsa-sink" (index: #0).
I: module.c: Unloading "module-bluetooth-device" (index: #1).
D: module-bluetooth-device.c: IO thread shutting down
I: source.c: Freeing source 1 "bluez_source.input"
I: card.c: Freed 0 "bluez_card.input"
I: module.c: Unloaded "module-bluetooth-device" (index: #1).
I: module.c: Unloading "module-loopback" (index: #2).
I: module.c: Unloaded "module-loopback" (index: #2).
I: module.c: Unloading "module-cli-protocol-unix" (index: #3).
I: client.c: Freed 0 "UNIX socket client"
I: module.c: Unloaded "module-cli-protocol-unix" (index: #3).
I: main.c: Daemon terminated.
method return sender=:1.7 -> dest=:1.185 reply_serial=2


Thank in advance

Alex

alex at apics.co.uk

Homer Simpson: Facts are meaningless. You could use facts to prove 
anything that's even remotely true!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20100725/63d4f8ba/attachment.htm>


More information about the pulseaudio-discuss mailing list