Transcoding of H.265 media is extremely broken

Plex Media Server Desktops & Laptops
,
1

Server Version#: 1.18.6.2368
Player Version#: 4.24.2

When I play any H.265 media that has to be transcoded (as when playing on a web client), the stream takes an exceptionally long time to start (30+ seconds) and the audio is completely out of sync, by tens of seconds in fact. Seeking also incurs the same 30+ startup delay.

My hardware is more than capable of transcoding the media (it’s only 1080p), and it used to work absolutely fine, but recent Plex server versions have rendered it completely unwatchable on devices that cannot direct stream H.265.

2

Please verify DEBUG logging enabled, VERBOSE logging disabled.
Now please play the problematic video file for 30 seconds
Stop Playback
Wait 30 seconds
Settings - Server - Troubleshooting - Download Logs

Attach that ZIP file with your next reply.

3

Alright, here’s the logs after playing the file.

Plex Media Server Logs_2020-02-16_02-13-55.zip (3.2 MB)

4

With that CPU whose Passmark score is 5389 with 4 cores yielding some 1347 Passmarks per core, you don’t have enough CPU performance to

  1. Decode the HEVC
  2. Burn the subtitles (which is a single threaded operation and likely the stumbling point)
  3. Convert the audio from 6 channels to 2 channels.
  4. Encode to H.264
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Scaled maximum bitrate for resolution reduction to 401Kbps.
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: Selected protocol dash; container: mp4
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: analyzing media item 9616
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: Direct Play is disabled
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: media must be transcoded in order to use the dash protocol
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: no direct play video profile exists for http/mkv/hevc
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: no direct play video profile exists for http/mkv/hevc/aac
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: no direct play video profile exists for http/mkv/hevc/aac
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Auto Erotic Assimilation - video.bitrate limitation applies: 1429 > 720
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Auto Erotic Assimilation - audio.channels limitation applies: 6 > 2
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: E3 - Auto Erotic Assimilation: no remuxable profile found, so video stream will be transcoded
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: Cannot direct stream video stream due to profile or setting limitations
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Scaled up video bitrate to 6430Kbps based on 4.500000x fudge factor.
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Scaled maximum bitrate for resolution reduction to 401Kbps.
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Auto Erotic Assimilation - audio.channels limitation applies: 6 > 2
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - Auto Erotic Assimilation - audio.channels limitation applies: 6 > 2
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: Cannot direct stream audio stream due to profile or setting limitations
Feb 16, 2020 01:54:43.805 [0x7f0f02e6b700] DEBUG - MDE: Rick and Morty - S2 E3 - Auto Erotic Assimilation: selected media 0 / 9616

Either subtitle burning is “Always on” or the subtitles are image based (PGS, VOBSUB, or DVDRIP).

There is no hardware transcoding capability.

