Lag during playback over NFS

Plex Media Server NAS & Devices
21

you have that docker container and know the path to the file (as far as docker is concerned), right?

Perform this basic NFS I/O test from your nas to the docker host.

It looks like this on my machine. Adjust for yours:

  1. cd /glock/media/movies (where older movies are)
  2. read the entire file and measure the NFS performance
[chuck@lizum movies.2014]$ ls -la V*
Victor Frankenstein (2015) [1080p]:
total 29852268
drwxr-xr-x   2 chuck chuck          60 Jul 19  2023 ./
drwxr-xr-x 231 chuck chuck       16384 Aug  7 21:08 ../
-rw-r--r--   1 chuck chuck 30568699163 May 27  2018 Victor Frankenstein (2015) [1080p].mkv

Voices (2014):
total 9783560
drwxr-xr-x   2 chuck chuck          51 Jan 18  2024 ./
drwxr-xr-x 231 chuck chuck       16384 Aug  7 21:08 ../
-rw-r--r--   1 chuck chuck 10018341203 May 27  2018 The Voices (2014) [1080p].mkv

Voyagers (2021) [2160p]:
total 11962660
drwxr-xr-x   2 chuck chuck          49 Jul 19  2023 ./
drwxr-xr-x 231 chuck chuck       16384 Aug  7 21:08 ../
-rw-r--r--   1 chuck chuck 12249742132 Apr 30  2021 Voyagers (2021) [2160p].mkv
[chuck@lizum movies.2015]$ cd Voy*
[chuck@lizum Voyagers (2021) [2160p].2016]$ cd ../Victor\ Frankenstein\ \(2015\)\ \[1080p\]/
[chuck@lizum Victor Frankenstein (2015) [1080p].2017]$ dd if=Victor\ Frankenstein\ \(2015\)\ \[1080p\].mkv of=/dev/null bs=4M status=progress
29909581824 bytes (30 GB, 28 GiB) copied, 39 s, 767 MB/s 
7288+1 records in
7288+1 records out
30568699163 bytes (31 GB, 28 GiB) copied, 39.6622 s, 771 MB/s
[chuck@lizum Victor Frankenstein (2015) [1080p].2018]$

Check your performance of the NFS first.

22

Do the tests from my earlier post cover this?

Two images are there. Showing read/write from the host and then read/write from within the container.

25

Is the location of NEWtestfile.bin, /data/movies, the same as the media files (assuming it is, just want to confirm)?

Edit. Never mind. Can see it in the log files.

If so, then that’s the same as what @ChuckPa mentions. And it looks OK, at 101 MB/sec.

28

@maaadAPE

Can you create a local library on the NUC with The Expanse (or other media that shows the problem)?

See what happens when media is read from local storage, instead of over the network.

This would take the NFS & QNAP NAS out of the loop, helping with problem isolation.

29

In my previous testing, I ran the Plex container directly on the QNAP, and this lag didn’t exist. Unfortunately, I won’t be able to do that much longer, so I am trying to debug the situation over NFS and attempting to identify any issues that can be remedied. I upgraded the NUC that runs the Plex container as @ChuckPa recommended, and looking for anything else that could be causing problems.

From the initial testing in this thread, it doesn’t seem to be network, and it doesn’t seem to be NFS - unless it is an intermittent problem, which is completely possible. I’m hopeful that the most recent logs will help point us in the next direction with that ~20 second gap that happened. Is there anything in the logs that would attribute that gap to the initial guidance of getting a CPU to avoid transcoding HDR? Or do the logs show us going in another direction entirely - back to network/nfs.

PS: Thanks for any assistance @FordGuy61 . Definitely appreciate you and @ChuckPa jumping in to provide guidance.

30

I’ll look through the logs again.

Is the new NUC up and running? Does it experience the same problem?

Regarding local playback - just trying to divide up the problem & simplify troubleshooting.

If the delayed playback continues, then NFS & the QNAP are not the problem, and things point to something on the NUC.

If the problem goes away, then it points toward something with NFS or the interaction between the NUC and the QNAP.

That’s why I’m wondering what happens with local playback on the NUC.

There is something weird/different/etc. happening. I’ve PMS on a small PC (Ubuntu, no docker) and media on a Synology NAS. Playback for 4K HDR movies on my Shield starts in 5 seconds. Yours should do the same. It will be interesting to find out what is going on

31

I appreciate it @FordGuy61 .

The new NUC is up and running, so far I have NOT experienced the issue. It has always been intermittent, so definitely hard to track down. That’s why I was hopeful the logs with the large gap would help us pinpoint another issue.

