How to find my buffering bottle neck?

Plex Media Server NAS & Devices
1

I’ve been having issues for a long time now with my Plex Media Server. My normal setup is a PMS running via Docker, using files from a NAS via NFS over power outlet network and streaming via Chromecast to my TV. So I guess lots if possible problems and I just haven’t gotten around to debugging this thoroughly :slight_smile:

My problems always comes after a while, like 20 minutes into a movie or something. Which of course is very annoying. Typically, it gets worse and worse until it needs to stop and buffer for 5 minutes to play 1 second.

I just now did a few tests to isolate. First off:

  • My Wifi is fine, no other streaming has been problematic on the Chromecast, I use a lot of other video services from the web and everything streams fine except Plex. Sometimes when using the microwave in the same room I get issues but I have always been sure these problems aren’t wifi related.

  • My server is an i7 4-something GHz with 16GB ram, should be fine.

  • I’m running docker image with network=host so I really don’t think there should be any issues there either.

  • Before, my NAS was next to the router which also does the wifi while the server was in a wardrobe over power outlet connection. So streaming, the bits had to pass through the outlet in duplex, first into the server (nfs) and then back again after transcoding. I now mover my NAS into the wardrobe too and with a switch it’s connected straight to the server so should only need to pass the outlet model once on it’s way out to the chromecast via wifi. This hasn’t helped.

Soo… I’ve never really gotten anything from the logs, but I just turned on verbose logging and looked at the transcoding speed numbers. So when I start playing I have number around 30-40 (some peaks at over 1000 though, hey algorithm?):

