[Announce] Community Firmware for Squeezebox Radio/Touch/Controller and LMS 8

[mrw]

I am not sure if this belongs here, so it it belongs somewhere else, let me know.

I have an SB Radio on firmware 8.0.1-r16835. When I returned to my office, one of my Red Radio's wifi had the red symbol so it was not connected. My other Back Radio four feet away was fine. I have had some recent trouble with the Red Radio radio seeing SSIDs. (The problem may be different that the disconnection problem that occurs in Radios due to interference as the Black Radio has not had any problems.) I wanted to try repair network prior to a reboot. The Red Radio got stuck on "repair network". After 15 minutes I tried to cancel with a long press of the home or power button, but it would not cancel its attempt. I had to unplug and remove the battery to reboot. Upon rebooting, Red saw my wifi network and connected again.

The issue that might be a firmware related is if the Radio gets stuck and the ability of a long press of the home button to be an escape.

Paul

I think I may have determined one possible cause of this particular behaviour.

I find that, if the Radio does not have a currently configured network, an attempt to "Repair Network" (under "Network Health") will yield the symptoms you describe (never ending spinny). Although, in my case, a good longish press of the power button did cause the Radio to restart.

In these circumstances, a look at "Check Network" first would have shown "No network interface". Unfortunately "Repair Network" fails to check that fact before doing its thing, and sends the Radio off into la-la land.

That does not tell us why your Radio found itself without a currently configured network. In my case it was the result of a failure to establish a wi-fi connection with a test access point I have been running. I would guess that it is related in some way to the wi-fi connectivity issues you are having.

This bug is present in both the stock firmware and the Community release firmware.

[ralphy]

Trying this. Sometimes I think it's a bit better, and then the problem emerges. So I'm not convinced that it is the cause. It was a wild idea, really.

The "pre-roll" (first 10 seconds ? or so) is always bad, even on stock firmware.

Happy to help with a "bisect", or similar, if that would help.

After reviewing several of the other decoders, I think I've tracked down the "pre-roll" issue with the AAC decoder.

I was not "pulling" enough decoded audio samples to the output buffer for each decoded aac frame, so the output buffer was underrunning. Also took the opportunity to rearrange the buffer copy based on the number of channels to check for stereo first instead of mono. As 2 channel stereo is the most likely value, not 1 channel mono.

