Bug 12909 - Improve sync
: Improve sync
Status: CLOSED FIXED
Product: SqueezePlay
Classification: Unclassified
Component: Audio
: unspecified
: PC Windows XP
: P1 normal (vote)
: 7.4.0
Assigned To: Alan Young
:
Depends on:
Blocks: 10823 11506
  Show dependency treegraph
 
Reported: 2009-07-17 02:20 UTC by Richard Titmuss
Modified: 2009-10-05 14:26 UTC (History)
2 users (show)

See Also:
Category: Bug


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Richard Titmuss 2009-07-17 02:20:06 UTC
Richard T.	
i don't know if you followed my changes, but basically i've had to split the alsa loop into a separate thread.
this means in the Decode:stauts() when it calls to get the playtime that value will be wrong.
(as that process does not have the device open).
Alan Y.	
A separate process even? But no, I've not really been following.
Richard T.	
right, sorry that's what i meant.
Alan Y.	
Incidentally - why did it need a separate process?
Richard T.	
also (but i need to double check) the playtime will only be reported to the period size due to hardware limitation, so at the moment that's 10000
Alan Y.	
What does that mean? Is that the resolution? What units?
Richard T.	
due to the inner workings of linux, a real-time pthread can still block based on the non real-time part of the process.
us i think.
ms
good question, one minute...
441 frames
2:00 AM
Alan Y.	
= 10ms?
Richard T.	
yes, i think that's right.
Alan Y.	
That is pretty terrible.
Richard T.	
so i think we need to record the playpoint and hi-res time in the alsa process.
Alan Y.	
yes
Richard T.	
then in the status call, use the current hi-res time, and predict where the playpoint will be now.
with the changes i've made that should be reliable. but still +/- 10ms i guess.
Alan Y.	
no, just use the tuple reported from the hi-res thread
Richard T.	
what accuracy do you need it reporting to?
k
Alan Y.	
hold on .. let me think
yes, using the tupe (playpoint, timestamp) from the also thread would be best. It does not matter that it gets reported some time later
Richard T.	
another idea would be to mod the kernel, so it records when the dma buffer is filled.
ok, that's easy.
Alan Y.	
but it needs to be reasonably fresh - I'll just check how much
2:05 AM
Alan Y.	
so long as it is less then 2s old then that will be fine
Richard T.	
at the moment i'm updating that value every 10ms (each time the loop fills the buffer). much more frequently than the decode status is called.
k
so what error do i need to work within?
i should now be possible to reduce the period time, but that'll increase cpu usage, so that's a performance trade off.
Alan Y.	
At +/-10ms we need to use smoothing on the playpoinst, so we cannot do accurate/instant track-start sync
I see CPU use as being quite tight sometimes. I would be wary of pushing that tradeoff.
How much data will be in the DMA buffers?
Richard T.	
sure.
once they are full, 3 * period_size, so at the moment 30ms
Alan Y.	
Ah. And the alsa driver cannot enquire as to how full they are?
Richard T.	
let me double check that...
Alan Y.	
Is there more buffering after DMA - if so how big?
Richard T.	
14 samples
2:10 AM
Richard T.	
that's 14 L/R samples, to 7 frames
Alan Y.	
ok, irrelevant
even (just about) at 11025
Richard T.	
i don't think we can get any status from the dma.
it run in it's own risk core, so it could be reprogrammed to do that, but we don't have the tools.
also on baby the dma was one of the channel swapping problems, so i'd be cautions about changing that.
Alan Y.	
So we just know when it is empty, or when it reaches a specific watermark
Richard T.	
when it reaches a watermark.
well there are three buffers, so when a buffer is empty.
Alan Y.	
so we could record the tuple then
Richard T.	
right.
Alan Y.	
just looking at some code ...
Richard T.	
processing the dma is the highest priority RT thread, so that should be pretty accurate.
2:15 AM
Alan Y.	
I cannot find it right now, but isn't there supposed to be an also API call to get the time/samples played?
David S.	
has left the room
Richard T.	
in alsa?
i've seen the code in the driver and that just reports the last buffer position the dma buffer was filled.
that's why i think the accuracy will only be +/- 10 ms
Comment 1 Alan Young 2009-07-17 02:28:17 UTC
I was thinking of snd_pcm_status_get_delay() and, as I suspected, it returns only the delay(in frames) and not the time at which it was valid.

