fpo wrote:
> I'm also experiencing dropouts. While reproducible, the exact timing of
> the dropouts depend on circumstances like stream buffer size and mp3
> bitrate.
> When loging to a terminal with -d all=sdebug the dropouts do occur. When
> logging same to a file with -f <logfile> however, the dropouts are gone.
> When they occur, one thread in squeezelite starts using nearly 100% of
> one cpu core, above 95% of that in kernel mode. Following the onset of
> 100% cpu usage the stream buffer runs empty and then the dropout occurs.
> To see this I had to run squeezelite from tailored program, redirecting
> the error stream, logging to memory and writing it all to a file after
> the tests so as not to alter squeezelite's internal timing. I tested
> with squeezelite v1.9.8-1307 (the test versions like 1318-test3 seem to
> be gone).
Good progress! I did not notice any high-CPU during the outage, but I'll
take another look and do more tests. It does seem true that the "stream
buffer runs empty", causing the dropout, because after 30 seconds, it
just grabs another chunk and continues normally. Thus, early on, I
suspected it was some kind of buffering issue.
I have not run with sdebug level yet, but seeing this code in the
stream_thread:
LOG_SDEBUG("poll timeout");
I think there might be some sdebug messages that will help with this
issue. I ran it like this:
squeezelite-1.9.8-1318-test2-win32 -d all=sdebug -n
SqueezeLite-bogan-admin -s nas -o 1 2>err.log
This will redirect STDERR to the err.log file. (outputting to the
console causes too much text, and audio gets dropped, so it must go to a
file)
The outage occurred after 5 minutes, as expected. Looking at the logs, I
see a few things going on.
First, we see 'normal' behavior, where the streambuf is allocated, the
buffer is read, and the streambuf returns to 'full' with 2097151 bytes.
The decode_thread() reports the size of the streambuf and outputbuf,
using _buf_used().
[11:52:08.332] decode_thread:75 streambuf bytes: 1963597
outputbuf space: 172615
[11:52:08.394] stream_thread:428 streambuf read 133554 bytes
[11:52:08.440] decode_thread:75 streambuf bytes: 2097151 outputbuf
space: 208967
...
Here we see that 1963597 + 133554 = 2097151. It continues like this:
[11:52:08.442] decode_thread:75 streambuf bytes: 2095221
outputbuf space: 172103
[11:52:08.501] stream_thread:428 streambuf read 1930 bytes
[11:52:08.548] decode_thread:75 streambuf bytes: 2097151 outputbuf
space: 208455
...
Various amounts are allocated, but it always returns to 2097151 bytes.
It continues this way until we see it come in pairs:
[11:52:18.017] decode_thread:75 streambuf bytes: 2095430
outputbuf space: 198215
[11:52:18.017] decode_thread:75 streambuf bytes: 2095430 outputbuf
space: 198215
[11:52:18.124] decode_thread:75 streambuf bytes: 2095430 outputbuf
space: 234567
[11:52:18.124] stream_thread:428 streambuf read 1721 bytes
[11:52:18.124] stream_thread:428 streambuf read 1826 bytes
[11:52:18.124] decode_thread:75 streambuf bytes: 2097151 outputbuf
space: 197703
[11:52:18.233] decode_thread:75 streambuf bytes: 2097151 outputbuf
space: 234055
....
Looks fishy. Why is it now reporting decode_thread() twice?
Also, I see that the numbers no longer add-up. 2095430 + 1721 = 2097151,
but the 1826 bytes does not add up correctly. Weird.
It continues normally for 2 minutes, and then this is the last time we
see it:
[11:53:54.105] decode_thread:75 streambuf bytes: 2097151
outputbuf space: 190791
[11:53:54.213] decode_thread:75 streambuf bytes: 2097151 outputbuf
space: 227143
...
Now it starts to steadily decrease over the next 2 minutes:
[11:53:54.753] decode_thread:75 streambuf bytes: 2085726
outputbuf space: 196807
[11:53:54.862] decode_thread:75 streambuf bytes: 2085726 outputbuf
space: 233159
They come in pairs, with the same streambuf size, but the outputbuf is
allocated/deallocated.
[11:54:00.056] decode_thread:75 streambuf bytes: 1989484
outputbuf space: 170439
[11:54:05.764] decode_thread:75 streambuf bytes: 1889334 outputbuf
space: 188103
[11:54:10.381] decode_thread:75 streambuf bytes: 1808956 outputbuf
space: 202055
[11:54:15.405] decode_thread:75 streambuf bytes: 1717460 outputbuf
space: 186311
[11:54:20.750] decode_thread:75 streambuf bytes: 1619750 outputbuf
space: 205895
[11:54:25.117] decode_thread:75 streambuf bytes: 1539989 outputbuf
space: 174919
[11:54:30.180] decode_thread:75 streambuf bytes: 1452300 outputbuf
space: 214343
[11:54:40.462] decode_thread:75 streambuf bytes: 1262312 outputbuf
space: 181575
[11:54:50.045] decode_thread:75 streambuf bytes: 1087811 outputbuf
space: 198471
[11:55:00.097] decode_thread:75 streambuf bytes: 911919 outputbuf space:
194631
[11:55:10.065] decode_thread:75 streambuf bytes: 730428 outputbuf space:
181959
[11:55:20.039] decode_thread:75 streambuf bytes: 558233 outputbuf space:
243015
[11:55:30.000] decode_thread:75 streambuf bytes: 376119 outputbuf space:
221255
[11:55:40.117] decode_thread:75 streambuf bytes: 183016 outputbuf space:
207687
[11:55:50.088] decode_thread:75 streambuf bytes: 3614 outputbuf space:
204231
[11:55:51.072] decode_thread:75 streambuf bytes: 1945 outputbuf space:
512711
[11:55:53.256] decode_thread:75 streambuf bytes: 1945 outputbuf space:
1276103
[11:55:55.241] decode_thread:75 streambuf bytes: 1945 outputbuf space:
1975879
[11:55:57.212] decode_thread:75 streambuf bytes: 1945 outputbuf space:
2675655
[11:55:58.304] decode_thread:75 streambuf bytes: 1945 outputbuf space:
3057351
[11:55:59.624] decode_thread:75 streambuf bytes: 1945 outputbuf space:
3527999
...
The streambuf bytes has decreased to 1945 bytes and stays there, until
the audio dropout occurs a few milliseconds later.
Next, we see that decode_thread stops and the outputbuf drops to zero.
Then, we see the "strm command p" which heralds the outage:
[11:55:59.690] sendSTAT:200 received bytesL: 4203604 streambuf:
1945 outputbuf: 0 calc elapsed: 231206 real elapsed: 231437 (diff: -231)
device: 175 delay: 15
[11:55:59.690] process:527 strm
[11:55:59.690] process_strm:280 strm command t
[11:55:59.690] sendSTAT:166 ms_played: 231206 (frames_played: 10203311
device_frames: 7761)
[11:55:59.690] sendSTAT:195 STAT: STMt
[11:55:59.690] sendSTAT:200 received bytesL: 4203604 streambuf: 1945
outputbuf: 0 calc elapsed: 231206 real elapsed: 231437 (diff: -231)
device: 175 delay: 15
[11:55:59.690] process:527 strm
[11:55:59.691] process_strm:280 strm command p
While the outage continues for 30 seconds, we continue to see:
[11:56:03.745] decode_thread:75 streambuf bytes: 1945 outputbuf
space: 3527999
Until the return of audio is heralded by command q:
[11:56:30.787] process_strm:280 strm command q
Then, we see recovery and starting a new audio stream, the streambuf
returns to a larger value:
[11:56:31.187] decode_thread:75 streambuf bytes: 994737
outputbuf space: 3527999
[11:56:31.187] _check_lame_header:163 gapless: skip: 2257 samples:
12759040 delay: 1105 padding: 1711
[11:56:31.187] mad_decode:247 setting track_start
[11:56:31.187] mad_decode:276 gapless: skipping 1152 frames at start
[11:56:31.187] mad_decode:302 write 0 frames
[11:56:31.187] mad_decode:235 mad_frame_decode error: lost
synchronization
[11:56:31.187] decode_thread:75 streambuf bytes: 992689 outputbuf space:
3527999
And..
[11:56:31.202] decode_thread:75 streambuf bytes: 991984
outputbuf space: 3527999
[11:56:31.203] decode_thread:75 streambuf bytes: 991983 outputbuf space:
3527999
[11:56:31.203] decode_thread:75 streambuf bytes: 991982 outputbuf space:
3527999
[11:56:31.203] mad_decode:235 mad_frame_decode error: bad
main_data_begin pointer
[11:56:31.203] decode_thread:75 streambuf bytes: 991981 outputbuf space:
3527999
And...
[11:56:31.233] stream_thread:436 poll timeout
To summarize, we see:
* decode_thread streambuf _buf_used() declines down to zero in the lead
up to the audio dropout.,
* The dropout is heralded by the "strm command p" (pause)
* The dropout lasts for almost exactly 30 seconds
* The end of the dropout is heralded by the "strm command q" (quit)
* After audio resumes, a few errors were seen:
-- the "frame decode error" reporting lost synchronization, due to an
unknown frame-decoding error.
-- the "poll timeout". The stream_thread polls the stream to get its
status, for each chunk of data it processes. Here it timed-out after
100ms.
* The errors suggest there is an issue with the way the stream buffers
are managed.
I hope that this provides a more complete picture of the circumstances
surrounding the audio dropout.
------------------------------------------------------------------------
foopydog's Profile: http://forums.slimdevices.com/member.php?userid=71156
View this thread: http://forums.slimdevices.com/showthread.php?t=113554
_______________________________________________
plugins mailing list
[email protected]
http://lists.slimdevices.com/mailman/listinfo/plugins