With the latest changes here's the log from playing the problematic stream posted by staresy.

Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_start:705 decode_start                                                                   
Feb 25 08:25:46 squeezeplay: INFO   audio.decode - decode_start_handler:281 init decoder aac                                                       
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:520 Track gain 65536                                               
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:524 Track clip range 7fffffff 80000000                             
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_set_track_polarity_inversion:529 Polarity inversion 0                                    
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_set_output_channels:537 Output channels left 0, right 0                   
Feb 25 08:25:46 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 192.168.100.22:9000 GET /stream.mp3?player=00:04:20:xx:xx:xx HTTP/1.0^M
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 192.168.100.22:9000                                       
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer                                                    
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 333 333                                                                             
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 28672 bytes buffered, decode threshold 2048                    
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder                                                 
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 1                  
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 28672 / 900416 | 0.91% / 25.52%                                    
Feb 25 08:25:46 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=44100                                        
Feb 25 08:25:46 squeezeplay: INFO   audio.decode - Playback.lua:448 4.3%/27.7%                                                                     
Feb 25 08:25:47 squeezeplay: INFO   audio.decode - Playback.lua:448 22.5%/27.5%                                                                    
Feb 25 08:25:48 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 2)                                              
Feb 25 08:25:50 squeezeplay: INFO   audio.decode - Playback.lua:448 48.7%/25.4%                                                                    
Feb 25 08:25:54 squeezeplay: INFO   audio.decode - Playback.lua:448 61.8%/44.9%                                                                    
Feb 25 08:25:55 squeezeplay: INFO   audio.decode - Playback.lua:448 82.4%/44.5%                                                                    
Feb 25 08:25:56 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/44.8%                                                                    
Feb 25 08:25:57 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/47.2%                                                                   
Feb 25 08:25:58 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/49.5%                                                                   
Feb 25 08:25:59 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/51.9%                                                                   
Feb 25 08:26:00 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/54.7%                                                                   
Feb 25 08:26:01 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/57.3%                                                                   
Feb 25 08:26:02 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/60.2%                                                                    
Feb 25 08:26:03 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/62.7%                                                                   
Feb 25 08:26:04 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/65.3%                                                                   
Feb 25 08:26:05 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/68.0%                                                                   
Feb 25 08:26:07 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/70.3%                                                                   
Feb 25 08:26:08 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/73.1%                                                                   
Feb 25 08:26:09 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/75.4%                                                                    
Feb 25 08:26:10 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/78.1%                                                                   
Feb 25 08:26:11 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/80.4%                                                                   
Feb 25 08:26:12 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/83.5%                                                  
Feb 25 08:26:13 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/86.5%                                                 
Feb 25 08:26:14 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/88.4%                                                 
Feb 25 08:26:15 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/90.7%                                                 
Feb 25 08:26:16 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/93.1%                                                 
Feb 25 08:26:17 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/96.1%                                                 
Feb 25 08:26:18 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/98.4%                                
Feb 25 08:26:19 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.5%                                       
Feb 25 08:26:20 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.5%                                       
Feb 25 08:26:21 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.4%                                       
Feb 25 08:26:22 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.1%                     
Feb 25 08:26:23 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.7%  
Feb 25 08:26:24 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.8%          
Feb 25 08:26:25 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.8%                                       
Feb 25 08:26:27 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.7%               
Feb 25 08:26:28 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.6%          
Feb 25 08:26:29 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.6%
Feb 25 08:26:30 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.9%               
Feb 25 08:26:31 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.5%
Feb 25 08:26:32 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/97.8%               
Feb 25 08:26:33 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.8%   
Feb 25 08:26:34 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.4%
Feb 25 08:26:35 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.2%               
Feb 25 08:26:36 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.4%

Previously the decode and output buffers would hardly ever fill above 1-2%.

I'd be interested to know if the changes make a difference for others. It would be good to know if Tidal aac playback is better as well, but I don't have an account.

I've uploaded a jive binary replacement with the changes.
The binary also includes support for the new Mono Output Channel Mode added to LMS 8.2, which for the radio is really only useful when using the line out/headphone jack. I just needed to confirm that the downmix changes didn't impact performance on the radio.

The tarfile also includes the patches applied to the binary as I've not committed them yet.

[expectingtofly]

I've uploaded a jive binary replacement with the changes.
The binary also includes support for the new Mono Output Channel Mode added to LMS 8.2, which for the radio is really only useful when using the line out/headphone jack. I just needed to confirm that the downmix changes didn't impact performance on the radio.

The tarfile also includes the patches applied to the binary as I've not committed them yet.

Apologies if it's obvious, can someone point me to the instructions on how to install this, and I'll test that it solves the issue for the BBC Sounds AAC streams

[mrw]

Apologies if it's obvious, can someone point me to the instructions on how to install this, and I'll test that it solves the issue for the BBC Sounds AAC streams

Download the tar file, untar it (tar -x-f /whereami/baby-jive-aac-stutterfix-8.0.1r16835.tar). You will find a jive binary, which you can install suitably in /usr/bin, taking due precautions that you can recover matters in event of difficulty.

[expectingtofly]

Download the tar file, untar it (tar -x-f /whereami/baby-jive-aac-stutterfix-8.0.1r16835.tar). You will find a jive binary, which you can install suitably in /usr/bin, taking due precautions that you can recover matters in event of difficulty.

Thank you

[expectingtofly]

A

Previously the decode and output buffers would hardly ever fill above 1-2%.

