PMS Version 1.30.1.6562 - this update stopped my transcodes from working

Responding here as well to share with everyone following.

  1. Build 6617 had a fixed buffer size of 8 decode frames (VERY wasteful)

  2. Build 6638 provides
    – Default buffer size = 1 (good for most)
    – Ability to tune to your needs (Preferences.xml or API setting)

  3. To tune:
    – Preferences.xml nvdecExtraFrames="X" where “X” is 2 → whatever you need
    AT THE COST OF VIDEO MEMORY
    ( I tested N=1, Memory used = 683 MB, Tested N=16, Memory used = 1580 MB )

I’m guessing, if we’re only running a couple if concurrent transcodes, 8 should be fine if the ram fits?

Anything specific you want us (@xenago) to test/check? Other than making sure we’re not overload cram usage?

I am testing plexmediaserver_1.31.1.6638-fad659ac6_amd64.deb. Have tried nvdecExtraFrames every number between 1-8. Getting Conversion failed. A required codec could not be found or failed to install. on all playback.

A snippet from the logs:

Jan 29, 2023 12:37:00.207 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:00.271 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:00.669 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:00.734 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:01.126 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:01.193 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:01.564 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:01.628 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:01.971 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:02.037 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:02.388 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:02.453 [0x7ffff1b96b38] ERROR - [Req#194a/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:02.849 [0x7ffff1b96b38] ERROR - [Req#1959/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 12:37:02.849 [0x7fffef81eb38] ERROR - [Req#1959/Transcode] Error configuring transcoder: Decoder install failed: h264

@Ossalingur Out of interest, what version of the Nvidia drivers are you using?

@Minxster

Running debian bookworm with nvidia-driver 510.108.03-3

I don’t know if these test versions of PMS are more weighted towards the CUDA version 12? Meaning, I think you could/may need v525 (or above 515). But don’t quote me on this :wink::+1:

Folks,
There have been a few more builds.
Our build system only keeps a limited number of experimental builds which is why the h264 decoder binaries are no longer available

Please try to download this.

I don’t know if it includes or not. (there are several builds floating around)

@ChuckPa I still get the same error on v1.31.1.6641-caf2b005c.

Jan 29, 2023 23:08:05.032 [0x7ffff33b1b38] INFO - Plex Media Server v1.31.1.6641-caf2b005c - Docker Docker Container (LinuxServer.io) x86_64 - build: linux-x86_64 debian - GMT 00:00
Jan 29, 2023 23:12:54.042 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:54.108 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:54.893 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:54.959 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:56.057 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:56.129 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:56.602 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:56.669 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:57.553 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:57.620 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:57.929 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:57.996 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:58.758 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:58.826 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:58.893 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:12:59.944 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:00.011 [0x7ffff006cb38] ERROR - [Req#6a0/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:00.090 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:00.836 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:00.905 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:01.667 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:01.735 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:01.810 [0x7ffff006cb38] ERROR - [Req#6a5/Transcode] Codecs: Failed to download XML for codec 'h264_decoder'
Jan 29, 2023 23:13:01.810 [0x7fffee5cbb38] ERROR - [Req#6a5/Transcode] Error configuring transcoder: Decoder install failed: h264

Thanks for the update, I’ve run through again and still having my issues. I started to play files at around 23:16. It starts DirectPlay fine, then I changed to lower mbps. I tried this once one a film then once on a tv show.

Plex Media Server Logs_2023-01-29_23-20-23.zip (2.0 MB)


I will need find out which build to use.

Given the amount of development / builds over the past few days, I’m nor surprised the “Experimental” space filled up and it purged the older builds ( :point_up: )

The stupid thing is if you back down off 525 drivers, everything works.

Does 6638 still work?

6638 just seemed to be the same for me, in that generally it seemed to work with directplay. Just manually lowering the mbps (for transcode) seems to just mess-up. TBH, all I tried were the two video files and then closed that VM snapshot. I’ve not touched Nvidia drivers, so it’s still on 525 :wink:

@Minxster

  1. It will always try to DirectPlay. Plex/web reports optimistically. Whatever it settles into is what it is.

  2. You can set transcode logging level back to error

I’m not seeing the actual error occur. I only see a killed message.

What’s the problem? HW not engaging?

Do you have subtitles in it?

I’m wondering if the problems I’m seeing are a different problem to what others have had!? Just a thought.

I’ll fire it up again now and re-enable the transcode logging. I don’t know why it would turn off, unless it did that during the PMS upgrade? :man_shrugging:

The problem I’m seeing is that when I force a transcode, it has a 50/50 chance of it working. In that the client just sits there showing nothing. And the logs seem to just show FFMPEG/Transcoder just quiting itself? If I just pick another mbps a few times, it all kicks in and works?

(firing up my vm snapshot now)

Just about your subtitles question… In the screenshots I posted earlier, they were set to none?

So I’ve changed the TranscoderLogLevel back to Error. Went to play a film, and it remembered to play at 2mbps, it fired up and seemed to be transcoding fine. I then just switched to another mbps and it just fell over again :man_shrugging:

Plex Media Server Logs_2023-01-30_00-09-51.zip (1.7 MB)

That’s what makes no sense.

There is no repeatability with the failure.

If you’re hard pressed to bring it back up then the only thing I can suggest is downgrade the Nvidia drivers to 515.86.01

This IS CUDA version 12.0 – Expecting perfect code ? Don’t think so.

@ChuckPa - I’ve edited my opening post as things are fluid so things have changed a little.

When I originally posted (this topic) the latest version of PMS just made this transcoding situation worse, as in 9/10 times it would not transcode something. Going back to 1.29 made it better, but with all of the “looking at things in detail”, this odd transcoding hiccup is quite repeatable for me.

Honestly, no idea why. The family are all ok watching (a few of them are remote on cheap Roku boxes) media and have reported no hiccups (now on 1.29.x) at all and they always have to transcode the files. But this testing, in detail, just shows that something wonky is happened.

So I’ve tried to go through the logs (that I uploaded before). It’s obviously difficult for me as I’m not familiar with the inner workings of PMS. But there are some very strange things being logged…

Have a slow read through, I’ve just tried to pick out bits and just make some comments. We really need to do something about PMS constantly messing with VAAPI. But it’s also showing messages that are just problematic! You can see my full log file from an earlier post #73

Start of request to play film:
Jan 30, 2023 00:08:20.908 [0x7f3ecdd97b38] DEBUG - [Req#89a8] Augment: Found a provider match for 'Alita: Battle Angel'.

Lots of checking and re-checking VAAPI - this is far too crazy the amount of times it checks!? And I know ESXi/VM is set with SVGA.Present as FALSE
PMS is showing this, but it just keeps on trying multiple times!?
Jan 30, 2023 00:08:20.940 [0x7f3eceaf6b38] ERROR - [Req#89d4/Transcode] [FFMPEG] - libva: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
Jan 30, 2023 00:08:20.940 [0x7f3eceaf6b38] ERROR - [Req#89d4/Transcode] [FFMPEG] - Failed to initialise VAAPI connection: -1 (unknown libva error).
Jan 30, 2023 00:08:20.940 [0x7f3eceaf6b38] DEBUG - [Req#89d4/Transcode] Codecs: hardware transcoding: opening hw device failed - probably not supported by this system, error: I/O error

First transcode file being PUT ready for the client to GET
Jan 30, 2023 00:08:28.149 [0x7f3ecc198b38] DEBUG - [Req#8e3e/Transcode/JobRunner] Jobs: Starting child process with pid 3238
Jan 30, 2023 00:08:28.166 [0x7f3eceaf6b38] DEBUG - Request: [127.0.0.1:45956 (Loopback)] PUT /video/:/transcode/session/oqiydjxj0poespkmb52rngmm/f7c55f90-4090-4933-bfd4-9a6d6f9b592a/progress?status=startup (14 live) #916f Signed-in Token (Minxster) (range: bytes=0-) 
Jan 30, 2023 00:08:28.166 [0x7f3ed111fb38] DEBUG - Completed: [127.0.0.1:45956] 204 PUT /video/:/transcode/session/oqiydjxj0poespkmb52rngmm/f7c55f90-4090-4933-bfd4-9a6d6f9b592a/progress?status=startup (14 live) #916f 0ms 203 bytes (pipelined: 1) (range: bytes=0-) 

---

Me switchingn to different mbps
Jan 30, 2023 00:09:02.128 [0x7f3ecc96cb38] DEBUG - Request: [192.168.1.160:52484 (Allowed Network (Subnet))] GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F616574&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=wan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=pbwqgmvk6amu87r86c4twb10&subtitles=burn&Accept-Language=en-GB (12 live) #a688 GZIP Signed-in
Jan 30, 2023 00:09:02.128 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Found session GUID of pbwqgmvk6amu87r86c4twb10 in session start.
Now starts the dance with PMS working out VAAPI, again!!!

Why is this still being logged?
Jan 30, 2023 00:09:03.895 [0x7f3ecc96cb38] ERROR - [Req#a688/Transcode] [FFMPEG] - libva: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
Jan 30, 2023 00:09:03.895 [0x7f3ecc96cb38] ERROR - [Req#a688/Transcode] [FFMPEG] - Failed to initialise VAAPI connection: -1 (unknown libva error).

Transcoder works out it's calculated mbps is over 4mbps, so will make another adjustment
Jan 30, 2023 00:09:03.451 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Streaming Resource: Calculated bandwidth of 4469kbps exceeds bandwidth limit. Changing decision parameters provided by client to fit bandwidth limit of 4000kbps

Origianl transcode job, 3238 has been killed
Jan 30, 2023 00:09:04.215 [0x7f3ebdcdfb38] DEBUG - [Req#aa65/Transcode] Signalling job ID 3238 with 9
Jan 30, 2023 00:09:04.215 [0x7f3ebdcdfb38] DEBUG - [Req#aa65/Transcode] Job was already killed, not killing again.

Getting ready to start new transcoding, seems it knows to use nvec. Yet later in the logs it's still messing with vaapi!?!?!?
Jan 30, 2023 00:09:04.216 [0x7f3eceaf6b38] DEBUG - [Req#aa65/Transcode] TPU: hardware transcoding: final decoder: nvdec, final encoder: nvenc
Jan 30, 2023 00:09:04.216 [0x7f3eceaf6b38] DEBUG - [Req#aa65/Transcode/JobRunner] Job running: CUDA_CACHE_PATH="/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Shaders/CUDA" EAE_ROOT=/tmp/pms-77bd91d5-b74b-46d1-a25c-c0118a8883b8/EasyAudioEncoder FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/89482f6-4464-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx49ac-aa0c-f2614613e2fe "/usr/lib/plexmediaserver/Plex Transcoder" -codec:0 hevc -hwaccel:0 nvdec -hwaccel_fallback_threshold:0 10 -threads:0 1 -extra_hw_frames:0 1 -hwaccel_output_format:0 cuda -hwaccel_device:0 cuda -codec:1 truehd_eae -eae_prefix:1 pbwqgmvk6amu87r86c4twb10_ -analyzeduration 20000000 -probesize 20000000 -i "/media/truenas_media/Films/4K/Alita Battle Angel 2019 REMUX 2160p (10bit) BluRay UHD HDR HEVC Atmos DTS-HD MA 7/Alita.Battle.Angel.2019.REMUX.2160p.(10bit).BluRay.UHD.HDR.HEVC.Atmos.DTS-HD.MA.7.mkv" -filter_complex "[0:0]hwupload[0];[0]scale_cuda=w=720:h=404:format=p010[1];[1]tonemap_cuda=mobius:nv12[2]" -map "[2]" -metadata:s:0 language=eng -codec:0 h264_nvenc -b:0 1293k -maxrate:0 1724k -bufsize:0 3448k -forced-idr:0 1 -r:0 23.975999999999999 -force_key_frames:0 "expr:gte(t,n_forced*8)" -filter_complex "[0:1] aresample=async=1:ochl='stereo':rematrix_maxval=0.000000dB:osr=48000[3]" -map "[3]" -metadata:s:1 language=eng -codec:1 aac -b:1 162k -f dash -seg_duration 8 -dash_segment_type mp4 -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/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/manifest?X-Plex-Http-Pipeline=infinite" -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 dash -start_at_zero -copyts -vsync cfr -init_hw_device cuda=cuda: -filter_hw_device cuda -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress
Jan 30, 2023 00:09:04.216 [0x7f3eceaf6b38] DEBUG - [Req#aa65/Transcode/JobRunner] In directory: "/dev/shm/Plex/Transcode/Sessions/plex-transcode-pbwqgmvk6amu87r86c4twb10-c3eb0a01-ecdd-4d66-b249-a18ecd264133"
Jan 30, 2023 00:09:04.216 [0x7f3eceaf6b38] DEBUG - [Req#aa65/Transcode/JobRunner] Jobs: Starting child process with pid 3322


Some data being PUT into new transcode folder/session
Jan 30, 2023 00:09:04.220 [0x7f3ecd58bb38] DEBUG - Request: [127.0.0.1:45372 (Loopback)] PUT /video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress?status=startup (13 live) #ad4b Signed-in Token (Minxster) (range: bytes=0-) 
Some more
Jan 30, 2023 00:09:04.487 [0x7f3ecd58bb38] DEBUG - Request: [127.0.0.1:45372 (Loopback)] PUT /video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress?status=startup (14 live) #ad95 Signed-in Token (Minxster) (range: bytes=0-) 
Jan 30, 2023 00:09:04.487 [0x7f3ed1322b38] DEBUG - Completed: [127.0.0.1:45372] 204 PUT /video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress?status=startup (14 live) #ad95 0ms 203 bytes (pipelined: 2) (range: bytes=0-) 
Jan 30, 2023 00:09:04.487 [0x7f3ecb563b38] DEBUG - Request: [127.0.0.1:45372 (Loopback)] PUT /video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress?status=opening (14 live) #ae3d Signed-in Token (Minxster) (range: bytes=0-) 
Jan 30, 2023 00:09:04.487 [0x7f3ed111fb38] DEBUG - Completed: [127.0.0.1:45372] 204 PUT /video/:/transcode/session/pbwqgmvk6amu87r86c4twb10/c3eb0a01-ecdd-4d66-b249-a18ecd264133/progress?status=opening (14 live) #ae3d 0ms 203 bytes (pipelined: 3) (range: bytes=0-) 
There are some more in the original log file...



Just another reference to job 3238 being killed off
Jan 30, 2023 00:09:04.387 [0x7f3ed155cb38] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 3238 is -9 (signal: Killed)


Why is this still doing something? It said it was starting the new transcode in nvec???
Jan 30, 2023 00:09:04.696 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Codecs: testing hevc (decoder) with hwdevice vaapi
Jan 30, 2023 00:09:04.697 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Codecs: hardware transcoding: testing API vaapi
Jan 30, 2023 00:09:04.697 [0x7f3ecc96cb38] ERROR - [Req#a688/Transcode] [FFMPEG] - libva: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
Jan 30, 2023 00:09:04.697 [0x7f3ecc96cb38] ERROR - [Req#a688/Transcode] [FFMPEG] - Failed to initialise VAAPI connection: -1 (unknown libva error).
Jan 30, 2023 00:09:04.697 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Codecs: hardware transcoding: opening hw device failed - probably not supported by this system, error: I/O error


---

Transcode stopping and a clean-up process taking place, for original transcode
I'm noting this only because look at the last line of all of this...
Jan 30, 2023 00:09:04.215 [0x7f3ebdcdfb38] DEBUG - [Req#aa65/Transcode] Stopping transcode session oqiydjxj0poespkmb52rngmm
Jan 30, 2023 00:09:04.216 [0x7f3eccf82b38] DEBUG - [Req#aa65/Transcode] Cleaning directory for session oqiydjxj0poespkmb52rngmm (/dev/shm/Plex/Transcode/Sessions/plex-transcode-oqiydjxj0poespkmb52rngmm-f7c55f90-4090-4933-bfd4-9a6d6f9b592a)


Why is PMS killing the transcode job? But it was already PUTting files in the session folder?
Jan 30, 2023 00:09:05.785 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Codecs: 10-bit HEVC test succeeded
Jan 30, 2023 00:09:05.842 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Alita: Battle Angel - audio.channels limitation applies: 8 > 6
Jan 30, 2023 00:09:05.842 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] MDE: Cannot direct stream audio stream due to profile or setting limitations
Jan 30, 2023 00:09:05.842 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] MDE: Alita: Battle Angel (2019): selected media 0 / 933026
Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Killing job.
Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Signalling job ID 3322 with 9
Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Job was already killed, not killing again.
Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Stopping transcode session pbwqgmvk6amu87r86c4twb10
Jan 30, 2023 00:09:05.842 [0x7f3eccb6fb38] DEBUG - [Req#a688/Transcode] Cleaning directory for session pbwqgmvk6amu87r86c4twb10 (/dev/shm/Plex/Transcode/Sessions/plex-transcode-pbwqgmvk6amu87r86c4twb10-c3eb0a01-ecdd-4d66-b249-a18ecd264133)
Jan 30, 2023 00:09:05.842 [0x7f3ecc96cb38] DEBUG - [Req#a688/Transcode] Streaming Resource: Reached Decision id=616574 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=933026 part=(id=998584 decision=transcode container=mp4 protocol=dash streams=(Video=(id=1874346 decision=transcode bitrate=3676 encoder=h264_nvenc width=1280 height=720) Audio=(id=1874347 decision=transcode bitrate=119 encoder=aac channels=2 rate=48000))))
Jan 30, 2023 00:09:05.843 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Transcoder: Cleaning old transcode directories.


Client clearly doesn't know what is going on, or ddn't got the memo that the transcode was cancelled!?
The client is requesting the files, but is getting a 404, because the job was cancelled and a clean-up started
Jan 30, 2023 00:09:06.035 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52621] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b046 GZIP 1101ms 379 bytes (pipelined: 3)
Jan 30, 2023 00:09:06.035 [0x7f3ecd58bb38] DEBUG - [Req#b04d/Transcode] Deleting stale file "/tmp/pms-77bd91d5-b74b-46d1-a25c-c0118a8883b8/EasyAudioEncoder/Convert to WAV (to 8ch or less)/pbwqgmvk6amu87r86c4twb10_3322-0-9.mlp"
Jan 30, 2023 00:09:06.035 [0x7f3ecd58bb38] DEBUG - [Req#b04d/Transcode] Deleting stale file "/tmp/pms-77bd91d5-b74b-46d1-a25c-c0118a8883b8/EasyAudioEncoder/Convert to WAV (to 8ch or less)/pbwqgmvk6amu87r86c4twb10_3322-0-9.wav"
Jan 30, 2023 00:09:06.036 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b04d GZIP 1102ms 379 bytes (pipelined: 3)
Jan 30, 2023 00:09:06.569 [0x7f3ecc96cb38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b41b GZIP Signed-in
Jan 30, 2023 00:09:06.569 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b41b GZIP 0ms 379 bytes (pipelined: 4)
Jan 30, 2023 00:09:06.905 [0x7f3eceaf6b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b420 GZIP Signed-in
Jan 30, 2023 00:09:06.906 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b420 GZIP 0ms 379 bytes (pipelined: 5)
Jan 30, 2023 00:09:07.592 [0x7f3ecb563b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b424 GZIP Signed-in
Jan 30, 2023 00:09:07.593 [0x7f3ed1322b38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b424 GZIP 0ms 379 bytes (pipelined: 6)
Jan 30, 2023 00:09:08.654 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b42a GZIP Signed-in
Jan 30, 2023 00:09:08.654 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b42a GZIP 0ms 379 bytes (pipelined: 7)
Jan 30, 2023 00:09:10.650 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b42f GZIP Signed-in
Jan 30, 2023 00:09:10.650 [0x7f3ed1322b38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b42f GZIP 0ms 379 bytes (pipelined: 8)
Jan 30, 2023 00:09:14.602 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b434 GZIP Signed-in
Jan 30, 2023 00:09:14.602 [0x7f3ed1322b38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b434 GZIP 0ms 379 bytes (pipelined: 9)
Jan 30, 2023 00:09:21.160 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b439 GZIP Signed-in
Jan 30, 2023 00:09:21.160 [0x7f3ed111fb38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (13 live) #b439 GZIP 0ms 379 bytes (pipelined: 10)
Jan 30, 2023 00:09:22.057 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b456 GZIP Signed-in
Jan 30, 2023 00:09:22.057 [0x7f3ed1322b38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/1/header (13 live) #b456 GZIP 0ms 379 bytes (pipelined: 11)
Jan 30, 2023 00:09:34.911 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (10 live) #b45b GZIP Signed-in
Jan 30, 2023 00:09:34.911 [0x7f3ed1322b38] DEBUG - Completed: [192.168.1.160:52620] 404 GET /video/:/transcode/universal/session/pbwqgmvk6amu87r86c4twb10/0/header (10 live) #b45b GZIP 0ms 379 bytes (pipelined: 12)

Me stopping the "attempted" playback, even though it was stopped for no reason?
Jan 30, 2023 00:09:41.942 [0x7f3ecc198b38] DEBUG - Request: [192.168.1.160:52620 (Allowed Network (Subnet))] GET /:/timeline?ratingKey=616574&key=%2Flibrary%2Fmetadata%2F616574&playbackTime=67761&playQueueItemID=706975&state=stopped&hasMDE=1&context=library%3Acontent.library&row=1&col=1&time=30000&duration=7317000 (10 live) #b463 GZIP Signed-in
Jan 30, 2023 00:09:41.942 [0x7f3ecc198b38] DEBUG - [Req#b463] Client [n3gvx3lq78qnwl8alrjwtj9n] reporting timeline state stopped, progress of 30000/7317000ms for guid=, playbackTime=67761ms ratingKey=616574 url=, key=/library/metadata/616574, containerKey=, metadataId=616574, source=



Why is this transcode session still cleaning something? Seems a bit odd? 
Jan 30, 2023 00:09:42.066 [0x7f3ecc198b38] DEBUG - [Req#b463] Cleaning directory for session oqiydjxj0poespkmb52rngmm (/dev/shm/Plex/Transcode/Sessions/plex-transcode-oqiydjxj0poespkmb52rngmm-f7c55f90-4090-4933-bfd4-9a6d6f9b592a)

The main bit for me is why is PMS stopping/killing it’s own transcode? It’s killing it off and the client is about to start asking for files?

Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Killing job.
Jan 30, 2023 00:09:05.842 [0x7f3ec9311b38] DEBUG - [Req#a688/Transcode] Signalling job ID 3322 with 9
1 Like

If you disable hardware-accelerated video encoding in the transcoder settings, are you able to change quality in the web client successfully?

2 Likes

@Adarnof for me changing the transcoder settings on chrome, works every time on CPU or Intel GPU, and almost never on NVIDIA (maybe 5-10% of the time).

I am pretty certain it’s because of the constant VAAPI / NVENC flapping, and have been searching for a solution to get transcoding working properly on NVIDIA, on any PMS version really.

I can confirm that if I turn off all HW transcoding, it all worked fine. I can switch between bandwidth multiple times and the transcoding is all to do so. I’m not sure what it’s telling us, but it is telling us something :man_shrugging:

Edit: FYI, when I did this I turned off all h/w related transcoding to just see how software transcoding would work. However just messing with “hardware-accelerated video encoding” yielded some surprising results! :wink::+1:

1 Like

The rather long and arduous task of going over my PMS logs (took me hours to try and understand them) just showed me that the transcoder was still checking VAAPI even though it had already started a new transcode?!! Which makes no sense! I was the only user on the server and know it was only me streaming one thing and switching between bandwidths (to force a transcode). It’s a waste of time and resource to be doing this so often and does actually slow down the responsiveness of the server. There just isn’t the need to do this all the time.

For the life of me I don’t know why PMS doesn’t just do one check (after every reboot or service start, as new hardware could have been installed in server/VM)) and decided if VAAPI and/or NVENC is available. After that, it just uses what is available with no extra faff with re-testing every time!

1 Like