Feb 16, 2020 01:54:43.922 [0x7f0f02e6b700] DEBUG - We're going to try to auto-select a subtitle.
Feb 16, 2020 01:54:43.922 [0x7f0f02e6b700] DEBUG - Audio Stream: 56115, Subtitle Stream: -1
Feb 16, 2020 01:54:43.922 [0x7f0f02e6b700] DEBUG - Found session GUID of 1m4ggmlc9iwvfe153dpecbr3 in session start.
Feb 16, 2020 01:54:43.922 [0x7f0f02e6b700] DEBUG - Cleaning directory for session 1m4ggmlc9iwvfe153dpecbr3 ()
Feb 16, 2020 01:54:43.923 [0x7f0f02e6b700] DEBUG - Starting a transcode session 1m4ggmlc9iwvfe153dpecbr3 at offset -1.0 (state=3)
Feb 16, 2020 01:54:43.923 [0x7f0f02e6b700] DEBUG - [Universal] Using local file path instead of URL: /storage/plexcontent/TV Shows/Rick and Morty/Season 02/Rick and Morty - S02E03 - Auto Erotic Assimilation.mkv
Feb 16, 2020 01:54:43.923 [0x7f0f02e6b700] DEBUG - TPU: hardware transcoding: zero-copy support not present
Feb 16, 2020 01:54:43.924 [0x7f0f02e6b700] DEBUG - Job running: EAE_ROOT='/tmp/pms-6d54e0a4-32e4-457c-984f-cfb175b1449e/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/8bf330d-2937-linux-x86_64/' XDG_CACHE_HOME='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:0' 'hevc' '-codec:1' 'aac' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/storage/plexcontent/TV Shows/Rick and Morty/Season 02/Rick and Morty - S02E03 - Auto Erotic Assimilation.mkv' '-filter_complex' '[0:0]scale=w=480:h=270[0];[0]format=pix_fmts=yuv420p|nv12[1]' '-filter_complex' '[0:1] aresample=async=1:ocl='\''stereo'\'':osr=48000[2]' '-map' '[1]' '-codec:0' 'libx264' '-crf:0' '23' '-maxrate:0' '401k' '-bufsize:0' '802k' '-r:0' '29.969999999999999' '-preset:0' 'veryfast' '-x264opts:0' 'subme=6:me_range=4:rc_lookahead=10:me=hex:8x8dct=1' '-force_key_frames:0' 'expr:gte(t,0+n_forced*8)' '-map' '[2]' '-metadata:s:1' 'language=eng' '-codec:1' 'aac' '-b:1' '125k' '-f' 'dash' '-seg_duration' '8' '-init_seg_name' 'init-stream$RepresentationID$.m4s' '-media_seg_name' 'chunk-stream$RepresentationID$-$Number%05d$.m4s' '-window_size' '5' '-delete_removed' 'false' '-skip_to_segment' '1' '-time_delta' '0.0625' '-manifest_name' 'http://127.0.0.1:32400/video/:/transcode/session/1m4ggmlc9iwvfe153dpecbr3/f068930a-2bc3-478f-aee5-013062784e1c/manifest' '-avoid_negative_ts' 'disabled' '-map_metadata' '-1' '-map_chapters' '-1' 'dash' '-start_at_zero' '-copyts' '-vsync' 'cfr' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/1m4ggmlc9iwvfe153dpecbr3/f068930a-2bc3-478f-aee5-013062784e1c/progress'
5

As I said the hardware is more than capable, despite what the PassMark scores may suggest. Also it’s a dual CPU system (4 cores/8 threads per socket), so concurrent transcodes can utilize both nodes.

It transcodes (and burns subtitles into) other media just fine. When playing the problematic video the transcoder fills the buffer and throttles, suggesting there is plenty of headroom, and at no point does the video pause for buffering once playing. I’m also not even burning subtitles into it, the subtitles are disabled. Like I said, it used to play just fine, but transcoding has been finicky with the recent releases.

6

Have you checked the connection to the player?

Deeper in your logs the connection is being reset.

This is either network drop (unlikely) or stopping the app mid playback (includes app failure)