I'd be interested to know if the changes make a difference for others. It would be good to know if Tidal aac playback is better as well, but I don't have an account.

Many thanks for providing this.
I've tested it on the BBC Sounds AAC streams 320kbps @ 48000hz. Everything is much more stable on this new version once its all underway.
I still get buffer underruns when the stream starts up :

Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 846842 / 73728 | 26.92% / 2.09%
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 19:33:40 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 1729 1729
Feb 25 19:33:41 squeezeplay: INFO   audio.decode - Playback.lua:448 30.2%/5.2%
Feb 25 19:33:42 squeezeplay: INFO   audio.decode - Playback.lua:448 51.0%/1.8%
Feb 25 19:33:43 squeezeplay: INFO   audio.decode - Playback.lua:448 64.6%/1.0%
Feb 25 19:33:43 squeezeplay: playback_callback:346 Audio underrun: used 192 frames, requested 480 frames. elapsed samples 219968
Feb 25 19:33:43 squeezeplay: playback_callback:346 Audio underrun: used 256 frames, requested 480 frames. elapsed samples 224000
Feb 25 19:33:43 squeezeplay: playback_callback:346 Audio underrun: used 64 frames, requested 480 frames. elapsed samples 225216
Feb 25 19:33:43 squeezeplay: playback_callback:346 Audio underrun: used 64 frames, requested 480 frames. elapsed samples 226240
Feb 25 19:33:44 squeezeplay: playback_callback:346 Audio underrun: used 64 frames, requested 480 frames. elapsed samples 227264
Feb 25 19:33:44 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 19:33:44 squeezeplay: playback_callback:346 Audio underrun: used 128 frames, requested 480 frames. elapsed samples 229248
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 2347851 / 57344 | 74.64% / 1.63%
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 1729 1729
Feb 25 19:33:44 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 25 19:33:45 squeezeplay: INFO   audio.decode - Playback.lua:448 80.5%/2.9%
Feb 25 19:33:46 squeezeplay: INFO   audio.decode - Playback.lua:448 89.8%/5.3%
Feb 25 19:33:47 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/8.2%
Feb 25 19:33:48 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/15.3%
Feb 25 19:33:49 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/24.4%
Feb 25 19:33:50 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/32.7%
Feb 25 19:33:51 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/41.3%
Feb 25 19:33:52 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/50.6%
Feb 25 19:33:53 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/58.8%
Feb 25 19:33:54 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/66.2%
Feb 25 19:33:55 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/75.1%
Feb 25 19:33:56 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/84.0%
Feb 25 19:33:57 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/92.5%
Feb 25 19:33:58 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/98.6%
Feb 25 19:33:59 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.9%
Feb 25 19:34:01 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.5%
Feb 25 19:34:02 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.6%
Feb 25 19:34:03 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/98.6%
Feb 25 19:34:04 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/98.6%
Feb 25 19:34:05 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/97.9%
Feb 25 19:34:06 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/98.0%
Feb 25 19:34:07 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/99.1%
Feb 25 19:34:08 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/98.3%
Feb 25 19:34:08 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer

[ralphy]

Many thanks for providing this.
I've tested it on the BBC Sounds AAC streams 320kbps @ 48000hz. Everything is much more stable on this new version once its all underway.
I still get buffer underruns when the stream starts up :

Thank you for testing.

Sorry I didn't reply with how to install the binary. Glad you worked it out. Thanks mrw. And no you didn't miss how to install it, none were provided.

At least it's encouraging that once playing, playback works well.

Unfortunately, I can't play the 320kbps @ 48000hz streams. The closest stream I've found is from Radio Paradise 320@44100, which unfortuately, both the original and the updated jive binary plays fine.

http://radioparadise.com/m3u/aac-320.m3u

Does it play okay for you?

Is your test radio wireless or wired?

From your log above, it appears that the radio can't handle getting the amount of decoded aac audio to the output buffer fast enough at the start. So it pauses, buffers more aac data and then continues without interruption.