From my experience local playback will be fine. I’ve never had issues when I ran Plex directly on the NAS.

Playback has been very fast on the new NUC, under 2 seconds. But I will keep an eye on it and see if it happens going forward. Definitely something I monitor every time I start something new.

For now, if you can review the logs around the time of that lag, and let me know if anything stands out. If nothing looks out of the ordinary, then we will just wait and see if it happens again.

As a note, I did purchase a better switch and will modify some of my network pathing in the next few days. Currently the ShieldTV is going through two switches before it gets to the NUC. I can remove one switch in the path, and installing the better one in there as well. Hoping to remove any random bottlenecks that might exist in the network configuration.

32

I just ran into the lag problem when starting a new episode, on the new NUC and AFTER removing one of the network switches in the way. New one arrives tomorrow, so I can replace the other switch that is in the path with a new Unifi device.

Hoping to have one of you (@ChuckPa / @FordGuy61) review the logs to see if anything stands out. The file looks to be 1080p and I do see some of the Broken Pipe errors in the log.

Aug 09, 2024 18:07:06.786 [123684232637240] DEBUG - Content-Length of /data/tv/Cobra Kai/Season 06/Cobra Kai - S06E03 - TBD - WEBDL-1080p - successfulcrab.mkv is 1631574595 (of total: 1631574595).
Aug 09, 2024 18:07:15.693 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 65536 bytes: 32 - Broken pipe
<redacted>
Aug 09, 2024 18:07:15.693 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 65536 bytes: 32 - Broken pipe
<redacted>
Aug 09, 2024 18:07:23.832 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 655360 bytes: 32 - Broken pipe

Plex Media Server Logs_2024-08-09_18-07-57.zip (7.0 MB)

As always, many thanks for your assistance and guidance.
.

33

Also, I have a LOT of these Failed to stream media errors:

# cat Plex\ Media\ Server.log* | grep -i "failed to stream" | wc -l
340

Snippet of the most recent:

Aug 09, 2024 14:26:36.822 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 44826624 bytes: 104 - Connection reset by peer
Aug 09, 2024 14:26:41.959 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 11714560 bytes: 104 - Connection reset by peer
Aug 09, 2024 15:25:06.779 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 10551296 bytes: 104 - Connection reset by peer
Aug 09, 2024 15:45:49.994 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 7667712 bytes: 104 - Connection reset by peer
Aug 09, 2024 15:45:50.216 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 6668288 bytes: 104 - Connection reset by peer
Aug 09, 2024 15:45:50.355 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 5242880 bytes: 104 - Connection reset by peer
Aug 09, 2024 15:45:51.761 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 14106624 bytes: 104 - Connection reset by peer
Aug 09, 2024 16:25:54.117 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 11272192 bytes: 104 - Connection reset by peer
Aug 09, 2024 18:07:15.693 [123684337494840] DEBUG - Failed to stream media, client probably disconnected after 65536 bytes: 32 - Broken pipe
Aug 09, 2024 18:07:15.693 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 65536 bytes: 32 - Broken pipe
Aug 09, 2024 18:07:23.832 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 655360 bytes: 32 - Broken pipe
Aug 09, 2024 18:22:59.742 [123684333300536] DEBUG - Failed to stream media, client probably disconnected after 10878976 bytes: 104 - Connection reset by peer

Does that seem resonable?

34

I copied over the same content to the new NUC and mounted a volume of the local directory, then added a new library specifically for that local content. I am getting these Failed to stream media messages even when I play local content.

A few other things that I have done to attempt resolution:

  • Replaced all accessible network cables between all devices and their routers/switches.
  • Removed an extra switch as part of the pathing for the ShieldTV to the router.
  • Uninstalled and reinstalled the Plex client on the ShieldTV.
  • Tried a different device as client, Pixel 8 Pro.
  • Switched the network port on the QNAP as I was seeing minor disconnects at the network level (in the Unifi interface wifi experience section)
35

I’ve no idea what is happening with your setup.

That you cannot play local media from the NUC is troublesome, but it seems to rule out NFS and the NAS as part of the problem.

There are also some confusing messages regarding playback on the Shield. There are times where there are sessions opening & closing every two to three seconds for different media files.

Any chance this is you starting/stopping playback and working through a list of movies or TV episodes? Not sure how to explain it otherwise.

Some examples, but there are many more in Plex Media Server.log:

Adding a new session:
Aug 08, 2024 22:47:52.840 [123684106808120] DEBUG - [Req#12e3/Transcode] Streaming Resource: Adding session 0x707d810579a8:73a2489c227ff3a4-com-plexapp-android which is using 50077kbps of WAN bandwidth. Used is now 50077kbps

Terminating session after ~2 seconds:
Aug 08, 2024 22:47:54.709 [123684106808120] DEBUG - [Req#12f6] Streaming Resource: Terminating session 0x707d810579a8:73a2489c227ff3a4-com-plexapp-android which is using 50077kbps of WAN bandwidth. Used is now 0kbps

~2 seconds later, start another session:
Aug 08, 2024 22:47:56.372 [123684106808120] DEBUG - [Req#133b/Transcode] Streaming Resource: Adding session 0x707d810324f8:73a2489c227ff3a4-com-plexapp-android which is using 31885kbps of WAN bandwidth. Used is now 31885kbps

Terminate second session in under 2 seconds:
Aug 08, 2024 22:47:57.975 [123684157139768] DEBUG - [Req#134b] Streaming Resource: Terminating session 0x707d810324f8:73a2489c227ff3a4-com-plexapp-android which is using 31885kbps of WAN bandwidth. Used is now 0kbps


I’m not sure where to look next. You’ve done the normal troubleshooting steps, switching clients, checking network gear, etc.

No idea about any possible Docker items. I do not use Docker on my Plex server.

Hopefully someone else can help.

36

I apologize for any confusion on episodes starting/stopping. I was testing after changes.
Those entries in the logs aren’t a concern as far as I can determine - the episodes all started promptly within 1-2 seconds.

For further clarity, I can play local media from the NUC, they do start and play. I just experienced the same intermittent lag during one of my tests leading me to believe it isn’t a local versus network issue.

Yesterday we fired up a movie and it had a 20-ish second lag as well.

With the problem being intermittent I know it is harder to debug, but I was hopeful the logs with the issue showing the Failed to stream media error over a nearly 20-second span would be helpful in providing guidance on where to go next. I apologize for introducing the additional noise by starting/stopping episodes.

If you aren’t seeing a problem with the Failed to stream media error then maybe that isn’t the culprit and I just don’t understand the logs well enough.

As a note, I did replace the switch that existed in the pathway, but haven’t had enough of an opportunity to observe any issues since that change late last night.

Again, thank you again for all your support and guidance, it is definitely appreciated. Still hoping we can narrow down a culprit and solution.

To try and conclude some of the above - I want to ask again - do you see anything concerning with the logs (realistically just eh playback of that one episode) showing the Failed to stream media error? Latest example being in this previous post with a 1080p video file:

37

Just decided to do a quick test with the new switch in place.

Aug 11, 2024 18:34:55.147 [128364492892984] DEBUG - Failed to stream media, client probably disconnected after 524288 bytes: 32 - Broken pipe
Aug 11, 2024 18:34:55.155 [128364488698680] DEBUG - Failed to stream media, client probably disconnected after 1114112 bytes: 32 - Broken pipe
Aug 11, 2024 18:35:01.524 [128364488698680] DEBUG - Failed to stream media, client probably disconnected after 6012928 bytes: 32 - Broken pipe
Aug 11, 2024 18:35:01.930 [128364488698680] DEBUG - Failed to stream media, client probably disconnected after 16842752 bytes: 104 - Connection reset by peer

Plex Media Server Logs_2024-08-11_18-36-38.zip (4.1 MB)

38

I just switched from the linuxserver.io docker container over to the plex standard and had the same issues over NFS and local with the same media file.

Screenshot 2024-08-12 at 9.53.41 AM

Here is a grep of Failed to stream media entries from the NFS playback:

Aug 12, 2024 09:24:12.624 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 4685824 bytes: 104 - Connection reset by peer
Aug 12, 2024 09:24:12.835 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 2801664 bytes: 104 - Connection reset by peer
Aug 12, 2024 09:24:12.984 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 3866624 bytes: 104 - Connection reset by peer
Aug 12, 2024 09:24:13.232 [137804084423480] DEBUG - Failed to stream media, client probably disconnected after 2539520 bytes: 32 - Broken pipe
Aug 12, 2024 09:24:13.523 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 6406144 bytes: 104 - Connection reset by peer

Here is a grep of Failed to stream media entries from local playback:

Aug 12, 2024 09:50:33.899 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 1966080 bytes: 104 - Connection reset by peer
Aug 12, 2024 09:50:34.242 [137804080229176] DEBUG - Failed to stream media, client probably disconnected after 8617984 bytes: 104 - Connection reset by peer

Logs attached.

Plex Media Server Logs_2024-08-12_09-51-22.zip (359.9 KB)

Is there anything in there that shows there is an issue with this specific episode?

39

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.