I guess you could make it accurate by internally recording the (playpoint, time) tuple when the DMA buffer is filled and then adjusting the returned value to take into account the current time.

Or you could just add your own API function to return the saved tuple; that would be good enough for us.
Comment 2 Alan Young 2009-07-17 02:56:48 UTC
We need to ensure that the manipulation of decode_audio->elapsed_samples (due to strm-a, strm-p and strm-u times and intervals) is taken into account.
Comment 3 Alan Young 2009-07-17 03:09:29 UTC
Don't forget bug 10823.
Comment 4 Alan Young 2009-07-17 03:10:39 UTC
The current (old) code does not seem to good at honouring the srtm-u(jiffies) start-at functionality, usually starting 50-60ms late.
Comment 5 Alan Young 2009-07-17 03:11:41 UTC
... but fixing the accurate playpoints would make that much less of an issue.
Comment 6 Richard Titmuss 2009-07-22 12:12:21 UTC
*** Bug 11879 has been marked as a duplicate of this bug. ***
Comment 7 Richard Titmuss 2009-07-30 03:55:32 UTC
*** Bug 10496 has been marked as a duplicate of this bug. ***
Comment 8 James Richardson 2009-08-12 08:49:58 UTC
*** Bug 11506 has been marked as a duplicate of this bug. ***
Comment 9 SVN Bot 2009-08-14 07:23:08 UTC
 == Auto-comment from SVN commit #7079 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7079 ==

Bug #12909
Fix race condition that could prevent tracks starting when sync'd, but also seen with 
non-sync'd AAC.
Comment 10 SVN Bot 2009-08-14 10:08:56 UTC
 == Auto-comment from SVN commit #7084 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7084 ==

Bug #12909
Improve accuracy of playpoint on SP players using alsa.
Comment 11 SVN Bot 2009-08-14 13:36:02 UTC
 == Auto-comment from SVN commit #7090 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7090 ==

Bug #12909
Change from SDL_GetTicks() to jive_jiffies(). This allows a single time epoch to be 
shared between the main and alsa backend processes.
Comment 12 SVN Bot 2009-08-14 13:43:01 UTC
 == Auto-comment from SVN commit #7091 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7091 ==

Bug #12909
Fix compile error.
Comment 13 SVN Bot 2009-08-14 13:48:10 UTC
 == Auto-comment from SVN commit #7092 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7092 ==

Bug #12909
Fix compile error.
Comment 14 Richard Titmuss 2009-08-14 14:00:47 UTC
Alan, please re-test after these changes.
Comment 15 SVN Bot 2009-08-15 05:05:21 UTC
 == Auto-comment from SVN commit #7097 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7097 ==

bug 12909:
Try to fix problem at start of track where elapsed_milliseconds is reported as 97391538.
Comment 16 Alan Young 2009-08-15 06:43:07 UTC
Still seeing at least two problems:

1. After a seek, maybe after a skip (the same at the protocol level), I sometimes hear some period of audio from what was playing before the seek - as if the output buffers have not been fully flushed.

2. Sometimes a skip (or seek) results in a hang.

Also, the new accurate sync points are certainly better, but shouldn't the delay be obtained after stuffing the buffer, so that it and the elapsed samles are sampled at the same time. See the FIXME I put in the code. Alternatively, as we discussed on the phone, once could assume that when 'avail >= state->period_size' there is a known amount of unplayed data, and hence known delay, and the whole evaluation of sync_elapsed_samples could be done where delay_ts is currently set. Either way, it seems wrong to get the delay before stuffing the buffer and then set the elapsed samples based on what has now been added to the buffer.
Comment 17 SVN Bot 2009-08-15 08:05:44 UTC
 == Auto-comment from SVN commit #7098 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7098 ==

