Plex Media Server process uses 100% cpu (SRT->ASS Conversion)

Well, it’s pretty obvious on my screenshot even with the threads, 2 processes at top using 100% (1 in the parent, 1 is the child) when subtitles are active. Everything else is almost 0 or 1%.

But I can disable the display of the threads if you want and screenshot again, we’ll have the same result :slight_smile:

You see all those “Plex Media Server” threads, one per line?
Folding it down to a single line makes it irrefutable and easy to convey to engineering.

Here you go!

Version: 1.16.3.1402, Plex Web, subtitles set to automatic.
File info:

<Media id="1304" duration="2546736" bitrate="3740" width="1280" height="720" aspectRatio="1.78" audioChannels="6" audioCodec="ac3" videoCodec="h264" videoResolution="720" container="mkv" videoFrameRate="24p" videoProfile="high">
   <Part accessible="1" exists="1" id="1304" key="/library/parts/1304/1476431031/file.mkv" duration="2546736" file="XXXXXX" size="1191324341" container="mkv" deepAnalysisVersion="4" requiredBandwidths="9688,8045,4805,4428,4428,4428,4428,4428" videoProfile="high">
      <Stream id="5504" streamType="1" codec="h264" index="0" bitrate="3356" language="English" languageCode="eng" bitDepth="8" chromaLocation="left" chromaSubsampling="4:2:0" frameRate="23.976" hasScalingMatrix="0" height="720" level="41" profile="high" refFrames="8" requiredBandwidths="9304,7661,4421,4088,4088,4088,4088,4088" scanType="progressive" width="1280" displayTitle="720p (H.264)" />
      <Stream id="5505" streamType="2" selected="1" default="1" codec="ac3" index="1" channels="6" bitrate="384" audioChannelLayout="5.1(side)" requiredBandwidths="384,384,384,384,384,384,384,384" samplingRate="48000" displayTitle="Unknown (AC3 5.1)" />
      <Stream id="20007" key="/library/streams/20007" streamType="3" selected="1" codec="srt" language="English" languageCode="eng" format="srt" displayTitle="English (SRT External)" />
      <Stream id="22367" key="/library/streams/22367" streamType="3" codec="srt" language="Français" languageCode="fre" format="srt" displayTitle="Français (SRT External)" />
   </Part>
</Media>

I’ve filtered only plex stuff without threads in the screenshots and processes are ordered by CPU usage. Top is using the most, bottom the less.

  1. idle load:

  2. playing with subtitles after 2/3 min wait time (SRT → ASS):

  3. After having disabled the subtitles (almost same as idle, no more PMS using 100% of CPU):

Thank you… Confirms what I see. We got it. Now to find out why

OK gang,
with what we have gathered here, I have had a direct chat with the engineer.

What would be nice:

  1. XML of the file which demonstrates the problem reliably when playing to Plex/web.
  2. DEBUG logs only, VERBOSE logging off.
  3. Start Playback.
  4. Skip forward (if subs don’t start for a while) until where it subtitles are visible on the display.
  5. Now let it play for 60 seconds
  6. Stop Playback
  7. Wait 30 seconds.
  8. Download the logs (Settings - Server - Troubleshooting - Download Logs)
  9. Attach the XML and ZIP file here
1 Like

There are private informations in those logs and it’s impossible to redact them, how can I send you those files privately?

I have the requested informations.

Logs should never include sensitive informations such as plex token, email address etc… (as these will automatically be excluded from the logs)

I believe they’ll only include your username, other users’ usernames within your server and the contents you play.

But if you’d like to stay anonymous, try to PM him the logs, or attach them within the post and delete them once he gets them.

Thanks but I can’t PM @ChuckPa. There’s no message button on his account.
The logs contain public IP addresses, including mine and that’s something I don’t want to share publicly.

PM sent.

My PM is not publicly available because I would be inundated with messages and unable to provide support properly in the public forum setting. It previously was open but I had no choice but to disable it.

1 Like

Hi ChuckPA,

I’ve not followed your steps exactly as it is not required to actually show any subtitiles for the issue to happen, it seems to be the opposite of subtitles not beeing present to cause the issue.

It is not required to play x seconds. I can directly stop the playback and the system is at 100% load for one core.

