Transcoding problem when only audio is being transcoded

Plex Media Server
,
1

Server Version#: 1.31.2.6810
Player Version#: 2.113.1.70 Xbox App running on a Xbox One X

I have a question/issue that I’m currently facing.
I am running my Plex server on a Ubuntu Server 20.04, i5-2400 (Sandy Bridge) and 1050ti machine.
While using the Nvidia GPU for HW transcoding, everything works great.
The problem I’m facing though is when only audio is being transcoded (EAC3 7.17 → AAC 5.1 for example) and the video is being direct streamed, the server is not using HW transcoding.
It initially works alright though, but usually will stop mid playback, look like it loads for a few minutes than spit out the following error message and completely stop playback:
“Playback Error
An unexpected playback error occurred”
If I manually lower the quality and thus force video transcoding, the HW transcoding kicks in and it runs with no issues.
I have also attached part of my server logs, please let me know if it’s enough, thank you!
Plex Media Server.log (17.7 KB)

2

Please turn DEBUG logging back on and recapture

Can’t see what we need to see (decisions made) with it off.

4

Thank you for your reply! I have switched the debug logging on, but I don’t seem to be getting new information in my logs, this is what I have:

image
image897×508 57 KB

Am I doing something wrong with the logs?

5

You’re showing me a screenshot of the logs. Having the full logs ZIP file would be better but, in this case, you provided enough information for me to answer.

I suspect you have a lot of well-curated (structured) media in your Plex server.
Depending on the Linux kernel used, you can run out of inotify slots without realizing.

– Pre-5.0 kernels have a default limit of 8192 directories
– Post-5.0 kernels have a default limit of 65536 directories

The transcoder needs 2 inotify slots when transcoding any Dolby audio.
(The software they provide requires it).

The solution for you is to:

  1. Count up the total number of directories you have in use for your media
  2. Round up to the next multiple of 32768 (or 65536 if you have ample memory)
  3. Customize the kernel configuration.

Here is the How-To

6

Hmm, this doesn’t seem to be the issue, because I don’t have that many directories, according to the command I only have 258 directories:

image

I think the default number of directories should be more than enough, right?

7

I have reproduced the problem once more (with debug logging enabled) and have attached the whole logs zip, hope that’s of help!
Just a short info, in order to reproduce the problem on command, I have to start the playback and have to fast forward a bit (in order to avoid just waiting for the issue to randomly pop-up mid playback, because it sometimes take a while).
Plex Media Server Logs_2023-03-17_21-46-52.zip (459.5 KB)

8

Thanks for the logs but you forgot to click SAVE after enabling DEBUG logging.

(don’t worry, I do it too) LOL

9

Sorry, I could’ve sworn I saved it. One more try:

Plex Media Server Logs_2023-03-17_21-59-36.zip (432.0 KB)

10

Ummmm… :thinking:

You sure I’m getting the logs from the right machine?

Don’t set PLAYER DEBUG - You want SERVER debug

( Settings - Server - General - Show Advanced )

