@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