Constant Buffering: New issue with old setup that hasn't "changed"

server-linux

#1

I have been running Plex Media Server on a Ubuntu machine for many years now. Although I have done OS and PMS updates, I haven’t changed this PMS in several years. I also use two Roku’s as my Plex clients. My network is fully hardwired 1GBps and all switches are 1Gbps switches. My NAS is 1Gbps and is on the same top level switch as my Roku’s.

Recently I have been having problems with constant buffering. I double checked my Plex client settings in the Roku and it is set in every which way possible to do no transcoding. But according to my server it appears to be transcoding. Here is a screenshot of the process utilization if that helps point to something I’m not knowledgeable enough to recognize.

I did a ’ tail -f Plex\ Media\ Server.log | grep speed’ on the logs. It is definitely falling behind but what is the most interesting is that when the Roku plex client starts to buffer the logs stop showing new entries and it doesn’t ever start new entries again unless I kill the ‘tail’ and start it again. I wonder if something isn’t running properly on the server causing server side resource locks? The CPU utilization really doesn’t seem to be an issue from the above screenshot. Here are some logs from the tail which aren’t encouraging:

Mar 07, 2018 18:47:28.613 [0x7ff0d6fff700] DEBUG - Request: [127.0.0.1:42758 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=8260&speed=0.7 (11 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:28.613 [0x7ff0d6fff700] VERBOSE - * speed => 0.7 Mar 07, 2018 18:47:28.615 [0x7ff0d97ff700] DEBUG - Completed: [127.0.0.1:42758] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=8260&speed=0.7 (11 live) 7ms 326 bytes Mar 07, 2018 18:47:29.105 [0x7ff0da7ff700] DEBUG - Request: [127.0.0.1:42760 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5563&speed=1.1 (10 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:29.105 [0x7ff0da7ff700] VERBOSE - * speed => 1.1 Mar 07, 2018 18:47:29.106 [0x7ff0d8ffe700] DEBUG - Completed: [127.0.0.1:42760] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5563&speed=1.1 (10 live) 1ms 326 bytes Mar 07, 2018 18:47:29.795 [0x7ff0c3bfe700] DEBUG - Request: [127.0.0.1:42764 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5791&speed=0.7 (12 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:29.796 [0x7ff0c3bfe700] VERBOSE - * speed => 0.7 Mar 07, 2018 18:47:29.796 [0x7ff0d97ff700] DEBUG - Completed: [127.0.0.1:42764] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5791&speed=0.7 (12 live) 1ms 326 bytes Mar 07, 2018 18:47:30.355 [0x7ff0a87fc700] DEBUG - Request: [127.0.0.1:42766 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=6166&speed=0.9 (10 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:30.355 [0x7ff0a87fc700] VERBOSE - * speed => 0.9 Mar 07, 2018 18:47:30.356 [0x7ff0d8ffe700] DEBUG - Completed: [127.0.0.1:42766] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=6166&speed=0.9 (10 live) 0ms 326 bytes Mar 07, 2018 18:47:31.299 [0x7ff0c23fe700] DEBUG - Request: [127.0.0.1:42770 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5446&speed=0.9 (9 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:31.299 [0x7ff0c23fe700] VERBOSE - * speed => 0.9 Mar 07, 2018 18:47:31.300 [0x7ff0d97ff700] DEBUG - Completed: [127.0.0.1:42770] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5446&speed=0.9 (9 live) 1ms 326 bytes Mar 07, 2018 18:47:31.946 [0x7ff0d6fff700] DEBUG - Request: [127.0.0.1:42772 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5512&speed=0.9 (10 live) Signed-in Token (scottlindner) Mar 07, 2018 18:47:31.947 [0x7ff0d6fff700] VERBOSE - * speed => 0.9 Mar 07, 2018 18:47:31.947 [0x7ff0d97ff700] DEBUG - Completed: [127.0.0.1:42772] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/dc6dbf40-d1a7-4183-9c3c-9a0e9108e4b3/progress?progress=23.6&size=-22&remaining=5512&speed=0.9 (10 live) 0ms 326 bytes


#2

The buffering also happens on the web plex client and PMP on a Windows machine. So it's definitely something with the server setup, but it hasn't changed in forever.


#3

Would you mind redoing all that please?

  1. Settings - Server - Help - Download Logs 30 seconds after recreating and stopping playback.
  2. This will present you with a ZIP file of the logs I need to see. Please attach to next reply (upload)
  3. To see why PMS is having difficulty also means I need to see the XML (hover over item -> Get Info - > View XML) and attach

#4

I think I found it. Not really sure yet. So far things have been reliable late last night and this morning. I noticed that it was transcoding a movie even when no players were playing anything. A reboot didn't appear to stop this transcoding with no clients playing anything. So I went through all of the connected clients and removed them all. Now it seems to be running cleanly.


Mar 08, 2018 06:34:30.734 [0x7f832b3fe700] DEBUG - Request: [127.0.0.1:35244 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.0&size=-22&remaining=73586&speed=2.0 (12 live) Signed-in Token (scottlindner)
Mar 08, 2018 06:34:30.734 [0x7f832b3fe700] VERBOSE - * speed => 2.0
Mar 08, 2018 06:34:30.735 [0x7f833a7ff700] DEBUG - Completed: [127.0.0.1:35244] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.0&size=-22&remaining=73586&speed=2.0 (12 live) 1ms 342 bytes
Mar 08, 2018 06:34:32.248 [0x7f8323bf9700] DEBUG - Request: [127.0.0.1:35260 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.0&size=-22&remaining=36042&speed=5.4 (10 live) Signed-in Token (scottlindner)
Mar 08, 2018 06:34:32.248 [0x7f8323bf9700] VERBOSE - * speed => 5.4
Mar 08, 2018 06:34:32.249 [0x7f8339ffe700] DEBUG - Completed: [127.0.0.1:35260] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.0&size=-22&remaining=36042&speed=5.4 (10 live) 1ms 342 bytes
Mar 08, 2018 06:34:33.763 [0x7f832b3fe700] DEBUG - Request: [127.0.0.1:35280 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.1&size=-22&remaining=35820&speed=9.1 (14 live) Signed-in Token (scottlindner)
Mar 08, 2018 06:34:33.764 [0x7f832b3fe700] VERBOSE - * speed => 9.1
Mar 08, 2018 06:34:33.764 [0x7f833a7ff700] DEBUG - Completed: [127.0.0.1:35280] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.1&size=-22&remaining=35820&speed=9.1 (13 live) 1ms 342 bytes
Mar 08, 2018 06:34:39.854 [0x7f83357ff700] DEBUG - Request: [127.0.0.1:35312 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.1&size=-22&remaining=42342&speed=2.9 (13 live) Signed-in Token (scottlindner)
Mar 08, 2018 06:34:39.854 [0x7f83357ff700] VERBOSE - * speed => 2.9
Mar 08, 2018 06:34:39.855 [0x7f833a7ff700] DEBUG - Completed: [127.0.0.1:35312] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.1&size=-22&remaining=42342&speed=2.9 (12 live) 0ms 342 bytes
Mar 08, 2018 06:34:41.876 [0x7f832b3fe700] DEBUG - Request: [127.0.0.1:35334 (Loopback)] PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.2&size=-22&remaining=35869&speed=9.7 (15 live) Signed-in Token (scottlindner)
Mar 08, 2018 06:34:41.876 [0x7f832b3fe700] VERBOSE - * speed => 9.7
Mar 08, 2018 06:34:41.877 [0x7f833a7ff700] DEBUG - Completed: [127.0.0.1:35334] 206 PUT /video/:/transcode/session/18b4f115c9c2033a880e4e765a9272ee/51dd84ef-49da-437d-ac61-c52978e120f2/progress?progress=24.2&size=-22&remaining=35869&speed=9.7 (15 live) 1ms 342 bytes

I'll snag the other data if this becomes a problem again.