bug 12909: 
Introduce an explicit STOPPING state for audio so that obsolete status information can be detected and thereby avoid spurious notifications or other state changes.
Comment 18 Alan Young 2009-08-15 09:37:53 UTC
That helped, although I still sometimes get the extra 'previous' output. (item 1 from comment #16).

Collecting the jiffies to be reported in the status packet at a time earlier than the status packet is sent has the unfortunate side effect of screwing up the jiffies-epoch tracking, which is also used in sync calculations. I think that the elapsed time needs to be adjusted and the current time used when actually assembling the status packet.
Comment 19 SVN Bot 2009-08-15 10:01:56 UTC
 == Auto-comment from SVN commit #7099 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7099 ==

bug 12909: Improve sync 
Use accurate timestamp and elapsed samples from state but adjust so that reported timestamp is the actual time that the status packet is assembled.
Comment 20 Alan Young 2009-08-15 10:12:33 UTC
Short tracks are a problem because SC will send the strm-u before the player has sent STMl. This SC behaviour is to work around a bug in the ip3k players (maybe also in SP) that mean that they don't send an STMl if the threshold is not reached. Presumably the ip3k players actually send the STMl the moment the threshold is reached, rather than just on a timer as in SP. See bug 9125.
Comment 21 Alan Young 2009-08-15 10:44:19 UTC
Actually, maybe this is just because the strm-u is sent and acted on too early for the player to handle. The decoders in SP seem pretty slow to start up.

Sample logging - 2 slightly different scenarios:

Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:443 strm q
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_stop:605 decode_stop
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:443 strm s
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_start:643 decode_start
Aug 15 19:28:41 squeezeplay: INFO   audio.decode - Playback.lua:351 connect 192.168.1.11:9000 GET /stream.mp3?player=00:04:20:26:01:49 HTTP/1.0^M
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - stream_connectL:480 streambuf connect 192.168.1.11:9000
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:443 strm u
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:517 resume unpause
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_resume_audio:539 decode_resume_audio start_jiffies=297258
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_stop_handler:195 decode_stop_handler
Aug 15 19:28:41 squeezeplay: DEBUG  audio.output - decode_alsa_stop:89 decode_alsa_stop
Aug 15 19:28:41 squeezeplay: INFO   audio.decode - decode_start_handler:273 init decoder mp3
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:604 Track gain 65536
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:608 Track clip range 7fffffff 80000000
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_set_track_polarity_inversion:613 Polarity inversion 0
Aug 15 19:28:41 squeezeplay: DEBUG  audio.output - decode_alsa_start:56 decode_alsa_start
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:129 decode_resume_audio_handler start_interval=36
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:147 resume_audio decode state: 0 audio state 0
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:28:41 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - Playback.lua:370 disconnect streambuf
Aug 15 19:28:42 squeezeplay: DEBUG  audio.decode - Playback.lua:307 status FULL

Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:443 strm s
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_start:643 decode_start
Aug 15 19:29:15 squeezeplay: INFO   audio.decode - Playback.lua:351 connect 192.168.1.11:9000 GET /stream.mp3?player=00:04:20:26:01:49 HTTP/1.0^M
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - stream_connectL:480 streambuf connect 192.168.1.11:9000
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:370 disconnect streambuf
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:280 resume decoder
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:518 decode_resume_decoder
Aug 15 19:29:15 squeezeplay: INFO   audio.decode - decode_start_handler:273 init decoder mp3
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:604 Track gain 65536
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:608 Track clip range 7fffffff 80000000
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_set_track_polarity_inversion:613 Polarity inversion 0
Aug 15 19:29:15 squeezeplay: DEBUG  audio.output - decode_alsa_start:56 decode_alsa_start
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:114 resume_decoder decode state: 1 audio state 0
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:443 strm u
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - Playback.lua:517 resume unpause
Aug 15 19:29:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio:539 decode_resume_audio start_jiffies=331422
Aug 15 19:29:16 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:129 decode_resume_audio_handler start_interval=0
Aug 15 19:29:16 squeezeplay: DEBUG  audio.decode - debug_fullness:104 fullness: 3.30% / 0.00%
Aug 15 19:29:16 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:147 resume_audio decode state: 1 audio state 0
Aug 15 19:29:16 squeezeplay: DEBUG  audio.decode - Playback.lua:307 status FULL
Aug 15 19:29:17 squeezeplay: DEBUG  audio.decode - decode_output_remove_padding:523 Removing 11808 bytes padding from buffer
Aug 15 19:29:17 squeezeplay: DEBUG  audio.decode - Playback.lua:208 status DECODE UNDERRUN
Aug 15 19:29:17 squeezeplay: DEBUG  audio.decode - decode_song_ended:713 decode_sond_ended
Aug 15 19:29:17 squeezeplay: DEBUG  audio.decode - Playback.lua:307 status FULL
Aug 15 19:29:17 squeezeplay: DEBUG  audio.decode - decode_song_ended_handler:314 decode_song_ended_handler
Comment 22 Alan Young 2009-08-16 00:20:39 UTC
Updating hours worked
Comment 23 Alan Young 2009-08-16 00:29:04 UTC
Richard, I took the liberty of adding a few hours for this remaining short-track problem.
Comment 24 Alan Young 2009-08-16 05:27:16 UTC
I can reproduce the problem of the previous stream being played when skipping. One needs to be in STREAMOUT state  - that is, the streaming connection has been closed already. You can actually accumulate multiple pieces of previous tracks this way.
Comment 25 Alan Young 2009-08-16 13:50:37 UTC
Yes, the decode buffer is not getting flushed upon strm-q if the end of stream has already occurred (streaming connection finished).

The problem is that Playback.lua::_streamDisconnect() gets called by _streamRead() at the end of the stream. Then, when strm-q is received, and the handler calls _streamDisconnect(nil, true), then the first statement does a short-circuit return because self.stream is already nil (from the call at the end of stream).

The same problem problem probably also occurs with flush (strm-f), which does not seem to call _streamDisconnect() at all, although the subsequent strm-s will cause it to be called. I think that it should call streamDisconnect().

My guess is that the stop and flush handlers in decode.c should both call streambuf_flush.
Comment 26 SVN Bot 2009-08-17 08:33:55 UTC
 == Auto-comment from SVN commit #7111 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7111 ==

bug 12909: Improve sync 
Make streambuf_flush a static Lua class method (on Stream).
Ensure it is called in _streamDisconnect() even when the stream is already disconnected.
Make the strm-f handler also call _streamDisconnect(), and consequently send an STMf confirmation.
Comment 27 Alan Young 2009-08-18 06:55:16 UTC
I have a couple of possible solutions to the short-track start problem.

I think that the best is to introduce a new AUTOSTART audio state. Pretty simple. Somewhere near the start of the output callback() method one would have:

if (decode_audio->state & DECODE_STATE_AUTOSTART
	&& bytes_used >=  len)
{
	decode_audio->state &= ~DECODE_STATE_AUTOSTART;
	decode_audio->state |= DECODE_STATE_RUNNING;
}

It would also be possible do something in the Lua code but that would be less elegant.
Comment 28 Alan Young 2009-08-18 07:19:09 UTC
I've thought of another problem, I think. Because the ALSA buffer is kept stuffed with silence, then a track will actually begin at an indeterminate time (0 .. the period of the ALSA buffer) later than expected.

On the other hand, because ip3k players do not decode while paused (or before the decoder buffer threshold is reached for autostart), they will actually start playing some non-zero period after processing the strm-u, this period being variable depending upon the codec and the player type. This is probably why, at least in part, ip3k players always have to do a skip-ahead just after starting.

Perhaps it is not worth worrying about either of these because: (a) this only happens at the start of the 'first' track; (b) it will often be unnoticeable because it will be corrected before the first audio is audible because of the initial silence on most tracks.
Comment 29 SVN Bot 2009-08-18 09:44:03 UTC
 == Auto-comment from SVN commit #7132 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7132 ==

bug 12909: Improve sync 
Deal with synchronized startup of short tracks:
Introduce a new audio state AUTOSTART and use this to mean that the output stage should start up
as soon as it has sufficient decoded data. 
This way we can cope with getting the strm-u before having sent the STMl.
Avoiding sending the STMl in this case.
Comment 30 Alan Young 2009-08-18 09:46:43 UTC
Still more to do.
Comment 31 SVN Bot 2009-08-18 10:36:33 UTC
 == Auto-comment from SVN commit #7135 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7135 ==

bug 12909: Improve sync 
I don't think that a single period was sufficient.
Comment 32 Alan Young 2009-08-19 00:45:20 UTC
This short-track stuff is really getting to me now. Even without sync it does not work properly.

It seems to either not generate or lose the decoder-underrun state.

At first I came to the conclusion that the logic was generating multiple decode:redumeDecode() calls and that at least one of these was actually being processed after the underrun had occurred and thereby resetting the state to running. So, I added a self.sendResumeDecode flag to the Playback.lua state to ensure that this call only happens once (not checked in). Looking at the audio.decode debug log output confirms that this is now correct.

But I still never see a decoder-underrun state. I just don't get it.
Comment 33 Richard Titmuss 2009-08-19 01:51:22 UTC
(In reply to comment #16)
> Also, the new accurate sync points are certainly better, but shouldn't the
> delay be obtained after stuffing the buffer, so that it and the elapsed samles
> are sampled at the same time. See the FIXME I put in the code. Alternatively,
> as we discussed on the phone, once could assume that when 'avail >=
> state->period_size' there is a known amount of unplayed data, and hence known
> delay, and the whole evaluation of sync_elapsed_samples could be done where
> delay_ts is currently set. Either way, it seems wrong to get the delay before
> stuffing the buffer and then set the elapsed samples based on what has now been
> added to the buffer.

I think the way the kernel driver tracks the delay that the snd_pcm_status_get_delay() would be the same anywhere while stuffing the audio buffer.

The kernel code is:
	offset = (runtime->period_size * (prtd->periods));
	if (offset >= runtime->buffer_size)
		offset = 0;

Where runtime->period_size is fixed, and prtd->periods is ++/%= in the irq handler. This is the count of the number of dma buffers queued. So snd_pcm_status_get_delay() will only return a different value after each irq. The code that stuffs the audio will run once after each irq.

If snd_pcm_status_get_delay() could return a more accurate value, it should actually be called after the snd_pcm_mmap_commit().
Comment 34 Richard Titmuss 2009-08-19 01:59:27 UTC
(In reply to comment #32)
> This short-track stuff is really getting to me now. Even without sync it does
> not work properly.

I'm seeing this problem with all tracks not sync'd since around the DECODE_STOPPING change. I'm surprised I've not seen any forum comments about this (but I guess the fab4 builds are broken, and baby has not been pushed since that change).

I'm looking into this now...
Comment 35 SVN Bot 2009-08-19 02:34:52 UTC
 == Auto-comment from SVN commit #7141 to the jive repo by richard ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7141 ==

Bug #12909
Fix decoder underrun events.
Comment 36 Richard Titmuss 2009-08-19 02:36:04 UTC
(In reply to comment #32)
> But I still never see a decoder-underrun state. I just don't get it.

That was exactly the problem. A recent change to improve Internet Radio suggested by triode broke track playback. Fixed the non-sync case. You should try with sync again now.
Comment 37 Richard Titmuss 2009-08-19 02:40:22 UTC
(In reply to comment #28)
> I've thought of another problem, I think. Because the ALSA buffer is kept
> stuffed with silence, then a track will actually begin at an indeterminate time
> (0 .. the period of the ALSA buffer) later than expected.
> 
> On the other hand, because ip3k players do not decode while paused (or before
> the decoder buffer threshold is reached for autostart), they will actually
> start playing some non-zero period after processing the strm-u, this period
> being variable depending upon the codec and the player type. This is probably
> why, at least in part, ip3k players always have to do a skip-ahead just after
> starting.

I think the SP case will be more deterministic, as the buffer size does not change. For ip3k it'll vary slightly depending on the decoder, and track.

> Perhaps it is not worth worrying about either of these because: (a) this only
> happens at the start of the 'first' track; (b) it will often be unnoticeable
> because it will be corrected before the first audio is audible because of the
> initial silence on most tracks.

Right, I don't think we should worry about this case now. Let see if it is often a real (audible) problem.
Comment 38 Alan Young 2009-08-19 03:58:12 UTC
(In reply to comment #36)
> (In reply to comment #32)
> > But I still never see a decoder-underrun state. I just don't get it.
> 
> That was exactly the problem. A recent change to improve Internet Radio
> suggested by triode broke track playback. Fixed the non-sync case. You should
> try with sync again now.

Great. I still think that I should add my uncommitted change to track having done a decode:resumeDecoder.
Comment 39 Alan Young 2009-08-19 04:31:54 UTC
(In reply to comment #33)

> I think the way the kernel driver tracks the delay that the
> snd_pcm_status_get_delay() would be the same anywhere while stuffing the audio
> buffer.
> 
> The kernel code is:
>     offset = (runtime->period_size * (prtd->periods));
>     if (offset >= runtime->buffer_size)
>         offset = 0;
> 
> Where runtime->period_size is fixed, and prtd->periods is ++/%= in the irq
> handler. This is the count of the number of dma buffers queued. So
> snd_pcm_status_get_delay() will only return a different value after each irq.
> The code that stuffs the audio will run once after each irq.
> 
> If snd_pcm_status_get_delay() could return a more accurate value, it should
> actually be called after the snd_pcm_mmap_commit().

I interpret the above to read that the delay will be accurate at the start of the loop, as prtd->periods should be just about accurate at that point. Therefore, setting the sync_elapsed_samples before the first call to playback_callback() (for each stuffing exercise) should yield the best results. I'll do that, without needing to take the audio lock another time.

I'm hoping that this will solve the 10-20ms offset problem.

Really, the snd_pcm_status_get_delay() call should actually interrogate the current state of the number of queued buffers, and even the current state of partially transferred ones, but we do not need to go there.
Comment 40 SVN Bot 2009-08-19 08:36:05 UTC
 == Auto-comment from SVN commit #7149 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7149 ==

bug 12909: Improve sync 
Track invocations of decode:resumeDecoder and decode:resumeAudio to avoid duplicates.
Comment 41 SVN Bot 2009-08-19 08:45:04 UTC
 == Auto-comment from SVN commit #7150 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7150 ==

bug 12909: Improve sync 
Improve accuracy of play-point.
Comment 42 SVN Bot 2009-08-19 23:34:52 UTC
 == Auto-comment from SVN commit #28227 to the slim repo by ayoung ==
 == https://svn.slimdevices.com/slim?view=revision&revision=28227 ==

bug 12909: Improve sync 
Make sure setStatus is used in Song.
Comment 43 SVN Bot 2009-08-19 23:40:54 UTC
 == Auto-comment from SVN commit #28228 to the slim repo by ayoung ==
 == https://svn.slimdevices.com/slim?view=revision&revision=28228 ==

bug 12909: Improve sync 
Fix test for stream too many simultaneous tracks.
Comment 44 Alan Young 2009-08-20 01:10:00 UTC
(In reply to comment #41)

>  == https://svn.slimdevices.com/jive?view=revision&revision=7150 ==
> 
> Improve accuracy of play-point.

This seems to have done the trick.
Comment 45 Alan Young 2009-08-20 01:17:37 UTC
Now we need to set the AccuratePlayPoints capability for fab4 and baby.
Comment 46 SVN Bot 2009-08-20 10:33:14 UTC
 == Auto-comment from SVN commit #7178 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7178 ==

bug 12909: Improve sync 
Tell SC that our play-points are accurate.
Comment 47 SVN Bot 2009-08-21 01:54:14 UTC
 == Auto-comment from SVN commit #7188 to the jive repo by ayoung ==
 == https://svn.slimdevices.com/jive?view=revision&revision=7188 ==

bug 12909: Improve sync 
Add accurate play-points for portaudio backend. It compiles but is otherwise untested as the portaudio backend does not really work at the moment.
Comment 48 Alan Young 2009-08-21 02:07:45 UTC
I'm done with this now. I think that there may still be some problems with sequences of very short tracks (< 10s) and I am not convinced that fab4 is quite solid but we can open new bugs for those if needed.
Comment 49 James Richardson 2009-10-05 14:26:33 UTC
This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server!
    * SqueezeCenter: 28672
    * Squeezebox 2 and 3: 130
    * Transporter: 80
    * Receiver: 65
    * Boom: 50
    * Controller: 7790
    * Radio: 7790  

Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes

If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.