Could you try increasing/setting the bufferThreshold in the bbc sounds plugin? I'm not sure if that would even make a difference based on how the audio is streamed.

Another thing that might give some insite is increasing the outputThreshold for aac on the server side.

diff --git a/Slim/Player/Squeezebox.pm b/Slim/Player/Squeezebox.pm
index fa2eb1669..78a999625 100644
--- a/Slim/Player/Squeezebox.pm
+++ b/Slim/Player/Squeezebox.pm
@@ -710,7 +710,7 @@ sub stream_s {
                $pcmsamplerate   = '?';
                $pcmendian       = '?';
                $pcmchannels     = '?';
-               $outputThreshold = 0;
+               $outputThreshold = 20;
 
        } elsif ($format eq 'dff' || $format eq 'dsf') {

I'll look at setting up my own 320@48K aac stream to see if I can work out how best to handle it
.

[mrw]

I'd be interested to know if the changes make a difference for others.

Thank you very much for this. It shows much promise.

I've been testing the revised binary against the same problematic stream posted by @staresy. My results differ from yours, in that I have start up problems, due to buffer underruns, much as described by @expectingtofly. Once going, all seems to be fine, and I get very nicely filled buffers, much as you have described.

I'll say now, that

increasing the outputThreshold for aac on the server side ... to 50

does seem to resolve the start up problems. I don't know what the 'proper' fix for this should be. And I don't know why you don't experience it while I and @expectingtofly do.

One other thing: under the original binary the problems (after initial start up issue) were accompanied by a curious log trace. Notice that the output buffer was thoroughly full, but still we got an underrun. I found that odd. I am not seeing this with the revised binary. I don't know what you did, but curing this may have been key.

Community release illustrating one very odd form of problem with aac problem stream

Output buffer well full, but suddenly “POP”
Feb 25 16:50:42 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/93.5%
Feb 25 16:50:43 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/96.5%
Feb 25 16:50:45 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:50:45 squeezeplay: playback_callback:346 Audio underrun: used 138 frames, requested 441 frames. elapsed samples 13659342
Feb 25 16:50:45 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer

After a few minutes of good playback, again suddenly “POP”:

Feb 25 16:54:48 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/91.5%
Feb 25 16:54:49 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/90.7%
Feb 25 16:54:50 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/90.6%
Feb 25 16:54:51 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/91.3%
Feb 25 16:54:52 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/94.6%
Feb 25 16:54:53 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.8%
Feb 25 16:54:54 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:54:55 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:54:55 squeezeplay: playback_callback:346 Audio underrun: used 53 frames, requested 441 frames. elapsed samples 24695419
Feb 25 16:54:56 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 25 16:54:56 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0

The binary also includes support for the new Mono Output Channel Mode added to LMS 8.2, which for the radio is really only useful when using the line out/headphone jack. I just needed to confirm that the downmix changes didn't impact performance on the radio.

I'm not familiar with this at all. I really don't know what the motivation is.

I would note that the Radio, when playing through speakers, does its own "downmix" in the crossover/dsp component. I can pull out the logic that it applies, it might be worth checking to ensure that inconsistencies are not introduced.

The tarfile also includes the patches applied to the binary as I've not committed them yet.

I will have a look at these, it might be educational ! If (unlikely) I have anything useful to say, I shall revert.

[ralphy]

Another thing that might give some insite is increasing the outputThreshold for aac on the server side.

diff --git a/Slim/Player/Squeezebox.pm b/Slim/Player/Squeezebox.pm
index fa2eb1669..78a999625 100644
--- a/Slim/Player/Squeezebox.pm
+++ b/Slim/Player/Squeezebox.pm
@@ -710,7 +710,7 @@ sub stream_s {
                $pcmsamplerate   = '?';
                $pcmendian       = '?';
                $pcmchannels     = '?';
-               $outputThreshold = 0;
+               $outputThreshold = 50;
 
        } elsif ($format eq 'dff' || $format eq 'dsf') {

I'll look at setting up my own 320@48K aac stream to see if I can work out how best to handle it.

I've been able to reproduce the problem on the radio using my own 320@48K stream, as well as running squeezeplay on my linux system which is way faster than the radio.

Setting outputThreshold to 50 for aac on the server, is too high, 20 gives a much shorter delay before playback starts for the first time, but long enough to prevent the AUDIO OUTPUT underrun.

If you can try the server side change to confirm/debunk my findings would be very helpful. I highlighted the threshold value in the log.

20210226 15:27:53.022 INFO   audio.decode - decode_start_handler:277 init decoder aac
20210226 15:27:53.022 DEBUG  audio.decode - decode_output_set_track_gain:520 Track gain 36864
20210226 15:27:53.022 DEBUG  audio.decode - decode_output_set_track_gain:524 Track clip range 7fffffff 80000000
20210226 15:27:53.023 DEBUG  audio.decode - decode_set_track_polarity_inversion:529 Polarity inversion 0
20210226 15:27:53.023 DEBUG  audio.decode - decode_set_output_channels:537 Output channels left 0, right 0
20210226 15:27:53.023 DEBUG  audio.codec - decode_aac_start:299 decode_aac_start(2)
20210226 15:27:53.022 INFO   audio.decode - Playback.lua:480 connect 192.168.100.22:9102 GET /94.9/S16_LE/48000/2/A HTTP/1.0
20210226 15:27:53.023 INFO   audio.decode - Playback.lua:483 GET /94.9/S16_LE/48000/2/A HTTP/1.0
20210226 15:27:53.023 DEBUG  audio.decode - Playback.lua:194 source=stream
20210226 15:27:53.023 DEBUG  audio.decode - stream_connectL:506 streambuf connect 192.168.100.22:9102
20210226 15:27:53.023 DEBUG  audio.decode - Playback.lua:1265 stopping local pause timer
20210226 15:27:53.023 DEBUG  audio.decode - Playback.lua:1195 gainL, gainR: 1729 1729
20210226 15:27:53.074 DEBUG  audio.decode - Playback.lua:1040 cont loop=0 icy=0
20210226 15:27:54.345 DEBUG  audio.decode - Playback.lua:397 resume decoder, 8192 bytes buffered, decode threshold 2048
20210226 15:27:54.345 DEBUG  audio.decode - decode_resume_decoder:577 decode_resume_decoder
20210226 15:27:54.345 DEBUG  audio.decode - decode_resume_decoder_handler:118 resume_decoder decode state: 1 audio state 0
20210226 15:27:54.345 DEBUG  audio.decode - debug_fullness:108 fullness: 8192 / 0 | 0.26% / 0.00%
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_init_heaac:73 FDK-AAC
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_callback_heaac:178 MPEG-4 AOT: 2
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_callback_heaac:179 MPEG-2 Profile: 1
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_callback_heaac:180 Sample rate: 48000
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_callback_heaac:181 Channels: 2
20210226 15:27:54.345 DEBUG  audio.codec - decode_aac_callback_heaac:182 Frame size: 1024
20210226 15:27:54.345 DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
20210226 15:27:54.439 DEBUG  audio.decode - Playback.lua:451 0.0%/0.5%
20210226 15:27:55.516 DEBUG  audio.decode - Playback.lua:451 0.1%/3.9%
20210226 15:27:56.639 DEBUG  audio.decode - Playback.lua:451 0.1%/16.3%
20210226 15:27:57.718 DEBUG  audio.decode - Playback.lua:451 0.0%/28.3%
20210226 15:27:58.845 DEBUG  audio.decode - Playback.lua:451 0.0%/40.6%
20210226 15:27:59.431 DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=208896 outputTime=4352 threshold=204800
20210226 15:27:59.431 DEBUG  audio.decode - decode_resume_audio:598 decode_resume_audio start_jiffies=0
20210226 15:27:59.431 DEBUG  audio.decode - decode_resume_audio_handler:129 decode_resume_audio_handler start_jiffies=0
20210226 15:27:59.431 DEBUG  audio.decode - debug_fullness:108 fullness: 0 / 1671168 | 0.00% / 47.37%
20210226 15:27:59.431 DEBUG  audio.decode - decode_resume_audio_handler:142 resume_audio decode state: 1 audio state 40
20210226 15:27:59.521 DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 5)
20210226 15:28:00.644 DEBUG  audio.decode - Playback.lua:451 0.1%/46.3%
20210226 15:28:01.725 DEBUG  audio.decode - Playback.lua:451 0.1%/46.9%
20210226 15:28:02.805 DEBUG  audio.decode - Playback.lua:451 0.0%/47.3%
20210226 15:28:03.840 DEBUG  audio.decode - Playback.lua:451 0.0%/47.3%
20210226 15:28:04.920 DEBUG  audio.decode - Playback.lua:451 0.1%/46.5%

[ralphy]

Thank you very much for this. It shows much promise.

I've been testing the revised binary against the same problematic stream posted by @staresy. My results differ from yours, in that I have start up problems, due to buffer underruns, much as described by @expectingtofly. Once going, all seems to be fine, and I get very nicely filled buffers, much as you have described.

I'll say now, that does seem to resolve the start up problems. I don't know what the 'proper' fix for this should be. And I don't know why you don't experience it while I and @expectingtofly do.

One other thing: under the original binary the problems (after initial start up issue) were accompanied by a curious log trace. Notice that the output buffer was thoroughly full, but still we got an underrun. I found that odd. I am not seeing this with the revised binary. I don't know what you did, but curing this may have been key.

Community release illustrating one very odd form of problem with aac problem stream

Output buffer well full, but suddenly “POP”
Feb 25 16:50:42 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/93.5%
Feb 25 16:50:43 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/96.5%
Feb 25 16:50:45 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:50:45 squeezeplay: playback_callback:346 Audio underrun: used 138 frames, requested 441 frames. elapsed samples 13659342
Feb 25 16:50:45 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 2
Feb 25 16:50:45 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer

After a few minutes of good playback, again suddenly “POP”:

Feb 25 16:54:48 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/91.5%
Feb 25 16:54:49 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/90.7%
Feb 25 16:54:50 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/90.6%
Feb 25 16:54:51 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/91.3%
Feb 25 16:54:52 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/94.6%
Feb 25 16:54:53 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.8%
Feb 25 16:54:54 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:54:55 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/99.3%
Feb 25 16:54:55 squeezeplay: playback_callback:346 Audio underrun: used 53 frames, requested 441 frames. elapsed samples 24695419
Feb 25 16:54:56 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 25 16:54:56 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0

I'm not familiar with this at all. I really don't know what the motivation is.

I would note that the Radio, when playing through speakers, does its own "downmix" in the crossover/dsp component. I can pull out the logic that it applies, it might be worth checking to ensure that inconsistencies are not introduced.


I will have a look at these, it might be educational ! If (unlikely) I have anything useful to say, I shall revert.

Thank you for testing this. Looks like we cross posted. I found setting the outputThreshold to 20 gives a quicker startup and still prevents the underrun. Need to do more testing with that server side change with all the aac content that played fine before changing it.

Hence my comments about no real need for the downmix feature for the radio. I couldn't hear any difference between the bass driver and tweeter with it set to stereo or mono output channel mode. But if I add it to the community firmware I didn't want the change to be in one and not the others, just too confusing.

Other than those 2 patches, the difference between the previous test static jive and the stutterfix jive is the stutterfix does NOT have fdk-aac linked static, which is the same as the jive binary included in r18635.
I haven't seen/heard the "POP" issue with any of the 3 jive binaries. Very strange.