[pulseaudio-discuss] Write callback not called in 0.9.19 (more info)

salsaman salsaman at gmail.com
Sun Nov 1 06:51:47 PST 2009 

OK, I have been doing a little more investigation into this. Here is
what I have discovered:

- after a reboot, LiVES (my application) will start and connect once,
subsequent starts of the app get no callbacks.

- if I kill pulseaudio before starting LiVES, the system restarts it,
and LiVES gets callbacks

- if I start another audio app, like amaroK, then even restarting
pulseaudio no longer gives me any write callbacks in LiVES. This
continues even after shutting down amaroK


I ran pulseaudio with log-level=debug, and this is the output in
syslog during a failed attempt (apologies for long paste):


Nov  1 11:30:39 LiVES-devel pulseaudio[9066]: client.c: Created 4
"Native client (UNIX socket client)"
Nov  1 11:30:39 LiVES-devel pulseaudio[9066]: protocol-native.c:
Protocol version: remote 16, local 16
Nov  1 11:30:39 LiVES-devel pulseaudio[9066]: protocol-native.c: Got
credentials: uid=1000 gid=1000 success=1
Nov  1 11:30:39 LiVES-devel pulseaudio[9066]: protocol-native.c: SHM
possible: yes
Nov  1 11:30:39 LiVES-devel pulseaudio[9066]: protocol-native.c:
Negotiated SHM: yes
Nov  1 11:30:39 LiVES-devel pulseaudio[9066]:
module-augment-properties.c: Looking for .desktop file for
lt-lives-exe
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: module-intended-roles.c:
Not setting device for stream LiVES_audio_out, because it lacks role.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: module-stream-restore.c:
Not restoring volume for sink input
sink-input-by-application-id:LiVES, because already set.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink.c: Suspend cause of
sink combined is 0x0000, resuming
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: module-stream-restore.c:
Not restoring device for stream sink-input-by-media-role:filter,
because already set.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: module-intended-roles.c:
Not setting device for stream Simultaneous output on Internal Audio
Analog Stereo, because already set.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink.c: Suspend cause of
sink alsa_output.pci-0000_00_14.5.analog-stereo is 0x0000, resuming
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: reserve-wrap.c:
Successfully acquired reservation lock on device 'Audio0'
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Trying resume...
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-util.c: Maximum hw
buffer size is 341 ms
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-util.c: Set buffer
size first, period size second.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: hwbuf_unused=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: setting
avail_min=15424
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Resumed
successfully...
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Starting playback.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_14.5.analog-stereo becomes idle, timeout in 5
seconds.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_14.5.analog-stereo becomes busy.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: resampler.c: Using
resampler 'trivial'
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: resampler.c: Using s16le
as working format.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1
maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0,
minreq=4 maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c: Created
input 1 "Simultaneous output on Internal Audio Analog Stereo" on
alsa_output.pci-0000_00_14.5.analog-stereo with sample spec s16le 2ch
48000Hz and channel map front-left,front-right
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
media.name = "Simultaneous output on Internal Audio Analog Stereo"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
media.role = "filter"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
module-stream-restore.id = "sink-input-by-media-role:filter"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Requested
volume: 0:  55% 1:  55%
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Got
hardware volume: 0:  56% 1:  56%
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Calculated
software volume: 0:  97% 1:  97% (accurate-enough=no)
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Cutting
sleep time for the initial iterations by half.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Latency set
to 200.00ms
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: hwbuf_unused=27136
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: setting
avail_min=15425
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Requesting
rewind due to latency change.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Requested
to rewind 65536 bytes.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Limited to
61188 bytes.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: before: 15297
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: after: 15297
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Rewound 61188 bytes.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink.c: Processing rewind...
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: source.c: Processing rewind...
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: core-subscribe.c:
Dropped redundant event due to change event.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: module-combine.c:
Resumed successfully...
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink combined becomes idle, timeout in 5
seconds.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink combined becomes busy.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1
maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0,
minreq=4 maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c: Created
input 2 "LiVES_audio_out" on combined with sample spec s16le 2ch
48000Hz and channel map front-left,front-right
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.icon_name = "LiVES"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.id = "LiVES"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.name = "LiVES"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.binary = "lt-lives-exe"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.id = "9102"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.version = "1.1.6-svn"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.language = "en-us"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
media.name = "LiVES_audio_out"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
native-protocol.peer = "UNIX socket client"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
native-protocol.version = "16"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.user = "gabriel"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.host = "LiVES-devel"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
window.x11.display = ":0.0"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.machine_id = "57d37d93ddd203a5191d123f490bccdb"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
application.process.session_id =
"57d37d93ddd203a5191d123f490bccdb-1257084780.801673-1924125055"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: sink-input.c:
module-stream-restore.id = "sink-input-by-application-id:LiVES"
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: protocol-native.c:
Requested tlength=20.02 ms, minreq=20.00 ms
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: protocol-native.c:
Adjust latency mode enabled, configuring sink latency to half of
overall latency.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
requested: maxlength=4194304, tlength=46080, base=4, prebuf=42244,
minreq=3840 maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: memblockq.c: memblockq
sanitized: maxlength=4194304, tlength=46080, base=4, prebuf=42244,
minreq=3840 maxrewind=0
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: protocol-native.c: Final
latency 440.00 ms = 200.00 ms + 2*20.00 ms + 200.00 ms
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: core-subscribe.c:
Dropped redundant event due to change event.
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: reserve-wrap.c: Device
lock status of reserve-monitor-wrapper at Audio0 changed: not busy
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Underrun!
Nov  1 11:30:40 LiVES-devel pulseaudio[9066]: alsa-sink.c: Increasing
wakeup watermark to 30.00 ms
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: module-combine.c:
[alsa_output.pci-0000_00_14.5.analog-stereo] total=199.68ms
sink=199.68ms
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: module-combine.c:
[combined] avg total latency is 199.68 msec.
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: module-combine.c:
[combined] target latency is 199.68 msec.
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: module-combine.c:
[alsa_output.pci-0000_00_14.5.analog-stereo] new rate is 48000 Hz;
ratio is 1.000; latency is 199681 usec.
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink combined becomes idle, timeout in 5
seconds.
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink combined becomes idle, timeout in 5
seconds.
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: sink-input.c: Freeing
input 2 "LiVES_audio_out"
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: client.c: Freed 4 "LiVES"
Nov  1 11:30:45 LiVES-devel pulseaudio[9066]: protocol-native.c:
Connection died.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink combined idle for too long, suspending
...
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: sink.c: Suspend cause of
sink combined is 0x0004, suspending
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Requested
volume: 0:  55% 1:  55%
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Got
hardware volume: 0:  56% 1:  56%
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Calculated
software volume: 0:  97% 1:  97% (accurate-enough=no)
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: hwbuf_unused=0
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: setting
avail_min=14944
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Requested
to rewind 65536 bytes.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Limited to
20712 bytes.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: before: 5178
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: after: 5178
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: alsa-sink.c: Rewound 20712 bytes.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: sink.c: Processing rewind...
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: source.c: Processing rewind...
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_14.5.analog-stereo becomes idle, timeout in 5
seconds.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_14.5.analog-stereo becomes idle, timeout in 5
seconds.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: core.c: Hmm, no streams
around, trying to vacuum.
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: sink-input.c: Freeing
input 1 "Simultaneous output on Internal Audio Analog Stereo"
Nov  1 11:30:50 LiVES-devel pulseaudio[9066]: module-combine.c: Device
suspended...
Nov  1 11:30:55 LiVES-devel pulseaudio[9066]:
module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_14.5.analog-stereo idle for too long,
suspending ...
Nov  1 11:30:55 LiVES-devel pulseaudio[9066]: sink.c: Suspend cause of
sink alsa_output.pci-0000_00_14.5.analog-stereo is 0x0004, suspending
Nov  1 11:30:55 LiVES-devel pulseaudio[9066]: alsa-sink.c: Device suspended...
Nov  1 11:30:55 LiVES-devel pulseaudio[9066]: reserve-wrap.c: Device
lock status of reserve-monitor-wrapper at Audio0 changed: not busy
Nov  1 11:30:55 LiVES-devel pulseaudio[9066]: module-udev-detect.c:
/dev/snd/controlC0 is accessible: yes
Nov  1 11:32:03 LiVES-devel pulseaudio[9066]: client.c: Created 5
"EsounD client (UNIX socket client)"