Feb 16, 2020 01:32:28.956 [0x7f0fb540d700] DEBUG - Transcoder segment range: 0 - 2 (1)
Feb 16, 2020 01:32:28.959 [0x7f0f53159700] DEBUG - Returning segment 1 from session
Feb 16, 2020 01:32:28.960 [0x7f0f53159700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-720e60c6e2d4b56b-com-plexapp-android-4a15475f-c137-438c-824e-b17035c5fefc/media-00001.ts is 8842204 (of total: 8842204).
Feb 16, 2020 01:32:29.627 [0x7f0fcdc44700] DEBUG - Failed to stream media, client probably disconnected after 3375104 bytes: 104 - Connection reset by peer
Feb 16, 2020 01:32:29.627 [0x7f0fcdc44700] DEBUG - Completed after connection close: [10.0.0.75:57578] 200 GET /video/:/transcode/universal/session/720e60c6e2d4b56b-com-plexapp-android/base/00000.ts (15 live) TLS 1988ms 3375104 bytes (pipelined: 1)
Feb 16, 2020 01:32:29.627 [0x7f0fcdc44700] DEBUG - Removed transcode data consumer, active count 2 => 1
Feb 16, 2020 01:32:29.654 [0x7f0fcd956700] DEBUG - Failed to stream media, client probably disconnected after 2326528 bytes: 104 - Connection reset by peer
Feb 16, 2020 01:32:29.654 [0x7f0fcd956700] DEBUG - Completed after connection close: [10.0.0.75:57579] 200 GET /video/:/transcode/universal/session/720e60c6e2d4b56b-com-plexapp-android/base/00001.ts (14 live) TLS 1095ms 2326528 bytes (pipelined: 1)
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Request: [10.0.0.75:57580 (WAN)] GET /video/:/transcode/universal/session/720e60c6e2d4b56b-com-plexapp-android/base/00120.ts (13 live) TLS Signed-in
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Asked for segment 120 from session.
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - We're in a seek: asked for 120, min/max available was 0/1
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Segment #120 WON.
Feb 16, 2020 01:32:29.822 [0x7f0f53159700] DEBUG - Removed transcode data consumer, active count 1 => 0
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Killing job.
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Signalling job ID 4479 with 9
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Job was already killed, not killing again.
Feb 16, 2020 01:32:29.822 [0x7f0fb540d700] DEBUG - Stopping transcode session 720e60c
7

Which Android-based device is this?

plexapp-android/39b5d3ac-9589-405f-b02b-9d2e5268acb1/progress'
Feb 16, 2020 01:32:29.825 [0x7f0fb540d700] DEBUG - Jobs: Starting child process with pid 4515
Feb 16, 2020 01:32:29.825 [0x7f0fb540d700] DEBUG - Started session successfully: 720e60c6e2d4b56b-com-plexapp-android
Feb 16, 2020 01:32:29.826 [0x7f0fb7a23700] DEBUG - Streaming Resource: Resetting play progress due to seek
Feb 16, 2020 01:32:29.828 [0x7f0fce220700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 4479 is -9 (signal: Killed)
Feb 16, 2020 01:32:29.828 [0x7f0fcd956700] DEBUG - Auth: authenticated user 1 as Techjar
Feb 16, 2020 01:32:29.828 [0x7f0f53159700] DEBUG - Request: [10.0.0.50:56294 (Allowed Network (WAN))] GET /status/sessions (12 live) TLS GZIP Signed-in Token (Techjar)
Feb 16, 2020 01:32:29.828 [0x7f0f53159700] DEBUG - [Now] Adding 0 sessions.
Feb 16, 2020 01:32:29.828 [0x7f0fcdc44700] DEBUG - Completed: [10.0.0.50:56294] 200 GET /status/sessions (12 live) TLS GZIP 0ms 429 bytes (pipelined: 4)
Feb 16, 2020 01:32:29.830 [0x7f0f50b43700] DEBUG - Request: [127.0.0.1:59428 (Loopback)] PUT /video/:/transcode/session/720e60c6e2d4b56b-com-plexapp-android/39b5d3ac-9589-405f-b02b-9d2e5268acb1/progress?status=startup (12 live) Signed-in Token (Techjar) (range: bytes=0-)
8

10.0.0.75 is my phone, I was testing playback there earlier, you can ignore it. For the record it plays fine since apparently my phone can decode HEVC (I didn’t know Snapdragon 801 supported that, cool).

10.0.0.50 is the PC I’m using the web client on, where I’m experiencing the transcode problems.

9

I will need pick this up tmorrow. It’s nearly 3am for me.
I thought I’d try to help out a bit tonight (idle time) but this is more detailed than I expected. I want to approach it clearly from the top again.

If you would please include the XML (from top through the </Media> tag, I would appreciate it. It will show me what PMS is making its decisions on.

10

Okay I did a sanity check and it turns out the audio is out of sync in the file. Something must have gone wrong when originally encoding the media to H.265, and I didn’t notice. Sorry for wasting your time with that.

In any case I’d still like to know why the transcoder startup takes so long when playing HEVC content, it used to be faster.

11

I can’t replicate slow startup at all but I also have HW transcoding capability so there is no direct comparison available. My bit rates are too high to even attempt with software also.

12

It’s not the software. My PMS( Version 1.18.8.2527 ) in a container is able to transcode with hardware support HEVC.
Untitled

13

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