Extremely slow stream start when transcoding

Plex Media Server Desktops & Laptops
, ,
1

Server Version#: 1.19.3.2764
Player Version#: Plex Web 4.30.2

My Plex server started having difficulty starting playback for client/media pairs that require transcoding. I first noticed this on my PS4, which almost always transcodes, and then in Firefox, which transcodes when I play MKV files. I never had any problems with Plex prior to this.

On PS4, I am completely unable to start playback because I get an error code after a few seconds of loading. I don’t have the error code on hand but I can get it if needed. With the Web UI, playback takes between 2 and 15 minutes to start. This is extremely strange because I’m running Plex in a Proxmox LXC on top of a Dell R720XD with two Xeon E5-2690s (32 threads total at 2.9 GHz).

The transcoder itself does not appear to be an issue. I checked a 24 minute 1371 kbps MKV file and it is fully transcoded (in the transcoder temp directory) to original quality for web playback within 25 seconds. The transcoder exits gracefully but the Web UI continues to spin for several minutes before playback begins.

The stream also doesn’t appear in the activity section of Tautulli or other Plex interfaces while it’s starting in this manner. After it starts, it appears with the usual statistics–transcoder throttled, the audio and video formats, etc.

I’ve attached two sets of logs: plex-1.log is starting a file from the beginning shortly after restarting plexmediaserver and plex-2.log is starting that file at the resume point after ending the first stream. In the first log, it takes about 1 minute for playback to start; in the second, it never starts.

I have an additional set of logs for starting that file again but from the beginning, which took about 2.5 minutes. I could not attach it due to the attachment limit for new users.

plex-1.log (102.8 KB)
plex-2.log (389.1 KB)

I should note that my media is mounted in the container via NFS to my NAS. This is a relatively recent addition to my setup; before yesterday my media was on the same system as Plex. This doesn’t appear to have any impact on the overall performance.

2

Please supply the full log ZIP file.

you’ve snipped out all the information we need to help with.

3

Sorry, it’s a habit from work. Been spending too much time analyzing customer defect reports lately myself :smile:

Here’s a reproduction of the first two cases I described (play from start, then resume).
Plex Media Server Logs_2020-05-17_02-35-17.zip (988.6 KB)

4

The device at 192.168.0.222 is being noisy but nothing which would interfere with playback from the server perspective.

Is it only the playstation which is slow to start or the entire LAN?

May 17, 2020 02:28:10.076 [0x7f5e689c5700] DEBUG - Scaled up video bitrate to 2073Kbps based on 1.500000x fudge factor.
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: Selected protocol dash; container: mp4
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: analyzing media item 22391
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : Direct Play is disabled
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : media must be transcoded in order to use the dash protocol
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : no direct play video profile exists for http/mkv/h264
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : no direct play video profile exists for http/mkv/h264/vorbis
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : no direct play video profile exists for http/mkv/h264/vorbis
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : Direct Streaming is disabled, so video stream will be transcoded
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: E1 - Secret of the Dragon Balls : no remuxable profile found, so video stream will be transcoded
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: Cannot direct stream video stream due to profile or setting limitations
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - Scaled up video bitrate to 2073Kbps based on 1.500000x fudge factor.
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: Cannot direct stream audio stream due to codec vorbis when profile only allows aac
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - MDE: Dragon Ball - S1 E1 - Secret of the Dragon Balls : selected media 0 / 22391
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - Streaming Resource: Session 0x7f5e001358c0:8uu18z92ilgvowruon1milmu changed transcode slot usage to used.  Used slots is now 1
May 17, 2020 02:28:10.077 [0x7f5debfff700] DEBUG - Killing job.
May 17, 2020 02:28:10.077 [0x7f5debfff700] DEBUG - Signalling job ID 12146 with 9
May 17, 2020 02:28:10.077 [0x7f5debfff700] DEBUG - Job was already killed, not killing again.
May 17, 2020 02:28:10.077 [0x7f5debfff700] DEBUG - Stopping transcode session 8iosx6szu8pekgwq7yey5fsm
May 17, 2020 02:28:10.077 [0x7f5e689c5700] DEBUG - Streaming Resource: Reached Decision id=15282 codes=(General=1001,Direct play not available; Conversion OK. Direct Play=3000,App cannot direct play this item. Direct play is disabled. Transcode=1001,Direct play not available; Conversion OK.) media=(id=22391 part=(id=57459 decision=transcode container=mp4 protocol=dash streams=(Video=(id=177655 decision=transcode bitrate=2073 encoder=libx264 width=640 height=480) Audio=(id=177656 decision=transcode bitrate=256 encoder=aac channels=2 rate=48000))))
May 17, 2020 02:28:10.078 [0x7f5dcb7fe700] DEBUG - Cleaning directory for session 8iosx6szu8pekgwq7yey5fsm (/dev/shm/Transcode/Sessions/plex-transcode-8iosx6szu8pekgwq7yey5fsm-f089a78f-b5a4-42b8-84fd-66e87cd31052)
May 17, 2020 02:28:10.079 [0x7f5e6b1ca700] DEBUG - Completed: [192.168.0.102:63227] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F15282&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=0&subtitleSize=100&audioBoost=100&location=wan&session=x2qd2elu4nsqeh1zq2duk4xz&subtitles=burn&Accept-Language=en (6 live) GZIP 15ms 1719 bytes (pipelined: 7)
May 17, 2020 02:28:10.080 [0x7f5debfff700] DEBUG - Transcoder: Cl
5