Application code can be viewed at:
http://lives.svn.sourceforge.net/viewvc/lives/trunk/src/pulse.c?view=markup

relevant functions:
lives_pulse_init()
pulse_driver_activate()

pulse_close_client()
pulse_shutdown()



During "playback", when no callbacks are being called, I see the
following in syslog:

Nov  1 11:47:49 LiVES-devel pulseaudio[9783]: module-combine.c:
[alsa_output.pci-0000_00_14.5.analog-stereo] total=199.66ms
sink=199.66ms
Nov  1 11:47:49 LiVES-devel pulseaudio[9783]: module-combine.c:
[combined] avg total latency is 199.66 msec.
Nov  1 11:47:49 LiVES-devel pulseaudio[9783]: module-combine.c:
[combined] target latency is 199.66 msec.
Nov  1 11:47:49 LiVES-devel pulseaudio[9783]: module-combine.c:
[alsa_output.pci-0000_00_14.5.analog-stereo] new rate is 48000 Hz;
ratio is 1.000; latency is 199656 usec







Also, strace during a non-connected session looks like this:

ppoll([{fd=5, events=POLLIN}, {fd=41, events=POLLIN}, {fd=10,
events=POLLIN}, {fd=7, events=POLLIN}, {fd=21, events=POLLIN}, {fd=27,
events=POLLIN}, {fd=33, events=POLLIN}, {fd=36, events=POLLIN},
{fd=32, events=POLLIN}, {fd=31, events=POLLIN}, {fd=30,
events=POLLIN}, {fd=29, events=POLLIN|POLLERR|POLLHUP}, {fd=29,
events=0}, {fd=23, events=POLLIN}, {fd=26, events=POLLIN}, {fd=17,
events=POLLIN}, {fd=20, events=POLLIN}, {fd=16,
events=POLLIN|POLLERR|POLLHUP}, {fd=16, events=0}, {fd=15,
events=POLLIN}, {fd=14, events=POLLIN}, {fd=8, events=POLLIN}], 22,
{2, 73725946}, NULL, 8) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {2221, 407606659}) = 0
clock_gettime(CLOCK_MONOTONIC, {2221, 407640463}) = 0
clock_gettime(CLOCK_MONOTONIC, {2221, 407668679}) = 0



This scrolls up very slowly. When LiVES is connected it goes much
faster and there is one poll() per clock_gettime(). I cant get this
right now because of the test I did with amaroK.


Any clues here ?

Gabriel.
http://lives.sourceforge.net

More information about the pulseaudio-discuss mailing list