search

philippe44 / LMS-ShairTunes2W

Airtunes with LMS (fork of https://github.com/disaster123/shairport2_plugin)
65 stars 3 forks source link

Buffer issues #23

Closed MarqL closed 4 years ago

MarqL commented 5 years ago

I'm running a LMS off my CentOS linux box. The server hast the version Logitech Media Server (v7.9.1, 1522157629, Fri Mar 30 12:23:41 CEST 2018) Shairtunes2 plugin is installed in version 0.107.7 My home netwrk also has 3 Slim devices squeezebox classic connected.

For quite a while now I'm getting buffer error on the displays of the squeezeboxes and interrupted music play when streaming from an iphone or ipdad. I fiddled with the settings but didn't find a good solution that works for me.

Any hints on what could cause this and how to fix it are highly appreciated.

Logs on the server read as follows:

[17:56:48.283021] rtp_thread_func:730 [0x9e71f00]: 1st sync packet received
[17:56:48.283089] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2915864213 rtp:2915941388 remote ntp:83aaaae6b2af9ebe, local time 73189843 (now:73189847)
[17:56:48.299413] hairtunes_flush:474 [0x9e71f00]: FLUSH ignored as same as RECORD (11731 - 2915946895)
[17:56:48.299587] hairtunes_flush:486 [0x9e71f00]: flush 11731 2915946895
[17:56:48.313986] flac_init:218 [0x9e71f00]: Using FLAC-0 (0xb5e00480)
[17:56:48.314443] buffer_put_packet:614 [0x9e71f00]: fill [level:1] [W:11731 R:11731]
[17:56:48.336924] _buffer_get_frame:954 [0x9e71f00]: drain [level:1 gap:1442] [W:11732 R:11731] [R:0 S:0 F:0]
[17:56:49.301154] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2915909185 rtp:2915986360 remote ntp:83aaaae7b7be20cc, local time 73190863 (now:73190865)
[17:56:50.322274] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2915954169 rtp:2916031344 remote ntp:83aaaae8bce00b02, local time 73191883 (now:73191887)
[17:56:51.341545] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2915999151 rtp:2916076326 remote ntp:83aaaae9c1fe7c06, local time 73192903 (now:73192906)
[17:56:51.341994] rtp_request_timing:831 [0x9e71f00]: timing request now:73192906 (port: 58037)
[17:56:51.345600] rtp_thread_func:812 [0x9e71f00]: Timing references local:73192906, remote:83aaaae9c2ffb267 (delta:-2, sum:-3, adjust:0, gaps:0)
[17:56:52.361524] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916044132 rtp:2916121307 remote ntp:83aaaaeac71cf56e, local time 73193922 (now:73193926)
[17:56:52.395207] buffer_put_packet:614 [0x9e71f00]: fill [level:4] [W:12243 R:12240]
[17:56:52.407325] _buffer_get_frame:954 [0x9e71f00]: drain [level:1 gap:1456] [W:12244 R:12243] [R:0 S:0 F:0]
[17:56:53.381424] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916089114 rtp:2916166289 remote ntp:83aaaaebcc3b62f4, local time 73194942 (now:73194946)
[17:56:54.401467] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916134099 rtp:2916211274 remote ntp:83aaaaecd15e72c3, local time 73195962 (now:73195966)
[17:56:55.421410] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916179082 rtp:2916256257 remote ntp:83aaaaedd67e0b7a, local time 73196982 (now:73196986)
[17:56:55.421774] rtp_request_timing:831 [0x9e71f00]: timing request now:73196986 (port: 58037)
[17:56:55.424534] rtp_thread_func:812 [0x9e71f00]: Timing references local:73196986, remote:83aaaaedd746bb82 (delta:0, sum:-3, adjust:0, gaps:0)
[17:56:56.443503] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916224068 rtp:2916301243 remote ntp:83aaaaeedba31832, local time 73198003 (now:73198008)
[17:56:56.503381] buffer_put_packet:614 [0x9e71f00]: fill [level:1] [W:12755 R:12755]
[17:56:56.519466] _buffer_get_frame:954 [0x9e71f00]: drain [level:4 gap:1432] [W:12759 R:12755] [R:0 S:0 F:0]
[17:56:57.461360] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916269043 rtp:2916346218 remote ntp:83aaaaefe0b73d18, local time 73199022 (now:73199026)
[17:56:58.516283] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916314025 rtp:2916391200 remote ntp:83aaaaf0e5d67989, local time 73200042 (now:73200081)
[17:56:59.372691] http_thread_func:1189 [0x9e71f00]: spent 824 ms in send for 3064 bytes (sent 3064)!
[17:56:59.501150] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916359009 rtp:2916436184 remote ntp:83aaaaf1eaf79c84, local time 73201062 (now:73201065)
[17:56:59.501538] rtp_request_timing:831 [0x9e71f00]: timing request now:73201066 (port: 58037)
[17:56:59.504568] rtp_thread_func:812 [0x9e71f00]: Timing references local:73201066, remote:83aaaaf1ebd102bc (delta:-1, sum:-4, adjust:0, gaps:0)
[17:57:00.137767] http_thread_func:1189 [0x9e71f00]: spent 759 ms in send for 3408 bytes (sent 3408)!
[17:57:00.521171] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916403991 rtp:2916481166 remote ntp:83aaaaf2f015fcc1, local time 73202082 (now:73202085)
[17:57:00.582670] buffer_put_packet:614 [0x9e71f00]: fill [level:146] [W:13267 R:13122]
[17:57:00.955053] http_thread_func:1189 [0x9e71f00]: spent 811 ms in send for 3189 bytes (sent 3189)!
[17:57:01.251284] http_thread_func:1189 [0x9e71f00]: spent 290 ms in send for 3169 bytes (sent 3169)!
[17:57:01.530383] http_thread_func:1189 [0x9e71f00]: spent 274 ms in send for 3290 bytes (sent 3290)!
[17:57:01.535488] _buffer_get_frame:954 [0x9e71f00]: drain [level:121 gap:502] [W:13388 R:13267] [R:0 S:0 F:0]
[17:57:01.541053] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916448971 rtp:2916526146 remote ntp:83aaaaf3f532b55e, local time 73203102 (now:73203105)
[17:57:02.075692] http_thread_func:1189 [0x9e71f00]: spent 538 ms in send for 3135 bytes (sent 3135)!
[17:57:02.560986] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916493952 rtp:2916571127 remote ntp:83aaaaf4fa4fe207, local time 73204122 (now:73204125)
[17:57:02.616267] http_thread_func:1189 [0x9e71f00]: spent 535 ms in send for 3274 bytes (sent 3274)!
[17:57:03.337267] http_thread_func:1189 [0x9e71f00]: spent 715 ms in send for 3225 bytes (sent 3225)!
[17:57:03.619951] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916538941 rtp:2916616116 remote ntp:83aaaaf5ff78e9f6, local time 73205142 (now:73205184)
[17:57:03.622518] rtp_request_timing:831 [0x9e71f00]: timing request now:73205187 (port: 58037)
[17:57:03.625630] rtp_thread_func:812 [0x9e71f00]: Timing references local:73205187, remote:83aaaaf60acd86bf (delta:-1, sum:-5, adjust:0, gaps:0)
[17:57:04.072623] http_thread_func:1189 [0x9e71f00]: spent 728 ms in send for 3267 bytes (sent 3267)!
[17:57:04.600843] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916583919 rtp:2916661094 remote ntp:83aaaaf70490ed6a, local time 73206162 (now:73206165)
[17:57:04.652592] http_thread_func:1189 [0x9e71f00]: spent 574 ms in send for 2988 bytes (sent 2988)!
[17:57:04.661054] buffer_put_packet:614 [0x9e71f00]: fill [level:230] [W:13779 R:13550]
[17:57:05.061172] http_thread_func:1189 [0x9e71f00]: spent 402 ms in send for 3098 bytes (sent 3098)!
[17:57:05.326865] http_thread_func:1189 [0x9e71f00]: spent 259 ms in send for 3288 bytes (sent 3288)!
[17:57:05.547076] http_thread_func:1189 [0x9e71f00]: spent 214 ms in send for 3322 bytes (sent 3322)!
[17:57:05.553738] _buffer_get_frame:954 [0x9e71f00]: drain [level:112 gap:570] [W:13891 R:13779] [R:0 S:0 F:0]
[17:57:05.620776] rtp_thread_func:736 [0x9e71f00]: sync packet rtp_latency:2916628898 rtp:2916706073 remote ntp:83aaaaf809abd1aa, local time 73207182 (now:73207185)
[17:57:05.781787] sock_gets:115 gets EOF on closed socket

Example taken from a start that was freshly started and paused 7sec later.

Thanks in advance! Marq

philippe44 commented 5 years ago

You have that issue that I've seen from time to time where the kernel spends a lot of time in a send() call for UDP, which should not at all happen. I've never figured out why some network exhibit this behavior

philippe44 commented 4 years ago

Closed for inactivity