Transcoder dies and inotify errors

Plex Media Server Desktops & Laptops
,
1

Server Version#: 1.19.1.2645, but not working properly for months
Player Version#: 4.22.3 (Web) and on the NVidia Shield (latest release)

Whenever I watch a video, it initially works for both direct play and transcoding, but then when I change the resolution, bitrate or audio channels the transcoder crashes with “Transcode runner appears to have died”.

At the same time I can watch nvidia-smi start transcoding, then stop.

If I switch between a few resolutions and audio channels (slowly) then it will eventually transcode and play but there seems to be no logic to it. The same combo of bitrate and audio track will fail sometimes and work others.

Skipping more than 30s ahead or back on a working stream also crashed the transcoder.

Direct play works fine.

I also get hundreds of “Received unexpected inotify event: 8192” errors, which sometimes coincide but may be unrelated. This is despite the inotify settings being set deliberately high both on the plex server and the NFS server:

fs.inotify.max_user_watches = 4194304
fs.inotify.max_queued_events = 8388608
fs.inotify.max_user_instances = 65536

Plex server is running in a Proxmox VM with a Quadro P620 forwarded to it, which is rock solid and used to work fine. It has 16GB RAM and 12 cores assigned to it.

The videos are stored on an NFS share which is mounted with autofs and on ZFS. All video folders and files have full permissions.

There is 256GB free space in the /tmp directory and it’s on an SSD with the correct permissions.

The database is massive and contains video and audio.