I noticed the 192.168.0.222 messages as well, but I haven’t been able to trace it to anything specific yet. I might try to filter that traffic out with my firewall because it inflates the logs quite a bit when debug logging is disabled.

The PlayStation doesn’t start playback at all. It gives an error code when I try to play anything. I can browse fine. I don’t have the code on hand, but I can fetch it if needed. Right now I’m mostly concerned with getting web playback up and running.

These logs were captured when I tried playing through Plex Web. The entire LAN is slow to start through Plex Web, regardless of whether the connection is wired or wireless. Browsing is smooth on all clients and DirectPlay through the Plex Windows client starts up instantaneously with no buffering.

6

if the entire LAN is slow, there is need to stop right there and find out why.

With that CPU, and those bitrates, unless you’ve got it limited in a VM or something else bizarre, it should be snapping to and playing in a couple seconds (5-7)

dumb question time. Jumbo Frames? (e.g. MTU is not 1500)

7

The MTU is correct. I get latency under 5ms into and out of the VM and can nearly saturate the gigabit connection with data transfers. The network is snappy overall and if I play media from Plex with the Windows client (ie with DirectPlay) the stream starts instantaneously even with higher bitrate media, such as Blu-ray rips. I’ve allocated 8 cores and 8 GB of memory to the container running Plex. It isn’t running anything other than Plex. The container is running Debian 10.

I only have this issue when transcoding is involved.

Hardware transcoding is disabled. I’ve tested with and without it and found no difference in behavior. I also tested with a different server (running Debian 10 on an AMD Kevari 7700k) using the same library and ran into the same problem.

I could try a fresh library, but the current one has accumulated several years of watch history that I would prefer to preserve. I migrated the library from a FreeBSD install where there were no issues.

8

I stopped plexmediaserver.service, moved my PMS directory to a different location, started the service, and added one library to the fresh server configuration. I encountered the same issue, even after the library scan and metadata refresh completed.

I removed that library (which used an NFS mount for the media), copied a single show into the container, and added a new library with only that show in it. I encountered the same issue.

I don’t think I’ve been able to stream correctly since I switched my server over from FreeBSD to Debian 10. I’ve tried installing Debian directly on hardware and running Plex on top of it, running Plex inside of an LXC running Debian, and running Plex inside of the official Docker image atop Debian. Is there something I’m missing specific to this distribution? I’ve been using it for close to 20 years without any issues, but it seems to be the common factor with this transcoding issue.

My next step will be trying a different Linux distribution inside of an LXC (most likely CentOS). Failing that, I will try FreeBSD in a full VM.

9

Latency to a VM must better be sub millisecond or there’s a problem.
Latency on the lan of under 1ms is expected.

sh-4.3# ping 192.168.0.1
PING 192.168.0.1 (192.168.0.1) 56(84) bytes of data.
64 bytes from 192.168.0.1: icmp_seq=1 ttl=64 time=0.126 ms
64 bytes from 192.168.0.1: icmp_seq=2 ttl=64 time=0.126 ms
64 bytes from 192.168.0.1: icmp_seq=3 ttl=64 time=0.105 ms
^C^C
--- 192.168.0.1 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 1998ms
rtt min/avg/max/mdev = 0.105/0.119/0.126/0.009 ms
sh-4.3#
10

Ping from the Plex container to the NAS:

PING 192.168.0.5 (192.168.0.5) 56(84) bytes of data.
64 bytes from 192.168.0.5: icmp_seq=1 ttl=64 time=0.259 ms
64 bytes from 192.168.0.5: icmp_seq=2 ttl=64 time=0.278 ms
64 bytes from 192.168.0.5: icmp_seq=3 ttl=64 time=0.262 ms
64 bytes from 192.168.0.5: icmp_seq=4 ttl=64 time=0.291 ms
64 bytes from 192.168.0.5: icmp_seq=5 ttl=64 time=0.218 ms

Ping from my desktop to the Plex container:

Pinging 192.168.0.11 with 32 bytes of data:
Reply from 192.168.0.11: bytes=32 time<1ms TTL=64
Reply from 192.168.0.11: bytes=32 time<1ms TTL=64
Reply from 192.168.0.11: bytes=32 time<1ms TTL=64
Reply from 192.168.0.11: bytes=32 time<1ms TTL=64
11

you had me worried when you said 5 ms. My ping over DSL to Google is about that much :slight_smile:

May i see the XML of the item being played?

12

The results are the same with CentOS and FreeBSD, so it must be this file.

<?xml version="1.0" encoding="UTF-8"?>
<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="8" librarySectionTitle="Anime" librarySectionUUID="8118d314-8972-4413-a742-f2c03c0268f7" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1588691599">
<Video ratingKey="15282" key="/library/metadata/15282" parentRatingKey="15281" grandparentRatingKey="15280" guid="com.plexapp.agents.thetvdb://76666/1/1?lang=en" parentGuid="com.plexapp.agents.thetvdb://76666/1?lang=en" grandparentGuid="com.plexapp.agents.thetvdb://76666?lang=en" type="episode" title="Secret of the Dragon Balls " grandparentKey="/library/metadata/15280" parentKey="/library/metadata/15281" librarySectionTitle="Anime" librarySectionID="8" librarySectionKey="/library/sections/8" grandparentTitle="Dragon Ball" parentTitle="Season 1" contentRating="TV-14" summary="Goku, an orphan living in the mountains, is out fishing when he meets Bulma, a young girl searching for the seven Dragon Balls, which, when gathered together, grant a wish. Goku&#39;s grandpa gave him the four-star Dragon Ball before he died. Needing this ball for her collection, already possessing two balls, Bulma decides to let Goku join her search. They take off on a motorcycle, but Bulma is suddenly grabbed by a giant flying dinosaur. Goku hits the monster with his power pole and rescues Bulma. " index="1" parentIndex="1" rating="7.7" viewCount="1" lastViewedAt="1589764844" year="1986" thumb="/library/metadata/15282/thumb/1589766768" art="/library/metadata/15280/art/1589766773" parentThumb="/library/metadata/15281/thumb/1589766773" grandparentThumb="/library/metadata/15280/thumb/1589766773" grandparentArt="/library/metadata/15280/art/1589766773" grandparentTheme="/library/metadata/15280/theme/1589766773" duration="1452463" originallyAvailableAt="1986-02-26" addedAt="1522753963" updatedAt="1589766768">
<Media id="22391" duration="1452463" bitrate="1377" width="640" height="480" aspectRatio="1.33" audioChannels="2" audioCodec="vorbis" videoCodec="h264" videoResolution="480" container="mkv" videoFrameRate="24p" videoProfile="high">
<Part accessible="1" exists="1" id="57459" key="/library/parts/57459/1589633786/file.mkv" duration="1452463" file="/mnt/anime/Dragon Ball/S01/S01E01.Secret.of.the.Dragon.Balls.mkv" size="250839620" container="mkv" deepAnalysisVersion="4" requiredBandwidths="1653,1418,1418,1418,1418,1418,1418,1418" videoProfile="high">
<Stream id="177655" streamType="1" default="1" codec="h264" index="0" bitrate="1217" bitDepth="8" chromaLocation="left" chromaSubsampling="4:2:0" codedHeight="480" codedWidth="640" frameRate="23.976" hasScalingMatrix="0" height="480" level="51" profile="high" refFrames="3" requiredBandwidths="1494,1262,1262,1262,1262,1262,1262,1262" scanType="progressive" width="640" displayTitle="480p (H.264)" />
<Stream id="177656" streamType="2" selected="1" default="1" codec="vorbis" index="1" channels="2" bitrate="93" language="English" languageCode="eng" audioChannelLayout="stereo" requiredBandwidths="103,103,103,103,103,103,103,103" samplingRate="48000" displayTitle="English (VORBIS Stereo)" />
<Stream id="177657" streamType="2" codec="vorbis" index="2" channels="1" bitrate="66" language="&#26085;&#26412;&#35486;" languageCode="jpn" audioChannelLayout="mono" requiredBandwidths="66,66,66,66,66,66,66,66" samplingRate="48000" displayTitle="&#26085;&#26412;&#35486; (VORBIS Mono)" />
<Stream id="177658" streamType="3" default="1" codec="ass" index="3" bitrate="0" language="English" languageCode="eng" requiredBandwidths="1,1,1,1,1,1,1,1" displayTitle="English (ASS)" />
<Stream id="187514" key="/library/streams/187514" streamType="3" codec="srt" format="srt" displayTitle="Unknown (SRT External)" />
</Part>
</Media>
<Director id="56919" filter="director=56919" tag="Minoru Okazaki" />
<Director id="17540" filter="director=17540" tag="Daisuke Nishio" />
<Writer id="17547" filter="writer=17547" tag="Akira Toriyama" />
<Writer id="56918" filter="writer=56918" tag="Yasushi Hirano" />
<Extras size="0">
</Extras>
</Video>
</MediaContainer>
13

ASS subtitles require a secondary conversion. The entire subtitle sequence must be converted in advance so it can be re-timed to inject back into the video as a SRT text.

If you can remove it for testing purposes, you’ll have the definitive answer.

15

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