After the pause LMS starts streaming again, then pauses once buffers
fill up.
Code:
--------------------
[21-06-01 01:11:41.5583] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun... <-- streaming resumes after
the second pause
[21-06-01 01:11:41.5589] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:11:41.5592] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100
...
[21-06-01 01:11:41.6963] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 32768 bytes)
[21-06-01 01:11:41.6965] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 32768 to 192.168.10.100 <-- streaming pauses for the
third time
...
[21-06-01 01:11:42.0045] Slim::Networking::Slimproto::_stat_handler (778)
FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535
[21-06-01 01:11:42.0047] Slim::Networking::Slimproto::_stat_handler (784)
00:02:c9:13:08:d0: STAT-STMt: fullness=2093497, output_fullness=3330736,
elapsed=59.206
[21-06-01 01:11:42.0049] 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 4216443
fullness: 2093497 (99%)
bufferSize 2097152
fullness 2093497
bytes_received 4216443
signal_strength: 65535
jiffies: 1655225250
voltage: 0
[21-06-01 01:11:42.0050] Slim::Networking::Slimproto::_stat_handler (823)
output size: 3528000
output fullness: 3330736
elapsed seconds: 59
[21-06-01 01:11:42.0052] Slim::Networking::Slimproto::_stat_handler (835)
elapsed milliseconds: 59206
server timestamp: 0
--------------------
This stream/pause repeats for a bit. We have a total of 6 pauses and 7
streaming bursts. I am not going to posts logs for all that since there
is really nothing interesting happening. Here is a table that summarizes
how much data was sent and received in each burst.
Code:
--------------------
Bytes sent in this burst | Bytes sent Total | Bytes Received | Difference in
bytes and playback time
1st burst: 5997035 5997035 2393886
3603149 118 seconds
2nd burst: 3112960 9109995 2448379
6661616 218 seconds
3rd burst: 2129920 11239915 4216443
7023472 230 seconds
4th burst: 2097152 13337067 6373697
6963370 228 seconds
5th burst: 2097152 15434219 8421048
7013171 229 seconds
6th burst: 2097152 17531371 10549011
6982360 228 seconds
7th burst: 1823723 19355094 12661166
6693928 219 seconds
--------------------
As you can see we steadily have around 220-230 seconds worth of playback
time sitting in TCP buffers.
Lets skip to LMS ending the stream:
Code:
--------------------
[21-06-01 01:16:09.2640] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:16:09.2643] Slim::Web::HTTP::sendStreamingResponse (2276)
(audio: 21483 bytes)
[21-06-01 01:16:09.2646] Slim::Web::HTTP::sendStreamingResponse (2425)
Streamed 21483 to 192.168.10.100 <-- last data
streamed
[21-06-01 01:16:09.2648] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:16:09.2651] Slim::Player::Protocols::File::sysread (283) Trying
to read past the end of file:
file:///mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05%20-%20Led%20Zeppelin%20-%20Carouselambra.mp3
[21-06-01 01:16:09.2653] Slim::Player::Source::_readNextChunk (349) Read to
end of file or pipe
[21-06-01 01:16:09.2656] Slim::Player::Source::_readNextChunk (372) end of
file or error on socket, song pos: 19390336, tell says: 19390336, totalbytes:
19354603
[21-06-01 01:16:09.2658] Slim::Player::Source::_readNextChunk (377)
00:02:c9:13:08:d0 mark end of stream
[21-06-01 01:16:09.2675] Slim::Player::StreamingController::_eventAction
(272) 00:02:c9:13:08:d0: LocalEndOfStream in PLAYING-STREAMING ->
Slim::Player::StreamingController::_Streamout
[21-06-01 01:16:09.2678]
Slim::Player::StreamingController::_setStreamingState (2386) new streaming
state STREAMOUT
[21-06-01 01:16:09.2680] Slim::Player::StreamingController::_eventAction
(302) 00:02:c9:13:08:d0: LocalEndOfStream - new state PLAYING-STREAMOUT
[21-06-01 01:16:09.2683] Slim::Web::HTTP::sendStreamingResponse (2299)
Nothing to stream, let's wait for 0.4 seconds...
[21-06-01 01:16:09.2688] Slim::Web::HTTP::sendStreamingResponse (2412)
$httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0)
[21-06-01 01:16:09.2690] Slim::Web::HTTP::sendStreamingResponse (2414)
$peeraddr{$httpClient} is: 192.168.10.100
[21-06-01 01:16:09.2692] Slim::Web::HTTP::sendStreamingResponse (2415) Got
nothing for streaming data to 192.168.10.100
[21-06-01 01:16:09.6701] Slim::Web::HTTP::sendStreamingResponse (2168)
sendStreaming response begun...
[21-06-01 01:16:09.6704] Slim::Web::HTTP::sendStreamingResponse (2289) Found
an empty chunk on the queue - dropping the streaming connection.
[21-06-01 01:16:09.6706] Slim::Web::HTTP::closeStreamingSocket (2532) Closing
streaming socket
[21-06-01 01:16:09.6709] Slim::Web::HTTP::closeHTTPSocket (2466) Closing HTTP
socket Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0) with
192.168.10.100:60755 (closed normally)
...
[21-06-01 01:16:11.0045] Slim::Networking::Slimproto::_stat_handler (778)
FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535
[21-06-01 01:16:11.0047] Slim::Networking::Slimproto::_stat_handler (784)
00:02:c9:13:08:d0: STAT-STMt: fullness=2093499, output_fullness=3325264,
elapsed=328.110
[21-06-01 01:16:11.0050] 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 12661166
fullness: 2093499 (99%)
bufferSize 2097152
fullness 2093499
bytes_received 12661166
signal_strength: 65535
jiffies: 1655494234
voltage: 0
[21-06-01 01:16:11.0052] Slim::Networking::Slimproto::_stat_handler (823)
output size: 3528000
output fullness: 3325264
elapsed seconds: 328
[21-06-01 01:16:11.0054] Slim::Networking::Slimproto::_stat_handler (835)
elapsed milliseconds: 328110
server timestamp: 0
--------------------
Nothing wrong from the LMS point of view, it has read all the data from
the file and streamed it to the client. Note that LMS closes socket at
01:16:09.670.
Now lets look at what happens with the TCP stream:
34907
Client machine receives last data packet (frame 17677) from the server
at 01:18:31.892, but we know that LMS closed socket at 01:16:09.670.
That's 144 second difference (accounting for 2 sec difference between
the machines), that's how long it took to drain TCP send buffers on the
LMS server machine. We already calculated that there was 219 seconds of
data in the TCP send + TCP receive buffers when LMS finished streaming
and closed the socket. Now that TCP send buffer is empty we can try to
calculate how much data there was in the TCP receive buffers on the
client machine when frame 17677 was received: 219-144=75 seconds.
Since Linux TCP stack on the server only waits 60 seconds (timeout
controlled by net.ipv4.tcp_fin_timeout) for response to the FIN packet
we already know that client is not going to be able to send back FIN,ACK
in time.
+-------------------------------------------------------------------+
|Filename: flow_04_fin.png |
|Download: http://forums.slimdevices.com/attachment.php?attachmentid=34907|
+-------------------------------------------------------------------+
------------------------------------------------------------------------
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