Hopefully relevant logs:

Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - Codecs: Testing with profile 'Main 10'
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - nal_unit_type: 32(VPS), nuh_layer_id: 0, temporal_id: 0
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - nal_unit_type: 33(SPS), nuh_layer_id: 0, temporal_id: 0
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - nal_unit_type: 34(PPS), nuh_layer_id: 0, temporal_id: 0
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - nal_unit_type: 20(IDR_N_LP), nuh_layer_id: 0, temporal_id: 0
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Decoding VPS
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Main 10 profile bitstream
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Decoding SPS
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Main 10 profile bitstream
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Decoding VUI
Apr 22, 2020 22:23:17.405 [0x7fce6966c700] DEBUG - [FFMPEG] - Decoding PPS
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Format cuda chosen by get_format().
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Format cuda requires hwaccel initialisation.
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded lib: libnvcuvid.so.1
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidGetDecoderCaps
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCreateDecoder
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidDestroyDecoder
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidDecodePicture
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidGetDecodeStatus
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidReconfigureDecoder
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidMapVideoFrame64
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidUnmapVideoFrame64
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCtxLockCreate
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCtxLockDestroy
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCtxLock
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCtxUnlock
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCreateVideoSource
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCreateVideoSourceW
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidDestroyVideoSource
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidSetVideoSourceState
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidGetVideoSourceState
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidGetSourceVideoFormat
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidGetSourceAudioFormat
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidCreateVideoParser
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidParseVideoData
Apr 22, 2020 22:23:17.406 [0x7fce6966c700] DEBUG - [FFMPEG] - Loaded sym: cuvidDestroyVideoParser
Apr 22, 2020 22:23:17.433 [0x7fce6966c700] DEBUG - Codecs: 10-bit HEVC test succeeded
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - Scaled up video bitrate to 289264Kbps based on 4.500000x fudge factor.
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - Scaled maximum bitrate for resolution reduction to 32140Kbps.
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - Video Name - audio.channels limitation applies: 8 > 2
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - MDE: Cannot direct stream audio stream due to profile or setting limitations
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - MDE: Video Name (Year): selected media 0 / 134520
Apr 22, 2020 22:23:17.566 [0x7fce6966c700] DEBUG - Streaming Resource: Reached Decision id=101032 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=134520 part=(id=159895 decision=transcode container=mp4 protocol=dash streams=(Video=(id=366315 decision=transcode bitrate=3676 encoder=h264_nvenc width=1280 height=720) Audio=(id=366316 decision=transcode bitrate=119 encoder=aac channels=2 rate=48000))))
Apr 22, 2020 22:23:17.567 [0x7fced17fa700] DEBUG - Killing job.
Apr 22, 2020 22:23:17.567 [0x7fced17fa700] DEBUG - Signalling job ID 2445 with 9
Apr 22, 2020 22:23:17.567 [0x7fced17fa700] DEBUG - Job was already killed, not killing again.
Apr 22, 2020 22:23:17.567 [0x7fced17fa700] DEBUG - Stopping transcode session z4j4vmams0pkprlsn5wju9cb
Apr 22, 2020 22:23:17.569 [0x7fced17fa700] DEBUG - Transcoder: Cleaning old transcode directories.
Apr 22, 2020 22:23:17.570 [0x7fced17fa700] DEBUG - Transcoder: Cleaning old transcode directory: "/tmp/Transcode/Sessions/plex-transcode-z4j4vmams0pkprlsn5wju9cb-c080f246-0fd4-403f-90cb-7bb20d0221a5"
Apr 22, 2020 22:23:17.570 [0x7fcf15f45700] DEBUG - Completed: [192.168.0.16:40862] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F101032&mediaIndex=0&partIndex=0&protocol=dash
&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=z4j4vmams0pkprlsn
5wju9cb&subtitles=burn&Accept-Language=en (12 live) TLS GZIP 3628ms 3995 bytes (pipelined: 15)
Apr 22, 2020 22:23:17.570 [0x7fced17fa700] DEBUG - Whacked session z4j4vmams0pkprlsn5wju9cb, 0 remaining.
Apr 22, 2020 22:23:17.571 [0x7fce6affd700] WARN - Transcode runner appears to have died.
Apr 22, 2020 22:23:17.571 [0x7fce6affd700] DEBUG - Session was stopped.
Apr 22, 2020 22:23:17.571 [0x7fcf15744700] DEBUG - Completed: [192.168.0.16:40896] 404 GET /video/:/transcode/universal/dash/z4j4vmams0pkprlsn5wju9cb/0/114.m4s (11 live) TLS GZIP 1002ms 458 bytes (pipelined: 1)
Apr 22, 2020 22:23:17.638 [0x7fce6bfff700] WARN - Transcode runner appears to have died.
Apr 22, 2020 22:23:17.638 [0x7fce6bfff700] DEBUG - Session was stopped.
Apr 22, 2020 22:23:17.638 [0x7fce8e7fc700] DEBUG - Cleaning directory for session z4j4vmams0pkprlsn5wju9cb (/tmp/Transcode/Sessions/plex-transcode-z4j4vmams0pkprlsn5wju9cb-c080f246-0fd4-403f-90cb-7bb20d0221a5)
Apr 22, 2020 22:23:17.638 [0x7fce8e7fc700] DEBUG - Deleting stale file "/tmp/pms-2503240f-aa1e-4365-a11f-8f6c9c2d3675/EasyAudioEncoder/Convert to WAV (to 8ch or less)/z4j4vmams0pkprlsn5wju9cb_2445-0-7.wav"
Apr 22, 2020 22:23:17.639 [0x7fcf15744700] DEBUG - Completed: [192.168.0.16:40892] 404 GET /video/:/transcode/universal/dash/z4j4vmams0pkprlsn5wju9cb/1/114.m4s (11 live) TLS GZIP 1102ms 458 bytes (pipelined: 2)
Apr 22, 2020 22:23:17.639 [0x7fce8e7fc700] DEBUG - Deleting stale file "/tmp/pms-2503240f-aa1e-4365-a11f-8f6c9c2d3675/EasyAudioEncoder/Convert to WAV (to 8ch or less)/z4j4vmams0pkprlsn5wju9cb_2445-0-7.mlp"
Apr 22, 2020 22:23:17.676 [0x7fcf1d3e9700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 2445 is -9 (signal: Killed)
1 Like
2

Any help with this would be greatly appreciated and will definitely affect whether I renew my annual membership at the end of the month.

Thanks!

3

It’s impossible to diagnose what’s happening based on the fragment of information provided.

Please verify the server logging is set DEBUG ON and VERBOSE OFF
Restart PMS
(given the size of the library) – Allow to sit idle for 2 minutes

Now download and attach the Log ZIP file.

As a side note: Saying it hasn’t worked right for months and only now asking for assistance while asserting a passive-aggressive “the support I get will determine if I renew or not” is not well received by most. Proxmox is a HyperVisor . It isn’t a supported formal “Distribution”. That not withstanding, the frustration and desire to make it work correctly is understood. The delay and initial statement prose is not.

4

Hi,

Thanks for replying, I appreciate it. I’ll do those steps as soon as I can.

I waited so long because I didn’t want to waste your time and several others seemed to have the same problem. I’ve been systematically trying all of the suggestions I could find on this forum and others and none have helped, and that has taken a while.

The server itself is installed on a Ubuntu VM. I realise Proxmox isn’t officially supported but it has worked in this configuration before so I’m hoping it will work again. I don’t have the money for a dedicated server.

I didn’t mean to be passive aggressive about mentioning my subscription, it’s just a fact that how well a piece of software works affects how much I want to pay for it. Also, that as I’ve been a customer for several years and want to keep paying might show some loyalty that might be reciprocated.

I was (and am) trying to be unemotional and state as many facts as I can that might be relevant. It was not my intention to be rude and I am sorry if you felt I was, I don’t really do passive aggressive.

5

If you’ve got it in a VM (which is what Proxmox does) and your guest OS is Ubuntu, then it should be predictable enough to resolve.

I ask for the logs so I may verify which message is being returned.
There are two type of inotify errors.
Knowing which one allows me to give the proper instructions.

6

Thanks, I have the logs. Where can I upload them securely please? They have my public IP and username in them as well as my entire library so I can’t upload them publicly.

7

Please check your PM

8

For anyone that comes here in future, the problem ended up being autofs. More specifically, when autofs unmounts a share (like it is supposed to), it results in all the inotify watches that plex uses to monitor changes being dropped, and Plex doesn’t notice and recover/recreate them.

The same happens for any share that is dropped and reconnected through any protocol. Things that would probably also cause the same problem would be:

  • network outages on shares
  • automount and autofs
  • rebooting your storage server without also restarting the Plex server
  • disconnecting a local drive and reconnecting it, although Plex may have the ability to recognise local drives being mounted/unmounted

As transcoding also requires inotify watches, it could be that the dropped ones were causing problems for that too.

The 8192 was a red herring as nothing in my system has or had that as a limit, and a value for max_user_watches that was too low resulted in a different error:

[Notify] Failed to add watch for "/mnt/Media/xyz" (28: No space left on device)

The solutions are:

  • Disable automatic scanning in the General tab for the server, or
  • Restart the plex server service if the share is dropped

Also, disabling autofs’ unmounting (set timeout to 0) makes it a lot more stable, as does switching from NFS (that doesn’t support inotify) to samba 3+ (that does).

After all that I no longer get any inotify errors, and transcoding is more stable and a lot faster.

If anyone comes up with a better solution, please let me know.

Big thanks to @ChuckPa for all the help and patience over PM.

1 Like
9

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