I’ve posted my logs already in my own topic long ago and saw an additional line in the verbose logging when the issue happens

Furthermore the only interesting part in the logs to my knowledge is the following verbose entry:

Jul 29, 2019 13:18:33.426 [0x14761b70e700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...

I would propose that you do a check on your own system with verbose logging to see if you also see the line mentioned before.

Information I could also gather is:
If there are sub-chunk- files in the transcoding session folder, no load is present
If there are none, the load will increase over time.

Nevertheless I’ll attach new logs (only debug for now).

The following test is done with:

<Media id="207901" duration="7903146" bitrate="5383" width="1920" height="804" aspectRatio="2.35" audioChannels="6" audioCodec="dca" videoCodec="hevc" videoResolution="1080" container="mkv" videoFrameRate="24p" audioProfile="dts" videoProfile="main">
<Part accessible="1" exists="1" id="212271" key="/library/parts/212271/1563428084/file.mkv" duration="7903146" file="/media/hdtv/1080p/Shazam (2019)/Shazam (2019) 1080p DTS.mkv" size="5295951746" audioProfile="dts" container="mkv" deepAnalysisVersion="4" indexes="sd" requiredBandwidths="11738,9950,9134,7983,6836,6062,5603,5507" videoProfile="main">
<Stream id="433259" streamType="1" default="1" codec="hevc" index="0" bitrate="3839" bitDepth="8" chromaSubsampling="4:2:0" colorRange="tv" frameRate="23.976" height="804" level="120" profile="main" refFrames="1" requiredBandwidths="10195,8402,7623,6472,5325,4529,4060,3961" width="1920" displayTitle="1080p (HEVC Main)"/>
<Stream id="433260" streamType="2" selected="1" default="1" codec="dca" index="1" channels="6" bitrate="1509" language="Deutsch" languageCode="ger" audioChannelLayout="5.1(side)" bitDepth="16" profile="dts" requiredBandwidths="1509,1509,1509,1509,1509,1509,1509,1509" samplingRate="48000" displayTitle="Deutsch (DTS 5.1)"/>
<Stream id="433261" streamType="3" selected="1" default="1" forced="1" codec="srt" index="2" language="Deutsch" languageCode="ger" requiredBandwidths="1,1,1,1,1,1,1,1" displayTitle="Deutsch Erzwungen (SRT)"/>
<Stream id="433262" streamType="3" codec="pgs" index="3" bitrate="35" language="Deutsch" languageCode="ger" headerCompression="1" requiredBandwidths="43,43,43,43,43,43,43,43" displayTitle="Deutsch (PGS)"/>
</Part>
</Media>

I’ve done these steps:

  1. Start server without logs and enable debug logs
  2. Start playback
  3. Pause playback after 5 seconds
  4. Wait for some seconds (until no normal conversion load is present on the system anymore)
  5. Stop playback
  6. Download logs

Plex Media Server Logs_2019-07-29_13-43-13.zip (755.1 KB)

Please feel free to ask for any additional logs or whatever is required to get all insights into the issue.

Copying from my other thread:

For this issue to happen, the transcoding must be enabled and no subtitles must be in the next chunk of allowed pretranscode timeframe. I have set mine to 120 seconds.
If I start the same movie in a chunk, where subtitles are actually beeing transcoded, no load is seen on the server.

Not 100% sure this is still valid but I’ve seen that you did not enable any limit to your transcoder in the other topic here:

That may in fact cause your transcoder session to include sub-chunk files and the issue to not happen.

@ChuckPa
Please ignore anything above that I’ve mentioned about the sub-chunk- files.
I’ve retried that now with another move that does have full (not forced) srt subtitles and I also see 1 core at 100% load even though there are now sub-chunk- files present.

In any case, the issue happens with or without actual conversion of subs and I can directly pause the file playback and still observe 100% load on 1 core after all buffers are filled and video and audio conversion are finished.

Folks,
I received logs from RomRider (thanks for those).

Not to single Rom out but there is no passthrough for HW transcoding defined, while such a step is trivial.

Without HW transcoding passthrough defined, you’re denying yourselves access to the benefits and are going to place additional burden on the CPU. As soon as anyone tries to play HEVC all heck is going to break loose.

If you’re going to use Plex in a Docker container, please do make full use of Plex and the CPU? :wink:

Add real directory /dev/dri to the list of what gets passed in and internally exist as /dev/dri. Make certain the GID assigned is also a member of the group assigned to the real /dev/dri (typically group render or video)

So you say hw transoding is mandatory? I don’t even have gpu in my system. Or is it misconfigured in his system?

I am not saying HW transcoding is mandatory.

The particular logs I examined have a HW-transcoding capable CPU (-7xxx family). That CPU can perform HEVC HDR decode and encode in hardware. Access to that capability was not enabled in the Docker container.

When HW is not available to assist, in spite of what the profile states, it will fall back to software. HEVC is the most complex codec to date to decode.

I suggest to all: Make certain to pass the host’s /dev/dri directory into the container as /dev/dri

@ChuckPa, It is enabled on my container, and working (and the plex user has the correct access rights).

    devices:
      - "/dev/dri:/dev/dri"

I can do HW transcoding and it is in use, but on the logs I’ve sent you, there’s no HW transcoding required as it’s using direct stream and especially not HEVC since it’s a H264 file.

And I will repeat it again, but with 1.14.1.5488 and exactly the same container it works properly :slight_smile: In both versions, I know that HW transcoding works as Plex reports it as being HW transcoded when required and I don’t have any load on my CPU while transcoding a video (just when subtitles needs to be transcoded from SRT to ASS…)

Just to show you what I’m saying:

root@docker01:/# ps auxf
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root       665  2.7  0.0  19972  3612 pts/0    Ss   19:17   0:00 bash
root       761  0.0  0.0  36128  3152 pts/0    R+   19:17   0:00  \_ ps auxf
root         1  0.9  0.0    196     4 ?        Ss   19:17   0:00 s6-svscan -t0 /var/run/s6/services
root        22  0.0  0.0    196     4 ?        S    19:17   0:00 s6-supervise s6-fdholderd
root       215  0.0  0.0    196     4 ?        S    19:17   0:00 s6-supervise plex
plex       217  0.0  0.0   4504   720 ?        Ss   19:17   0:00  \_ /bin/sh -c LD_LIBRARY_PATH=/usr/lib/plexmediaserver:/usr/lib/plexmediaserver/lib /usr/lib/plexmediaserver/Plex\ Media\ Server
plex       224 13.0  0.2 2748240 90224 ?       Sl   19:17   0:02      \_ /usr/lib/plexmediaserver/Plex Media Server
plex       252 16.0  0.1 1741260 50884 ?       SNl  19:17   0:03          \_ Plex Plug-in [com.plexapp.system] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resources/Plug-ins-2
plex       307  0.1  0.0 438444 14356 ?        Sl   19:17   0:00          \_ /usr/lib/plexmediaserver/Plex Tuner Service /usr/lib/plexmediaserver/Resources/Tuner/Private /usr/lib/plexmediaserver/Resources/Tuner/Shared 1.16.3.1402-22929c8a2 32600 /waitmutex
plex       333  6.5  0.1 943940 33144 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.plexthememusic] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resou
plex       419  8.4  0.1 945132 34224 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.opensubtitles] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resour
plex       464 12.1  0.1 953952 43316 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.thetvdb] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resources/Pl
plex       606 15.7  0.1 951304 40420 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.themoviedb] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resources
plex       613 16.8  0.1 948236 37308 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.plexmusic] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resources/
plex       615 58.4  0.2 1370688 87148 ?       Sl   19:17   0:05          \_ Plex Plug-in [com.plexapp.agents.subzero] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /config/Library/Application Support/P
plex       728 41.0  0.1 955628 44952 ?        Sl   19:17   0:01          \_ Plex Plug-in [com.plexapp.agents.imdb] /usr/lib/plexmediaserver/Resources/Plug-ins-22929c8a2/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.16.3.1402-22929c8a2 /usr/lib/plexmediaserver/Resources/Plug-