Mar 17, 2023 21:42:56.538 [0x7fb993269b38] INFO - Plex Media Server v1.31.2.6810-a607d384f - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT 00:00
Mar 17, 2023 21:42:56.539 [0x7fb993269b38] INFO - Linux version: 20.04.6 LTS (Focal Fossa), language: en-US
Mar 17, 2023 21:42:56.539 [0x7fb993269b38] INFO - Processor: 4-core         Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz
Mar 17, 2023 21:42:56.539 [0x7fb993269b38] INFO - Compiler is - Clang 11.0.1 (https://plex.tv 9b997da8e5b47bdb4a9425b3a3b290be393b4b1f)
Mar 17, 2023 21:42:56.539 [0x7fb993269b38] INFO - /usr/lib/plexmediaserver/Plex Media Server
Mar 17, 2023 21:42:56.693 [0x7fb9934fbaa8] INFO - [CERT/OCSP] Successfully retrieved response from cache.
Mar 17, 2023 21:42:56.848 [0x7fb9934fbaa8] INFO - Running migrations. (EPG 0)
Mar 17, 2023 21:42:58.160 [0x7fb9934fbaa8] INFO - Running migrations. (EPG 0)
Mar 17, 2023 21:42:58.430 [0x7fb990962b38] WARN - Crash: Crash reporting disabled
Mar 17, 2023 21:42:58.817 [0x7fb98fd50b38] WARN - [MediaProviderManager] Unrecognized MediaProvider feature: availability
Mar 17, 2023 21:42:58.817 [0x7fb98fd50b38] WARN - [MediaProviderManager] Unrecognized MediaProvider feature: availability-platforms
Mar 17, 2023 21:42:58.820 [0x7fb990fa7b38] WARN - [MediaProviderManager] Unrecognized MediaProvider feature: availability
Mar 17, 2023 21:42:58.820 [0x7fb990fa7b38] WARN - [MediaProviderManager] Unrecognized MediaProvider feature: availability-platforms
Mar 17, 2023 21:43:01.617 [0x7fb98fb18b38] INFO - Refreshing paths watched by LibraryUpdateManager
Mar 17, 2023 21:43:03.530 [0x7fb992c04b38] WARN - [EventSourceClient/pubsub/172.105.245.178:443] MyPlex: attempted a reachability check but we're not yet mapped.
Mar 17, 2023 21:43:16.964 [0x7fb98cb3fb38] INFO - [Req#cb] AutoUpdate: no updates available
Mar 17, 2023 21:43:32.600 [0x7fb98ff53b38] WARN - [Req#fa] QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
Mar 17, 2023 21:43:32.604 [0x7fb98ff53b38] WARN - [Req#fa] QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Mar 17, 2023 21:44:04.342 [0x7fb98f50fb38] ERROR - [Req#139] Unable to find client profile for device; platform=Xbox, platformVersion=10.0.22621.3680, device=Xbox, model=Xbox One X
Mar 17, 2023 21:44:04.545 [0x7fb98f50fb38] INFO - [Req#14a/Transcode] CodecManager: starting EAE at "/tmp/pms-f5021a8e-5f9e-4e72-9fcc-cc9848d0960f/EasyAudioEncoder"
11

You are of course right, I was enabling the debug on my web player… Sorry again, third time’s the charm:

Plex Media Server Logs_2023-03-17_22-08-04.zip (611.9 KB)

12

First up… You have a configuration error in the domain / dns there.

It’s making PMS push you away as “Non-Local”

Mar 17, 2023 22:05:00.880 [0x7fb992c04b38] DEBUG - Request came in with unrecognized domain / IP ‘s192.168.0.101’ in header Host; treating as non-local

This is a problem… Severe database fragmentation. (need optimize and then restart PMS)

Mar 17, 2023 21:44:15.356 [0x7fb98c333b38] WARN - [Req#2c1/Transcode/Req#35d] SLOW QUERY: It took 9710.000000 ms to retrieve 1 items.

This appears to be the root cause but we’ll know better after you take care of the first items

Mar 17, 2023 22:04:50.973 [0x7fb992c04b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:50.973 [0x7fb992c04b38] DEBUG - Removed transcode data consumer, active count 12 => 11
Mar 17, 2023 22:04:50.973 [0x7fb99075fb38] DEBUG - [Req#540c] [Now] Adding 0 sessions.
Mar 17, 2023 22:04:50.987 [0x7fb99035bb38] DEBUG - [Req#54a4] Audio Stream: 31802, Subtitle Stream: 31804
Mar 17, 2023 22:04:51.027 [0x7fb98e46bb38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.028 [0x7fb992e07b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:51.028 [0x7fb992e07b38] DEBUG - Removed transcode data consumer, active count 11 => 10
Mar 17, 2023 22:04:51.077 [0x7fb984cfbb38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.077 [0x7fb992c04b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:51.077 [0x7fb992c04b38] DEBUG - Removed transcode data consumer, active count 10 => 9
Mar 17, 2023 22:04:51.140 [0x7fb98b924b38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.140 [0x7fb992e07b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:51.140 [0x7fb992e07b38] DEBUG - Removed transcode data consumer, active count 9 => 8
Mar 17, 2023 22:04:51.177 [0x7fb98d04db38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.178 [0x7fb992e07b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:51.178 [0x7fb992e07b38] DEBUG - Removed transcode data consumer, active count 8 => 7
Mar 17, 2023 22:04:51.249 [0x7fb98da5cb38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.249 [0x7fb98bb3db38] DEBUG - [TranscodeOutputStream] Input processing thread exited after writing 5218 bytes, m_closed=1, m_endOfFileReached=1, session->isStopped()=1
Mar 17, 2023 22:04:51.250 [0x7fb992c04b38] DEBUG - [TranscodeOutputStream] Timed out waiting for data
Mar 17, 2023 22:04:51.250 [0x7fb992c04b38] DEBUG - Removed transcode data consumer, active count 7 => 6

These are timeouts because the CPU is not keeping up with basic demands.

13

Alright, I think I have managed to solve the first issue and I also optimized the db and restarted the whole server:

image

I still have the issue though, new logs attached:
Plex Media Server Logs_2023-03-18_09-21-32.zip (794.3 KB)

14

Did you maybe manage to figure anything else from the new logs?
I also have one short question, should Plex actually use HW when transcoding only audio, or is that not a thing?
Thanks!

15

@Horea17

It’s been a busy weekend for me.

I’m not seeing any wild database delays as I did in the previous logs.
Did you optimize the database and restart PMS?

These logs have network configuration issues running rampant – constantly reconfiguring . PMS will not work in an environment which has an unstable network.
It resets everything when the main adapter is involved in a change. You’r primary is the bridge root adapter of all the ‘br-xxx’ adapters

Mar 18, 2023 09:17:23.147 [0x7f9e3f21eb38] DEBUG - NetworkInterface: Notified of network changed (force=0)
Mar 18, 2023 09:17:23.148 [0x7f9e3f21eb38] DEBUG - Network change notification but nothing changed.
Mar 18, 2023 09:17:23.148 [0x7f9e3f21eb38] DEBUG - NetworkInterface: received Netlink message len=1348, type=RTM_NEWLINK, flags=0x0
Mar 18, 2023 09:17:23.148 [0x7f9e3f21eb38] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=32, flags=0x1002, change=0xffffffff
Mar 18, 2023 09:17:23.148 [0x7f9e3f21eb38] DEBUG - Network change.
Mar 18, 2023 09:17:23.149 [0x7f9e3f21eb38] DEBUG - NetworkInterface: Notified of network changed (force=0)
Mar 18, 2023 09:17:23.149 [0x7f9e3f21eb38] DEBUG - Network change notification but nothing changed.
Mar 18, 2023 09:17:23.150 [0x7f9e3f21eb38] DEBUG - NetworkInterface: received Netlink message len=1632, type=RTM_NEWLINK, flags=0x0
Mar 18, 2023 09:17:23.150 [0x7f9e3f21eb38] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=32, flags=0x1002, change=0x0
Mar 18, 2023 09:17:23.150 [0x7f9e3f21eb38] DEBUG - Network change.

Regarding :

If you only need to convert the audio then the transcoder will “DirectStream” the file.

You can look at the FFMPEG line

Mar 18, 2023 09:18:15.044 [0x7f9e40a50b38] DEBUG - [Req#2bd/Transcode/JobRunner] Job running: EAE_ROOT=/tmp/pms-192f05a9-0447-4c84-aa16-5fdc504342ce/EasyAudioEncoder FFMPEG_EXTERNAL_LIBS=‘/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/2584b51-4483-linux-x86_64/’ X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx4192-85e9-7171da168480 “/usr/lib/plexmediaserver/Plex Transcoder” -codec:0 h264 -codec:1 eac3_eae -eae_prefix:1 4fym2uyb8cp25ct2ke02oq8z_ -noaccurate_seek -analyzeduration 20000000 -probesize 20000000 -i “/mnt/cloud/Movies/Puss in Boots The Last Wish (2022)/Puss in Boots The Last Wish (2022) {imdb-tt3915174} [Bluray-1080p][EAC3 7.1][x264]-playHD.mkv” -map 0:0 -metadata:s:0 language=eng -codec:0 copy -filter_complex “[0:1] aresample=async=1:ochl=‘5.1’:rematrix_maxval=0.000000dB:osr=48000[0]” -map “[0]” -metadata:s:1 language=eng -codec:1 aac -b:1 774k -break_non_keyframes 1 -f dash -seg_duration 1 -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/4fym2uyb8cp25ct2ke02oq8z/691eec8e-ff93-429f-a1d0-31c31cd95c43/manifest?X-Plex-Http-Pipeline=infinite” -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 dash -map 0:3 -metadata:s:0 language=eng -codec:0 copy -strict_ts:0 0 -f segment -segment_format srt -segment_time 1 -segment_header_filename sub-header -segment_start_number 0 -segment_list “http://127.0.0.1:32400/video/:/transcode/session/4fym2uyb8cp25ct2ke02oq8z/691eec8e-ff93-429f-a1d0-31c31cd95c43/manifest?stream=subtitles&X-Plex-Http-Pipeline=infinite” -segment_list_type csv -segment_list_size 5 -segment_list_separate_stream_times 1 -segment_list_unfinished 1 -fflags +flush_packets “sub-chunk-%05d” -start_at_zero -copyts -vsync cfr -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/4fym2uyb8cp25ct2ke02oq8z/691eec8e-ff93-429f-a1d0-31c31cd95c43/progress

and see it COPY the video

-map 0:0 -metadata:s:0 language=eng -codec:0 copy

and setup the audio conversion to ‘aac’ (in this case)

-filter_complex “[0:1] aresample=async=1:ochl=‘5.1’:rematrix_maxval=0.000000dB:osr=48000[0]” -map “[0]” -metadata:s:1 language=eng -codec:1 aac -b:1 774k -break_non_keyframes 1

The player then mandates the output be in MP4 streaming format

-f dash -seg_duration 1 -dash_segment_type mp4 -init_seg_name ‘init-stream$RepresentationID$.m4s’

Lastly, it specifies to copy the SRT subtitles.

-map 0:3 -metadata:s:0 language=eng -codec:0 copy -strict_ts:0 0 -f segment -segment_format srt

PMS pushes the input into the /video:/transcode port

Mar 18, 2023 09:18:15.476 [0x7f9e40a50b38] DEBUG - [Req#2bd/Transcode] Started session successfully: 4fym2uyb8cp25ct2ke02oq8z
Mar 18, 2023 09:18:15.476 [0x7f9e4374ab38] DEBUG - Completed: [127.0.0.1:50728] 204 PUT /video/:/transcode/session/4fym2uyb8cp25ct2ke02oq8z/691eec8e-ff93-429f-a1d0-31c31cd95c43/progress?duration=6141.152000 (18 live) #325 0ms 203 bytes (pipelined: 14) (range: bytes=0-)

We see the player come GET the output to play

Mar 18, 2023 09:18:15.476 [0x7f9e4374ab38] DEBUG - Completed: [192.168.0.103:56227] 206 GET /video/:/transcode/universal/start.mpd?Accept=application%2Fjson&Accept-Language=en&directPlay=0&directStream=1&directStreamAudio=0&protocol=dash&fastSeek=1&path=%2Flibrary%2Fmetadata%2F4136&session=4fym2uyb8cp25ct2ke02oq8z&mediaIndex=0&partIndex=0&mediaBufferSize=50000&hasMDE=1&subtitleSize=100&videoQuality=100&videoResolution=3840x2160&audioBoost=100&subtitles=sidecar&location=lan (18 live) #2bd TLS GZIP 446ms 1794 bytes (pipelined: 9) (range: bytes=0-)

16

Sorry for piling on, I know you have a lot on your plate, seen you reply to a lot of topics on this forum. Thank you for your help btw :slight_smile:

Yup, I did.

Do you know what could be causing this? I’m running my server and the player on the same network, both wired. PMS is not running in a docker container or anything, it just runs directly on the server.

17

How many virtual ‘bridged’ adapters (Containers) are you running?
Every time you create a ‘Bridged’ docker container , you get one of these.

If you look at my NAS, you see

  1. Individual ‘enp2s0f0/enp2s0f1’ 10GbE adapters
  2. The main adapter (bond0) from the two physical.
  3. br0 which is the netplan “virtual switch” for all the containers to connect into
  4. The LXC containers which stand as ‘peers’ on the server, each with their own LAN IP address (vethxxxxxxxx)

Something on your machine is creating and attaching a lot of things to br0

[chuck@glockner media.2005]$ ifconfig
bond0: flags=5187<UP,BROADCAST,RUNNING,MASTER,MULTICAST>  mtu 1500
        ether c2:e5:24:d2:0f:8c  txqueuelen 1000  (Ethernet)
        RX packets 2370289473  bytes 1768395022215 (1.7 TB)
        RX errors 0  dropped 83314  overruns 0  frame 0
        TX packets 14324197974  bytes 21227641675064 (21.2 TB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

br0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.0.20  netmask 255.255.255.0  broadcast 192.168.0.255
        inet6 fe80::c0e5:24ff:fed2:f8c  prefixlen 64  scopeid 0x20<link>
        inet6 2601:985:500:360:c0e5:24ff:fed2:f8c  prefixlen 64  scopeid 0x0<global>
        inet6 2601:985:500:360::2000  prefixlen 128  scopeid 0x0<global>
        ether c2:e5:24:d2:0f:8c  txqueuelen 1000  (Ethernet)
        RX packets 1324155939  bytes 383393441246 (383.3 GB)
        RX errors 0  dropped 1342981  overruns 0  frame 0
        TX packets 810764774  bytes 20332606221663 (20.3 TB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

enp2s0f0: flags=6211<UP,BROADCAST,RUNNING,SLAVE,MULTICAST>  mtu 1500
        ether c2:e5:24:d2:0f:8c  txqueuelen 1000  (Ethernet)
        RX packets 162306752  bytes 91958563962 (91.9 GB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 7686799686  bytes 11452515831293 (11.4 TB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

enp2s0f1: flags=6211<UP,BROADCAST,RUNNING,SLAVE,MULTICAST>  mtu 1500
        ether c2:e5:24:d2:0f:8c  txqueuelen 1000  (Ethernet)
        RX packets 2207982721  bytes 1676436458253 (1.6 TB)
        RX errors 0  dropped 83314  overruns 0  frame 0
        TX packets 6637398288  bytes 9775125843771 (9.7 TB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 13698447  bytes 3735116363 (3.7 GB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 13698447  bytes 3735116363 (3.7 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth07e64be4: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        ether be:45:58:8b:fc:83  txqueuelen 1000  (Ethernet)
        RX packets 731937  bytes 61670328 (61.6 MB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 2129509  bytes 5379059678 (5.3 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth3d7dd26c: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        ether 7e:f4:6a:5f:61:94  txqueuelen 1000  (Ethernet)
        RX packets 74029  bytes 11201800 (11.2 MB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 11960854  bytes 3985934051 (3.9 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth4e3e4ea7: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        ether 72:6f:b3:3d:02:77  txqueuelen 1000  (Ethernet)
        RX packets 274848  bytes 27157254 (27.1 MB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 12149903  bytes 4038891943 (4.0 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

vethf4fcf5df: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        ether 3e:b0:07:59:a7:0a  txqueuelen 1000  (Ethernet)
        RX packets 1009861  bytes 515184157 (515.1 MB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 11124313  bytes 3488325512 (3.4 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
18

Thanks for helping me, I think it’s simply an issue of my CPU not being powerful enough and able to handle the transcoding after a while… I’ve tried everything, and still have this issue.

19

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