Feb 23, 2018 13:17:50.121 [0x7f39b33ff700] DEBUG - Request: [127.0.0.1:33460 (Loopback)] PUT /video/:/transcode/session/v59s8oc0dfn5zeckwnb67kj4/2ab61586-65bf-45da-a80d-0821fa1f884b/progress?progress=1.1&size=-22&remaining=67&speed=42.0 (15 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:17:50.121 [0x7f39b33ff700] VERBOSE -  * speed => 42.0
Feb 23, 2018 13:17:50.121 [0x7f39c1bfe700] DEBUG - Completed: [127.0.0.1:33460] 206 PUT /video/:/transcode/session/v59s8oc0dfn5zeckwnb67kj4/2ab61586-65bf-45da-a80d-0821fa1f884b/progress?progress=1.1&size=-22&remaining=67&speed=42.0 (15 live) 0ms 326 bytes
Feb 23, 2018 13:17:50.784 [0x7f39b2bfe700] DEBUG - Request: [127.0.0.1:33463 (Loopback)] PUT /video/:/transcode/session/v59s8oc0dfn5zeckwnb67kj4/2ab61586-65bf-45da-a80d-0821fa1f884b/progress?progress=1.7&size=-22&remaining=80&speed=30.1 (15 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:17:50.785 [0x7f39b2bfe700] VERBOSE -  * speed => 30.1
Feb 23, 2018 13:17:50.785 [0x7f39c1bfe700] DEBUG - Completed: [127.0.0.1:33463] 206 PUT /video/:/transcode/session/v59s8oc0dfn5zeckwnb67kj4/2ab61586-65bf-45da-a80d-0821fa1f884b/progress?progress=1.7&size=-22&remaining=80&speed=30.1 (15 live) 0ms 326 bytes
Feb 23, 2018 13:17:51.349 [0x7f39b33ff700] DEBUG - Request: [127.0.0.1:33468 (Loopback)] PUT /video/:/transcode/session/v59s8oc0dfn5zeckwnb67kj4/2ab61586-65bf-45da-a80d-0821fa1f884b/progress?progress=2.2&size=-22&remaining=102&speed=24.9 (17 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:17:51.349 [0x7f39b33ff700] VERBOSE -  * speed => 24.9
…

Feb 23, 2018 13:17:58.016 [0x7f39b33ff700] VERBOSE -  * speed => 1812.8

This then rapidly dropped to 0:

Feb 23, 2018 13:18:06.939 [0x7f39c1bfe700] DEBUG - Completed: [127.0.0.1:33581] 206 PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.6&size=-22&remaining=57&speed=24.1 (18 live) 0ms 342 bytes
Feb 23, 2018 13:18:42.881 [0x7f39b33ff700] DEBUG - Request: [127.0.0.1:33594 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=5842&speed=8.7 (18 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.881 [0x7f39c03ff700] DEBUG - Request: [127.0.0.1:33596 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=39090&speed=0.0 (17 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.881 [0x7f39b33ff700] VERBOSE -  * speed => 8.7
Feb 23, 2018 13:18:42.882 [0x7f39c03ff700] VERBOSE -  * speed => 0.0
Feb 23, 2018 13:18:42.882 [0x7f39a13f6700] DEBUG - Request: [127.0.0.1:33599 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=78011&speed=0.0 (20 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.883 [0x7f39a13f6700] VERBOSE -  * speed => 0.0
Feb 23, 2018 13:18:42.883 [0x7f39a53fe700] DEBUG - Request: [127.0.0.1:33597 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=78010&speed=0.0 (25 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.883 [0x7f39c23ff700] DEBUG - Completed: [127.0.0.1:33599] 206 PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=78011&speed=0.0 (26 live) 1ms 326 bytes
Feb 23, 2018 13:18:42.883 [0x7f39a1bf7700] DEBUG - Request: [127.0.0.1:33600 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=76240&speed=0.0 (25 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.884 [0x7f39b33ff700] DEBUG - Request: [127.0.0.1:33604 (Loopback)] PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=78013&speed=0.0 (27 live) Signed-in Token (hedefalk)
Feb 23, 2018 13:18:42.884 [0x7f39c23ff700] DEBUG - Completed: [127.0.0.1:33594] 206 PUT /video/:/transcode/session/gpct1cwtvtlcgq4ll7nsul7s/023158cb-80c8-4009-a5ed-b5d22e0a9c28/progress?progress=47.8&size=-22&remaining=5842&speed=8.7 (27 live) 3ms 326 bytes
Feb 23, 2018 13:18:42.884 [0x7f39b33ff700] VERBOSE -  * speed => 0.0

CPU on machine is so far from being hogged and I see nothing suspicious in the plex log. How do I proceed in debugging this?

Thanks!

2

I have the same problem streaming via web ui and app so disregard chromecast

3

I’m continuing to struggle. Did an entirely new installation with plexinc/pms-server instead of the wernight one I was using before. Everything is crawling. Added to libraries yesterday which finished scanning 10 hours ago and now I can’t even add another one:

456×530 141 KB

Can’t even load the server, but nothing in logs:

No limits in docker:

version: ‘2’
services:
plex:
container_name: plex
image: plexinc/pms-docker
restart: unless-stopped
environment:
- TZ=Europe/Stockholm
- PLEX_CLAIM=claim-XXX
- PLEX_UID=1000
- PLEX_GID=1000
network_mode: host
volumes:
- /var/lib/plex-config/plexinc-config:/config
- /var/lib/plex-transcode-temp:/transcode
- /var/lib/old-media:/old-media
………

User is my own.

4

I’ll just continue adding info:

When running “optimize for TV” offline I get pretty consistent around 15x speed during whole conversion even with source files over NFS. So doesn’t seem to be source file network related.

It’s something that degrades over time when I’m streaming. Typically I’m screwed if I ever do any jumping. Then server becomes unresponsive in every way and I have to reboot it.

5

One more thing I entirely forgot - some movies /series actually streams quite ok always. But if I skip to much, something happens, stuff seems to get overloaded and just dies. Then I have to restart PMS to get it responsive again. I have like 3-4 skips before it dies.

6

Just to confirm, you don’t have the /config mapped to a point that’s on NFS, do you? Also is your transcoding temp on NFS too?

Just as a test, you may want to try putting a file or two not on NFS and see if it makes a difference for those files. It could be the NFS interaction that’s causing the issue. Either way this would help narrow it down.