root@docker01:/# ls -la /dev/dri
total 0
drwxr-xr-x 2 root root        80 Jul 29 13:20 .
drwxr-xr-x 6 root root       360 Jul 29 13:20 ..
crw-rw---- 1 root video 226,   0 Jul 29 13:20 card0
crw-rw---- 1 root video 226, 128 Jul 29 13:20 renderD128

root@docker01:/# id plex
uid=1036(plex) gid=100(users) groups=100(users),44(video)

This isn’t a point about whether it was used or not. Please do not misunderstand.

This is what PMS is seeing: The hardware, used or not, is not being found. The Plex UID/GID has no access to it.

Jul 28, 2019 13:40:53.484 [0x7fe6bffff700] DEBUG - TPU: hardware transcoding: enabled, but no hardware decode accelerator found
Jul 28, 2019 13:40:53.484 [0x7fe6bffff700] DEBUG - [Universal] Using local file path instead of URL: /data/Series/----season-------/------file-------.mkv
Jul 28, 2019 13:40:53.485 [0x7fe6bffff700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/library/streams/20007?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Jul 28, 2019 13:40:53.485 [0x7fe6ceffd700] DEBUG - Auth: authenticated user 1 as 

So can you explain me why it works with 1.14.1.5488? And you’re wrong, the Plex process has access to it, in both containers.
So my guess is that the transcoder doesn’t manage to use HW to transcode text, that doesn’t make sense. Apparently it does with 1.14.1.5488

The transcoder does Text in the CPU. It always has.
If you didn’t need video transcoding to play. fine.

I was ONLY pointing out that video transcoding HW was / is unavailable.

Text and this problem is not related.

Yes, but in not the logs I’ve sent you, there’s no requirement for transcoding the video since it’s using direct play!

I can force the transcoding of a video and you’ll see that HW transcoding is used in the logs… Here you go (forced the transcoding from 720p to 328p, exact same file as the one I’ve sent you the logs with)

Jul 29, 2019 19:28:27.991 [0x7f99223da700] DEBUG - TPU: hardware transcoding: using hardware decode accelerator vaapi
Jul 29, 2019 19:28:27.991 [0x7f99223da700] DEBUG - [Universal] Using local file path instead of URL: /data/Series/xxxx/xxxxx/xxxxx.mkv
Jul 29, 2019 19:28:27.991 [0x7f99223da700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/library/streams/20007?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Jul 29, 2019 19:28:27.992 [0x7f9931b8a700] DEBUG - Auth: authenticated user 1 as xxxx

Rom,

Going to file: Plex Media Server Logs_2019-07-28_13-43-15.zip
File: Plex Media Server.log

Please refer to:

    535 Jul 28, 2019 13:40:53.482 [0x7fe6bffff700] DEBUG - Audio Stream: 5505, Subtitle Stream: 20007
    536 Jul 28, 2019 13:40:53.483 [0x7fe6bffff700] DEBUG - Found session GUID of xg2u6smpqugyoc4a9as6h8tr in session start.
    537 Jul 28, 2019 13:40:53.483 [0x7fe6bffff700] DEBUG - Cleaning directory for session xg2u6smpqugyoc4a9as6h8tr ()
    538 Jul 28, 2019 13:40:53.484 [0x7fe6bffff700] DEBUG - Starting a transcode session xg2u6smpqugyoc4a9as6h8tr at offset -1.0 (state=3)
    539 Jul 28, 2019 13:40:53.484 [0x7fe6bffff700] DEBUG - TPU: hardware transcoding: enabled, but no hardware decode accelerator found
    540 Jul 28, 2019 13:40:53.484 [0x7fe6bffff700] DEBUG - [Universal] Using local file path instead of URL: /data/Series/----REDACTED----.mkv
    541 Jul 28, 2019 13:40:53.485 [0x7fe6bffff700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/library/streams/20007?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
    542 Jul 28, 2019 13:40:53.485 [0x7fe6ceffd700] DEBUG - Auth: authenticated user 1 as RomRider42

AGAIN, I am pointing out ONLY that it didn’t declare it as found. It may be absolutely nothing. Let’s move on.

It otherwise looks like this log set will give the engineer what he’s looking for.
This, plus what I have recreated for him, will hopefully shed light on how he can recreate it.

I was able to create a finite sequence.

I will pass these two log file sets to him (your set plus my set)