Bugzilla – Bug 13848
Improve audio startup time
Last modified: 2016-11-27 21:11:10 UTC
Alan pointed out that SP takes longer than ip3k to start music. I noticed that removing the Playback "status.outputTime > 50" check make audio start much faster. Richard points out that a) the check is there to avoid stuttering, and b) that there is something else underlying that is creating an unneeded delay.
== Auto-comment from SVN commit #7439 to the jive repo by richard == == https://svn.slimdevices.com/jive?view=revision&revision=7439 == Bug #13848 Add debug to capture audio start times.
I've added extra logging to help diagnose this. Enable audio.decode and audio.output logging to see the useful events. Here is an example with mp3: 20090907 21:13:10.002 DEBUG audio.decode - Playback.lua:475 strm q 20090907 21:13:10.007 DEBUG audio.decode - Playback.lua:704 stopping local pause timer 20090907 21:13:10.010 DEBUG audio.decode - decode_stop:613 decode_stop 20090907 21:13:10.013 DEBUG audio.decode - Playback.lua:397 flush streambuf 20090907 21:13:10.033 DEBUG audio.decode - decode_stop_handler:194 decode_stop_handler 20090907 21:13:10.037 DEBUG audio.output - decode_alsa_stop:89 decode_alsa_stop 20090907 21:13:10.057 DEBUG audio.decode - Playback.lua:704 stopping local pause timer 20090907 21:13:10.060 DEBUG audio.decode - Playback.lua:682 gainL, gainR: 658 658 20090907 21:13:10.090 DEBUG audio.decode - Playback.lua:475 strm s 20090907 21:13:10.093 DEBUG audio.decode - Playback.lua:397 flush streambuf 20090907 21:13:10.107 DEBUG audio.decode - decode_start:651 decode_start * 20090907 21:13:10.111 INFO audio.decode - Playback.lua:380 connect 192.168.1.1:9000 GET /stream.mp3?player=00:04:20:08:06:1e HTTP/1.0 20090907 21:13:10.116 DEBUG audio.decode - stream_connectL:480 streambuf connect 192.168.1.1:9000 20090907 21:13:10.151 DEBUG audio.decode - Playback.lua:704 stopping local pause timer 20090907 21:13:10.154 DEBUG audio.decode - Playback.lua:682 gainL, gainR: 658 658 * 20090907 21:13:10.221 DEBUG audio.decode - Playback.lua:297 resume decoder 20090907 21:13:10.226 DEBUG audio.decode - decode_resume_decoder:526 decode_resume_decoder 20090907 21:13:10.533 INFO audio.decode - decode_start_handler:272 init decoder mp3 20090907 21:13:10.536 DEBUG audio.decode - decode_output_set_track_gain:606 Track gain 65536 20090907 21:13:10.539 DEBUG audio.decode - decode_output_set_track_gain:610 Track clip range 7fffffff 80000000 20090907 21:13:10.542 DEBUG audio.decode - decode_set_track_polarity_inversion:615 Polarity inversion 0 20090907 21:13:10.549 DEBUG audio.output - decode_alsa_start:56 decode_alsa_start 20090907 21:13:10.552 DEBUG audio.decode - decode_resume_decoder_handler:115 resume_decoder decode state: 1 audio state 0 20090907 21:13:10.554 DEBUG audio.decode - debug_fullness:105 fullness: 18.75% / 0.00% * 20090907 21:13:11.049 DEBUG audio.decode - decode_output_samples:385 first buffer sample_rate=44100 20090907 21:13:11.106 DEBUG audio.decode - Playback.lua:329 resume audio bytesReceivedL=872400 outputTime=183 threshold=261120 20090907 21:13:11.109 DEBUG audio.decode - decode_resume_audio:547 decode_resume_audio start_jiffies=0 20090907 21:13:11.136 DEBUG audio.decode - decode_resume_audio_handler:130 decode_resume_audio_handler start_interval=0 20090907 21:13:11.138 DEBUG audio.decode - debug_fullness:105 fullness: 29.86% / 1.84% 20090907 21:13:11.141 DEBUG audio.output - decode_alsa_resume:67 decode_alsa_resume 20090907 21:13:11.144 DEBUG audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40 * 20090907 21:13:11.145 DEBUG playback_callback:412 playback started, copyright not asserted 20090907 21:13:11.166 DEBUG audio.decode - Playback.lua:280 status TRACK STARTED Interesting items are marked with a *, they are: 1. http stream connection is made 2. decoder starts 3. first samples of stream are queued in output buffer 4. samples are queued in alsa buffer Removing the "status.outputTime > 50" check saves the time between steps 3 and 4. For local mp3 playback this is usually around .1 seconds. Tom what did you measure this change on? I don't see it would make that bigger impact?
I also do not understand why startup should be so slow with the timer on a 100ms interval. The trace does not seem to explain that. However, the AUTOSTART state that I introduced for audio may mean that the 50ms check is actually not necessary any more, as the output thread will wait for decoded data being available before starting and will not get an underrun. It only waits for one period of data being available (that could easily be tweaked) but my guess is that that is not important. Nonetheless, that would only solve the unsynchronized case. It is still the case that whatever is causing this issue would still lead to slower synchronized startup, as the STMl would still be delayed.
(In reply to comment #2) > Removing the "status.outputTime > 50" check saves the time between steps 3 and > 4. For local mp3 playback this is usually around .1 seconds. > > Tom what did you measure this change on? I don't see it would make that bigger > impact? Hmm, I had tested this on desktop. There the change made the track come up nearly instantly. When I just tried the change on baby, it does not seem to have the same impact....
I've looked at the logging on Baby and played about with the parameters a bit. I think that we are seeing a couple of effects here: (a) Baby is CPU-challenged at track-start time. (b) The thread context-switching and scheduling does not seem to be very snappy. I get the impression that the Playback.lua timer sometimes runs quit a bit later than scheduled (over 100ms late on occasions). The consequence are that decode startup actually is pretty slow. This can then be compounded by (b) not allowing audio-startup as soon as it should. I guess that a single period for AUTOSTART may not be sufficient but 5 periods should be sufficient, and in effect the same as the 50ms check from Playback.lua. I'll make that change. It will still not be as snappy as we might like but it could improve things quite a bit much of the time.
== Auto-comment from SVN commit #7512 to the jive repo by ayoung == == https://svn.slimdevices.com/jive?view=revision&revision=7512 == bug 13848: Improve audio startup time Give autostart in the ALSA backend thread a bit more leeway by making sure a few more periods worth of sample are ready before starting. In Playback.lua, do not wait for 50ms of output to be ready before starting the audio, as the autostart feature will take care of that.
There may still be some more that can be done by tweaking thread priorities.
Even after Richard's changes in https://svn.slimdevices.com/jive?view=revision&revision=7523 it is still pretty slow: too slow for the default synchronized startup time of 100ms - more like 350ms typically. I have not tried to track it down yet.
passing back to richard.
Update hours
Changing priorities due to management guidance.