LMS continues sending data to squeezelite non stop until buffers fill up
and then it pauses.
Code:
--------------------
[21-06-01 01:10:42.7389] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:10:42.7390] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:10:42.7391] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100 <-- last data sent before pause
[21-06-01 01:10:42.7803] Slim::Networking::Slimproto::client_readable (393)
Slimproto frame: STAT, len: 53
[21-06-01 01:10:42.7808] Slim::Player::Player::trackJiffiesEpoch (925)
00:02:c9:13:08:d0 trackJiffiesEpoch: epoch=1620872676.75235,
offset=1620872676.74956
[21-06-01 01:10:42.7810] Slim::Player::Player::trackJiffiesEpoch (932)
00:02:c9:13:08:d0 adjust jiffies epoch -0.003s
[21-06-01 01:10:42.7813] Slim::Networking::Slimproto::_stat_handler (778)
FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535
[21-06-01 01:10:42.7815] Slim::Networking::Slimproto::_stat_handler (784)
00:02:c9:13:08:d0: STAT-STMs: fullness=2097151, output_fullness=3345784,
elapsed=0.000
[21-06-01 01:10:42.7817] Slim::Networking::Slimproto::_stat_handler (811)
00:02:c9:13:08:d0 Squeezebox stream status:
event_code: STMs
bytes_rec_H 0
bytes_rec_L 2393886
fullness: 2097151 (99%)
bufferSize 2097152
fullness 2097151
bytes_received 2393886
signal_strength: 65535
jiffies: 1655166031
voltage: 0
[21-06-01 01:10:42.7819] Slim::Networking::Slimproto::_stat_handler (823)
output size: 3528000
output fullness: 3345784
elapsed seconds: 0
[21-06-01 01:10:42.7821] Slim::Networking::Slimproto::_stat_handler (835)
elapsed milliseconds: 0
server timestamp: 0
[21-06-01 01:10:42.7824]
Slim::Player::StreamingController::playerTrackStarted (2200) 00:02:c9:13:08:d0
[21-06-01 01:10:42.7826] Slim::Player::StreamingController::_eventAction
(272) 00:02:c9:13:08:d0: Started in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_Playing
[21-06-01 01:10:42.7829] Slim::Player::StreamingController::_setPlayingState
(2377) new playing state PLAYING
[21-06-01 01:10:42.7831] Slim::Player::StreamingController::_Playing (368)
Song 0 has now started playing
--------------------
LMS does not log how much total data it streamed, but it logs every
socket write, so I added everything up and at this point in time LMS has
already sent out 5997035 bytes (5.71 MB) of data, but squeezelite
reports that it has only received 2393886 bytes (2.28 MB). 5997035 minus
2393886 = 3603149 bytes (3.43 MB). So now we know that 3.43 MB of data
is sitting in TCP send buffers on the LMS server machine and TCP receive
buffers on the squeezelite client machine. Song I am playing is 244 kbps
which means we have 118 seconds of song sitting in TCP buffers Since
squeezelite stream buffer is full at this point it would take
squeezelite 118 seconds to retrieve everything from TCP buffers.
Code:
--------------------
[01:10:40.702] stream_thread:428 streambuf read 7300 bytes
[01:10:40.702] stream_thread:428 streambuf read 13787 bytes
[01:10:40.702] pa_monitor:294 device reopen
[01:10:40.702] pa_monitor:304 end monitor thread
[01:10:40.702] _pa_open:409 opened device 6 - Topping E30 (2- TOPPING USB
DAC) [Windows WASAPI] at 44100 latency 21 ms
[01:10:40.749] _check_lame_header:163 gapless: skip: 2257 samples: 27974100
delay: 1105 padding: 1115
[01:10:40.811] stream_thread:428 streambuf read 1 bytes
[01:10:40.811] stream_thread:428 streambuf read 296734 bytes
[01:10:40.811] pa_callback:525 pad with silence
[01:10:40.811] sendSTAT:171 ms_played: 0
[01:10:40.811] sendSTAT:195 STAT: STMs
[01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151
outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0
[01:10:40.811] sendSTAT:171 ms_played: 0
[01:10:40.811] sendSTAT:195 STAT: STMt
[01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151
outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0
[01:10:41.012] stream_thread:428 streambuf read 3131 bytes
[01:10:41.113] stream_thread:428 streambuf read 3237 bytes
--------------------
This is how TCP flow looks. Note that this pause is very short, so no
keep-alive packets were sent out.
34903
LMS resumes streaming and then pauses again
Code:
--------------------
[21-06-01 01:10:42.7923] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:10:42.7926] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:10:42.7929] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100
[21-06-01 01:10:42.7932] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:10:42.7935] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:10:42.7937] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100
...
[21-06-01 01:10:42.8297] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:10:42.8298] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100
[21-06-01 01:10:42.8300] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:10:42.8301] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:10:42.8302] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100 <-- last data before the
second pause
...
[21-06-01 01:10:44.7826] Slim::Networking::Slimproto::_stat_handler (778)
FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535
<-- first STMt after pause
[21-06-01 01:10:44.7829] Slim::Networking::Slimproto::_stat_handler (784)
00:02:c9:13:08:d0: STAT-STMt: fullness=2094020, output_fullness=3325696,
elapsed=1.986
[21-06-01 01:10:44.7831] Slim::Networking::Slimproto::_stat_handler (811)
00:02:c9:13:08:d0 Squeezebox stream status:
event_code: STMt
bytes_rec_H 0
bytes_rec_L 2448379
fullness: 2094020 (99%)
bufferSize 2097152
fullness 2094020
bytes_received 2448379
signal_strength: 65535
jiffies: 1655168031
voltage: 0
[21-06-01 01:10:44.7834] Slim::Networking::Slimproto::_stat_handler (823)
output size: 3528000
output fullness: 3325696
elapsed seconds: 1
[21-06-01 01:10:44.7836] Slim::Networking::Slimproto::_stat_handler (835)
elapsed milliseconds: 1986
server timestamp: 0
--------------------
Code:
--------------------
[01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151
outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0
[01:10:40.811] sendSTAT:171 ms_played: 0
[01:10:40.811] sendSTAT:195 STAT: STMt
[01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151
outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0
[01:10:41.012] stream_thread:428 streambuf read 3131 bytes
[01:10:41.113] stream_thread:428 streambuf read 3237 bytes
[01:10:41.214] stream_thread:428 streambuf read 4698 bytes
[01:10:41.315] stream_thread:428 streambuf read 1879 bytes
[01:10:41.416] stream_thread:428 streambuf read 3236 bytes
[01:10:41.517] stream_thread:428 streambuf read 1462 bytes
[01:10:41.618] stream_thread:428 streambuf read 3132 bytes
[01:10:41.719] stream_thread:428 streambuf read 3549 bytes
[01:10:41.820] stream_thread:428 streambuf read 3445 bytes
[01:10:41.920] stream_thread:428 streambuf read 1775 bytes
[01:10:42.020] stream_thread:428 streambuf read 3341 bytes
[01:10:42.120] stream_thread:428 streambuf read 3967 bytes
[01:10:42.221] stream_thread:428 streambuf read 3549 bytes
[01:10:42.322] stream_thread:428 streambuf read 3236 bytes
[01:10:42.423] stream_thread:428 streambuf read 3654 bytes
[01:10:42.524] stream_thread:428 streambuf read 1775 bytes
[01:10:42.624] stream_thread:428 streambuf read 3757 bytes
[01:10:42.725] stream_thread:428 streambuf read 1670 bytes
[01:10:42.812] sendSTAT:166 ms_played: 1986 (frames_played: 87318
device_frames: 441)
[01:10:42.812] sendSTAT:195 STAT: STMt
[01:10:42.812] sendSTAT:200 received bytesL: 2448379 streambuf: 2094020
outputbuf: 3325696 calc elapsed: 1986 real elapsed: 2000 (diff: -14) device: 10
delay: 16
[01:10:42.826] stream_thread:428 streambuf read 3131 bytes
[01:10:42.926] stream_thread:428 streambuf read 3445 bytes
[01:10:43.027] stream_thread:428 streambuf read 1879 bytes
--------------------
I calculated that LMS has sent out 3112960 bytes in this second burst
(since last pause) and 9109995 (8.68 MB) total. squeezelite has received
2448379 bytes (2.33 MB). Difference between sent and received data is
6661616 bytes (6.35 MB) or 218 seconds of playback.
34905
since second pause is almost a minute long we see keep-alive packets
being sent to make sure the TCP session does not time out.
+-------------------------------------------------------------------+
|Filename: flow_03_second_pause.jpg |
|Download: http://forums.slimdevices.com/attachment.php?attachmentid=34905|
+-------------------------------------------------------------------+
------------------------------------------------------------------------
lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826
View this thread: http://forums.slimdevices.com/showthread.php?t=114661
_______________________________________________
Squeezecenter mailing list
[email protected]
http://lists.slimdevices.com/mailman/listinfo/squeezecenter
