Buffering on transcode

Plex Media Server Desktops & Laptops
1

Server Version#: 1.14
Player Version#: ps4 latest
So I bought latest i3 nuc (plex is in esxi) so I can play anything no issue. PS4 can’t play subtitles without transcode. Now I know without plex pass I don’t have hw transcoding. No issue - yesterday I let plex transcode 4k to 4k - worked without flaw. Today I have 4k stream and it constantly buffers on 1080p. I’m mad because I bought rather powerful device to avoid this. Both devices are connected on gbit lan.
I dunno how to get active transcodes in linux, but “top” show load about 60% max, also dunno how to get how much of the stream is buffered ahead on ps4.

2

On Linux, and with a active Plex Pass,

All you will need to do is

  1. Restart the server after subscribing to a Plex Pass
  2. Settings - Server - Transcoder - Show Advanced
  3. Use Hardware accelerated transcoding when available (checkbox)
  4. Save

If you have allowed the ESXi guest to access the hardware directly, you’ll have it.

“Transcoding 4K -> 4K” is remultiplexing and a very easy task.
“Transcoding 4K -> 1080p” is a profoundly more difficult task and not likely the i3 can do in software

3

Well, I now see that my post is not clear at all what i’m after.
Transcoding that is now buffering worked for me before on this setup no issue. So i’m looking into ways how to see what is going on, because I don’t think that the cpu is fully utilized even in “software” mode.

Also obvious solution would be to not transcode for subtitles on ps4 (netflix does not), but I guess that is unlikely to happen.

4

There are two issues here.

  1. 2160p (4K) -> 1080p (Hardare acceleration -or- enough CPU power)
  2. Subtitles - CPU power only

What is actually needed depends on what your logs show.
In most cases, Player (client) settings determine what PMS will do.

At this point, I am not certain you have a Server problem. From your description and reply, it appears to be a player issue?

If so, this topic has been tagged incorrectly.

5

I don’t think so.
At least until there is a way to prove it.
Until now, contrary to what people write here, i3 NUC was powerful enough to encode subtitles into 1080p and 4k streams no issue. Still on gbit LAN and AFAIK no cable issues.
I’m looking for ways to diagnose where the issue is - on linux. (or ps4)

BTW if you look on cpu benchmark, or similar web site, you can see that it is almost as powerful as last gen i7s.

IE. In my previous windows experience, I could see plex starting 4 transcodes for single file, when ie. rewersing etc. If I then waited for them to die or manually killed processes it would work, otherwise PC would not be powerful to transcode, but that was q6600, long time ago. Maybe same is still still happening and I just don’t know how to verify on linux.

So IMO first things to verify would be:

  1. how many transcodes are running on the system
  2. what is performance of running transcode, ie. in FPS

there is Throttle - Going into sloth mode. in the log, lot of time, but dunno what it really means. I would guess that it completed he transcode ahead that it thought is enough and went “idle” (which makes sense - as smaller load on cpus would reduce noise). But I guess, in this case, for some reason it is “throttling” too soon, but I might be wrong about what that throttling sloth mode means.

Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - MDE: E6 - The Crime Scene: Direct Play is disabled
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - MDE: E6 - The Crime Scene: media must be transcoded in order to use the hls protocol
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - MDE: E6 - The Crime Scene: no direct play video profile exists for http/mkv/h264
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - MDE: E6 - The Crime Scene: no direct play video profile exists for http/mkv/h264/eac3
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - MDE: Brooklyn Nine-Nine - S6 E6 - The Crime Scene: selected media 0 / 713
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - Streaming Resource: Added session 0x7f1e51416c20:x32y6kx847mte1cjmd67qsup
Feb 15, 2019 22:40:47.868 [0x7f1e32bf9700] DEBUG - Streaming Resource: Reached Decision id=326 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=713 part=(id=713 decision=transcode container=mpegts protocol=hls streams=(Video=(id=1735 decision=copy width=1920 height=1080) Audio=(id=1736 decision=copy channels=6 rate=48000))))
Feb 15, 2019 22:40:47.869 [0x7f1e553ff700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Feb 15, 2019 22:40:47.869 [0x7f1e553ff700] DEBUG - Selecting best audio stream for part ID 713 (autoselect: 0 language: en)
Feb 15, 2019 22:40:47.869 [0x7f1e553ff700] DEBUG - Audio Stream: 1736, Subtitle Stream: -1
Feb 15, 2019 22:40:47.869 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:54377] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F326&mediaIndex=0&partIndex=0&protocol=hls&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&directStreamAudio=1&mediaBufferSize=51200&session=tnap4vuvctb05kvy6brpc57k&subtitles=burn&Accept-Language=en (9 live) TLS GZIP 7ms 1531 bytes (pipelined: 9)
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - [Now] User is evlo (ID: 1)
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - [Now] Device is WebMAF ().
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] ERROR - Unable to find client profile for device; platform=WebMAF, platformVersion=01.81, device=PlayStation 4 Pro, model=
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - [Now] Updated play state for /library/metadata/326.
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - HubCache: Expiring '1/home.continue/1/hubs/en/count=8&excludeElements=Actor%2CCollection%2CCountry%2CDirector%2CGenre%2CLabel%2CMood%2CPart%2CProducer%2CRole%2CSimilar%2CWriter%2CPhoto%2CMedia&excludeFields=file%2Csummary%2Ctagline&excludePlaylists=1&includeLibraryPlaylists=1&libraryHubsOnly=1' because of event plex.event.play.session.state.update.
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - HubCache: Expiring '1/home.ondeck/1/hubs/en/count=8&excludeElements=Actor%2CCollection%2CCountry%2CDirector%2CGenre%2CLabel%2CMood%2CPart%2CProducer%2CRole%2CSimilar%2CWriter%2CPhoto%2CMedia&excludeFields=file%2Csummary%2Ctagline&excludePlaylists=1&includeLibraryPlaylists=1&libraryHubsOnly=1' because of event plex.event.play.session.state.update.
Feb 15, 2019 22:40:47.870 [0x7f1e553ff700] DEBUG - HubCache: Expiring '1/home.television.recent/1/hubs/en/count=8&excludeElements=Actor%2CCollection%2CCountry%2CDirector%2CGenre%2CLabel%2CMood%2CPart%2CProducer%2CRole%2CSimilar%2CWriter%2CPhoto%2CMedia&excludeFields=file%2Csummary%2Ctagline&excludePlaylists=1&includeLibraryPlaylists=1&libraryHubsOnly=1' because event plex.event.play.session.state.update referenced an item the hub contained
Feb 15, 2019 22:40:47.871 [0x7f1e553ff700] DEBUG - Statistics: (owfwr2yy54oxftn8ri9sbhx1) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Feb 15, 2019 22:40:47.873 [0x7f1e333fa700] DEBUG - Request: [127.0.0.1:49020 (Loopback)] GET /status/sessions (9 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:47.873 [0x7f1e333fa700] DEBUG - [Now] Adding 1 sessions.
Feb 15, 2019 22:40:47.873 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:52751] 200 GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=playing&hasMDE=1&time=0&duration=1287000 (9 live) TLS GZIP 11ms 543 bytes (pipelined: 6)
Feb 15, 2019 22:40:47.875 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49020] 200 GET /status/sessions (9 live) 2ms 2975 bytes (pipelined: 2)
Feb 15, 2019 22:40:47.878 [0x7f1e32bf9700] DEBUG - Request: [127.0.0.1:49020 (Loopback)] GET /library/metadata/326 (9 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:47.881 [0x7f1e32bf9700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Feb 15, 2019 22:40:47.881 [0x7f1e32bf9700] DEBUG - Selecting best audio stream for part ID 713 (autoselect: 0 language: en)
Feb 15, 2019 22:40:47.881 [0x7f1e32bf9700] DEBUG - Audio Stream: 1736, Subtitle Stream: -1
Feb 15, 2019 22:40:47.882 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49020] 200 GET /library/metadata/326 (9 live) 3ms 3067 bytes (pipelined: 3)
Feb 15, 2019 22:40:47.886 [0x7f1e427ff700] DEBUG - Request: [127.0.0.1:49020 (Loopback)] GET /clients (9 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:47.887 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49020] 200 GET /clients (9 live) 0ms 580 bytes (pipelined: 4)
Feb 15, 2019 22:40:47.894 [0x7f1e553ff700] DEBUG - Request: [127.0.0.1:49020 (Loopback)] GET /library/metadata/326 (9 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:47.897 [0x7f1e553ff700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Feb 15, 2019 22:40:47.897 [0x7f1e553ff700] DEBUG - Selecting best audio stream for part ID 713 (autoselect: 0 language: en)
Feb 15, 2019 22:40:47.897 [0x7f1e553ff700] DEBUG - Audio Stream: 1736, Subtitle Stream: -1
Feb 15, 2019 22:40:47.898 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49020] 200 GET /library/metadata/326 (9 live) 3ms 3067 bytes (pipelined: 5)
Feb 15, 2019 22:40:48.405 [0x7f1e543ff700] DEBUG - handleStreamRead code 335544539: short read
Feb 15, 2019 22:40:48.444 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:48.444 [0x7f1e333fa700] DEBUG - Request: [192.168.0.150:51765 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (8 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:48.445 [0x7f1e333fa700] DEBUG - Beginning read from two-way stream.
Feb 15, 2019 22:40:48.678 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:48.678 [0x7f1e32bf9700] DEBUG - Request: [192.168.0.150:54377 (Subnet)] GET /playQueues/23?repeat=0&own=1&includeChapters=1&includeGeolocation=1 (8 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:48.679 [0x7f1e32bf9700] DEBUG - PlayQueue: total generated: 1, before cursor: 0, after cursor: 0
Feb 15, 2019 22:40:48.679 [0x7f1e32bf9700] DEBUG - PlayQueue: No need to refresh, active window is operational.
Feb 15, 2019 22:40:48.682 [0x7f1e32bf9700] DEBUG - PlayQueue: Client owfwr2yy54oxftn8ri9sbhx1 requested ownership of play queue 23, but already had it.
Feb 15, 2019 22:40:48.683 [0x7f1e32bf9700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Feb 15, 2019 22:40:48.683 [0x7f1e32bf9700] DEBUG - Selecting best audio stream for part ID 713 (autoselect: 0 language: en)
Feb 15, 2019 22:40:48.683 [0x7f1e32bf9700] DEBUG - Audio Stream: 1736, Subtitle Stream: -1
Feb 15, 2019 22:40:48.684 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:54377] 200 GET /playQueues/23?repeat=0&own=1&includeChapters=1&includeGeolocation=1 (8 live) TLS GZIP 6ms 1655 bytes (pipelined: 10)
Feb 15, 2019 22:40:48.747 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:48.747 [0x7f1e427ff700] DEBUG - Request: [192.168.0.150:52849 (Subnet)] GET /video/:/transcode/universal/start.m3u8?hasMDE=1&path=%2Flibrary%2Fmetadata%2F326&mediaIndex=0&partIndex=0&protocol=hls&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&directStreamAudio=1&mediaBufferSize=51200&session=tnap4vuvctb05kvy6brpc57k&subtitles=burn&Accept-Language=en (9 live) TLS Signed-in Token (evlo)
Feb 15, 2019 22:40:48.747 [0x7f1e427ff700] DEBUG - Found session GUID of tnap4vuvctb05kvy6brpc57k in session start.
Feb 15, 2019 22:40:48.747 [0x7f1e427ff700] DEBUG - TranscodeUniversalRequest: using augmented profile PlayStation 4 App
Feb 15, 2019 22:40:48.748 [0x7f1e427ff700] DEBUG - Downloading document http://127.0.0.1:32400/library/metadata/326?checkFiles=1&includeBandwidths=1&offset=-1&X-Plex-Session-Identifier=x32y6kx847mte1cjmd67qsup
Feb 15, 2019 22:40:48.748 [0x7f1e427ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:48.752 [0x7f1e427ff700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Feb 15, 2019 22:40:48.753 [0x7f1e427ff700] DEBUG - Selecting best audio stream for part ID 713 (autoselect: 0 language: en)
Feb 15, 2019 22:40:48.753 [0x7f1e427ff700] DEBUG - Audio Stream: 1736, Subtitle Stream: -1
Feb 15, 2019 22:40:48.753 [0x7f1e427ff700] DEBUG - Found session GUID of tnap4vuvctb05kvy6brpc57k in session start.
Feb 15, 2019 22:40:48.753 [0x7f1e427ff700] DEBUG - Using session GUID tnap4vuvctb05kvy6brpc57k for new transcode session.
Feb 15, 2019 22:40:48.753 [0x7f1e427ff700] DEBUG - Cleaning directory for session tnap4vuvctb05kvy6brpc57k ()
Feb 15, 2019 22:40:48.754 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:52849] 200 GET /video/:/transcode/universal/start.m3u8?hasMDE=1&path=%2Flibrary%2Fmetadata%2F326&mediaIndex=0&partIndex=0&protocol=hls&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&directStreamAudio=1&mediaBufferSize=51200&session=tnap4vuvctb05kvy6brpc57k&subtitles=burn&Accept-Language=en (9 live) TLS 7ms 366 bytes (pipelined: 1)
Feb 15, 2019 22:40:48.807 [0x7f1e553ff700] DEBUG - Request: [192.168.0.150:60888 (Subnet)] GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/index.m3u8 (10 live) TLS Signed-in
Feb 15, 2019 22:40:48.807 [0x7f1e553ff700] DEBUG - Found session GUID of tnap4vuvctb05kvy6brpc57k in session start.
Feb 15, 2019 22:40:48.807 [0x7f1e553ff700] DEBUG - Starting a transcode session tnap4vuvctb05kvy6brpc57k at offset -1.0 (state=3)
Feb 15, 2019 22:40:48.808 [0x7f1e553ff700] DEBUG - [Universal] Using local file path instead of URL: /mnt/usbHddNtfs/shows/Brooklyn.Nine-Nine.S06E06.1080p.WEB.H264-METCON[rarbg]/Brooklyn.Nine-Nine.S06E06.1080p.WEB.H264-METCON.mkv
Feb 15, 2019 22:40:48.809 [0x7f1e553ff700] DEBUG - Job running: EAE_ROOT='/tmp/pms-499d3433-339e-4bc5-96ad-a2c05a78e02f/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/531e313-1328-linux-ubuntu-x86_64/' XDG_CACHE_HOME='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:0' 'h264' '-noaccurate_seek' '-probesize' '10000000' '-i' '/mnt/usbHddNtfs/shows/Brooklyn.Nine-Nine.S06E06.1080p.WEB.H264-METCON[rarbg]/Brooklyn.Nine-Nine.S06E06.1080p.WEB.H264-METCON.mkv' '-map' '0:0' '-metadata:s:0' 'language=eng' '-codec:0' 'copy' '-map' '0:1' '-metadata:s:1' 'language=eng' '-codec:1' 'copy' '-copypriorss:1' '0' '-segment_format' 'mpegts' '-f' 'ssegment' '-individual_header_trailer' '0' '-segment_time' '10' '-segment_start_number' '0' '-segment_copyts' '1' '-segment_time_delta' '0.0625' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/seglist' '-segment_list_type' 'csv' '-segment_list_size' '2147483647' '-segment_list_separate_stream_times' '1' '-max_delay' '5000000' '-avoid_negative_ts' 'disabled' '-map_metadata' '-1' '-map_chapters' '-1' 'media-%05d.ts' '-start_at_zero' '-copyts' '-vsync' 'cfr' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress'
Feb 15, 2019 22:40:48.811 [0x7f1e553ff700] DEBUG - Jobs: Starting child process with pid 16658
Feb 15, 2019 22:40:48.818 [0x7f1e333fa700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=startup (11 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.819 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49028] 204 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=startup (11 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-) 
Feb 15, 2019 22:40:48.819 [0x7f1e427ff700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=opening (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.820 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49028] 204 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=opening (10 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-) 
Feb 15, 2019 22:40:48.820 [0x7f1e32bf9700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=opened (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.821 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49028] 204 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?status=opened (10 live) 0ms 203 bytes (pipelined: 3) (range: bytes=0-) 
Feb 15, 2019 22:40:48.821 [0x7f1e333fa700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/stream?index=0&id=0&codec=h264&type=video (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.821 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49028] 206 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/stream?index=0&id=0&codec=h264&type=video (10 live) 0ms 256 bytes (pipelined: 4) (range: bytes=0-) 
Feb 15, 2019 22:40:48.821 [0x7f1e32bf9700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/stream?index=1&id=0&codec=eac3&type=audio (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.822 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49028] 206 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/stream?index=1&id=0&codec=eac3&type=audio (10 live) 0ms 256 bytes (pipelined: 5) (range: bytes=0-) 
Feb 15, 2019 22:40:48.855 [0x7f1e333fa700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=eng&width=1920&height=1080&interlaced=0&sar=1:1&level=40&frameRate=23.976&disp_default=1 (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.855 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49028] 206 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=eng&width=1920&height=1080&interlaced=0&sar=1:1&level=40&frameRate=23.976&disp_default=1 (10 live) 0ms 256 bytes (pipelined: 6) (range: bytes=0-) 
Feb 15, 2019 22:40:48.855 [0x7f1e427ff700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=1&id=0&codec=eac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.856 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49028] 206 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=1&id=0&codec=eac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (10 live) 0ms 256 bytes (pipelined: 7) (range: bytes=0-) 
Feb 15, 2019 22:40:48.856 [0x7f1e32bf9700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.856 [0x7f1e543ff700] DEBUG - Completed: [127.0.0.1:49028] 206 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (10 live) 0ms 256 bytes (pipelined: 8) (range: bytes=0-) 
Feb 15, 2019 22:40:48.857 [0x7f1e427ff700] DEBUG - Request: [127.0.0.1:49028 (Loopback)] PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?duration=1287.424000 (10 live) Signed-in Token (evlo)
Feb 15, 2019 22:40:48.857 [0x7f1e53bfe700] DEBUG - Completed: [127.0.0.1:49028] 204 PUT /video/:/transcode/session/tnap4vuvctb05kvy6brpc57k/165334e3-57d0-4cde-96ff-4590b8bf7788/progress?duration=1287.424000 (10 live) 0ms 203 bytes (pipelined: 9) (range: bytes=0-) 
Feb 15, 2019 22:40:48.857 [0x7f1e553ff700] DEBUG - Started session successfully: tnap4vuvctb05kvy6brpc57k
Feb 15, 2019 22:40:48.857 [0x7f1e553ff700] DEBUG - HLS: Building an M3U8 for 1288 total seconds with 10 seconds/segment, target duration of 10.
Feb 15, 2019 22:40:48.858 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:60888] 200 GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/index.m3u8 (10 live) TLS 51ms 3923 bytes (pipelined: 1)
Feb 15, 2019 22:40:48.895 [0x7f1e333fa700] DEBUG - Request: [192.168.0.150:65395 (Subnet)] GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00000.ts (11 live) TLS Signed-in
Feb 15, 2019 22:40:48.896 [0x7f1e333fa700] DEBUG - Asked for segment 0 from session.
Feb 15, 2019 22:40:49.028 [0x7f1e53bfe700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:49.028 [0x7f1e32bf9700] DEBUG - Request: [192.168.0.150:52751 (Subnet)] GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=buffering&hasMDE=1&time=0&duration=1287000 (10 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:49.029 [0x7f1e32bf9700] DEBUG - Client [x32y6kx847mte1cjmd67qsup] reporting timeline state buffering, progress of 0/1287000ms for guid=, ratingKey=326 url=, key=/library/metadata/326, containerKey=, metadataId=326, source=
Feb 15, 2019 22:40:49.030 [0x7f1e32bf9700] DEBUG - [Now] User is evlo (ID: 1)
Feb 15, 2019 22:40:49.030 [0x7f1e32bf9700] DEBUG - [Now] Device is WebMAF ().
Feb 15, 2019 22:40:49.030 [0x7f1e32bf9700] DEBUG - [Now] Profile is PlayStation 4 App
Feb 15, 2019 22:40:49.030 [0x7f1e32bf9700] DEBUG - [Now] Updated play state for /library/metadata/326.
Feb 15, 2019 22:40:49.030 [0x7f1e32bf9700] DEBUG - Statistics: (owfwr2yy54oxftn8ri9sbhx1) Reporting active playback in state 2 of type 4 (scrobble: 0) for account 1
Feb 15, 2019 22:40:49.032 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:52751] 200 GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=buffering&hasMDE=1&time=0&duration=1287000 (10 live) TLS GZIP 4ms 737 bytes (pipelined: 7)
Feb 15, 2019 22:40:49.319 [0x7f1e553ff700] DEBUG - Transcoder segment range: 0 - 0
Feb 15, 2019 22:40:49.396 [0x7f1e333fa700] DEBUG - Returning segment 0 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00000.ts"
Feb 15, 2019 22:40:49.397 [0x7f1e333fa700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00000.ts is 10299392.
Feb 15, 2019 22:40:49.438 [0x7f1e32bf9700] DEBUG - Transcoder segment range: 0 - 1
Feb 15, 2019 22:40:49.569 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:65395] 200 GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00000.ts (11 live) TLS 673ms 10299392 bytes (pipelined: 1)
Feb 15, 2019 22:40:49.606 [0x7f1e553ff700] DEBUG - Transcoder segment range: 0 - 2
Feb 15, 2019 22:40:49.612 [0x7f1e427ff700] DEBUG - Request: [192.168.0.150:64320 (Subnet)] GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00001.ts (13 live) TLS Signed-in
Feb 15, 2019 22:40:49.612 [0x7f1e427ff700] DEBUG - Asked for segment 1 from session.
Feb 15, 2019 22:40:49.612 [0x7f1e427ff700] DEBUG - Returning segment 1 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00001.ts"
Feb 15, 2019 22:40:49.612 [0x7f1e427ff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00001.ts is 14625084.
Feb 15, 2019 22:40:49.771 [0x7f1e32bf9700] DEBUG - Transcoder segment range: 0 - 3
Feb 15, 2019 22:40:49.859 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:64320] 200 GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00001.ts (13 live) TLS 246ms 14625084 bytes (pipelined: 1)
Feb 15, 2019 22:40:49.895 [0x7f1e333fa700] DEBUG - Transcoder segment range: 0 - 4
Feb 15, 2019 22:40:49.901 [0x7f1e427ff700] DEBUG - Request: [192.168.0.150:54968 (Subnet)] GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00002.ts (12 live) TLS Signed-in
Feb 15, 2019 22:40:49.902 [0x7f1e427ff700] DEBUG - Asked for segment 2 from session.
Feb 15, 2019 22:40:49.902 [0x7f1e427ff700] DEBUG - Returning segment 2 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00002.ts"
Feb 15, 2019 22:40:49.902 [0x7f1e427ff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00002.ts is 14126320.
Feb 15, 2019 22:40:50.053 [0x7f1e32bf9700] DEBUG - Transcoder segment range: 0 - 5
Feb 15, 2019 22:40:50.135 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:50.135 [0x7f1e553ff700] DEBUG - Request: [192.168.0.150:54377 (Subnet)] GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=buffering&hasMDE=1&time=0&duration=1288000 (13 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:50.138 [0x7f1e553ff700] DEBUG - Client [x32y6kx847mte1cjmd67qsup] reporting timeline state buffering, progress of 0/1288000ms for guid=, ratingKey=326 url=, key=/library/metadata/326, containerKey=, metadataId=326, source=
Feb 15, 2019 22:40:50.138 [0x7f1e553ff700] DEBUG - [Now] User is evlo (ID: 1)
Feb 15, 2019 22:40:50.138 [0x7f1e553ff700] DEBUG - [Now] Device is WebMAF ().
Feb 15, 2019 22:40:50.138 [0x7f1e553ff700] DEBUG - [Now] Profile is PlayStation 4 App
Feb 15, 2019 22:40:50.138 [0x7f1e553ff700] DEBUG - [Now] Updated play state for /library/metadata/326.
Feb 15, 2019 22:40:50.139 [0x7f1e553ff700] DEBUG - Statistics: (owfwr2yy54oxftn8ri9sbhx1) Reporting active playback in state 2 of type 4 (scrobble: 0) for account 1
Feb 15, 2019 22:40:50.139 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:54968] 200 GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00002.ts (12 live) TLS 238ms 14126320 bytes (pipelined: 1)
Feb 15, 2019 22:40:50.141 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:54377] 200 GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=buffering&hasMDE=1&time=0&duration=1288000 (12 live) TLS GZIP 5ms 823 bytes (pipelined: 11)
Feb 15, 2019 22:40:50.182 [0x7f1e333fa700] DEBUG - Request: [192.168.0.150:61396 (Subnet)] GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00003.ts (13 live) TLS Signed-in
Feb 15, 2019 22:40:50.182 [0x7f1e333fa700] DEBUG - Asked for segment 3 from session.
Feb 15, 2019 22:40:50.182 [0x7f1e333fa700] DEBUG - Returning segment 3 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00003.ts"
Feb 15, 2019 22:40:50.182 [0x7f1e333fa700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-tnap4vuvctb05kvy6brpc57k-165334e3-57d0-4cde-96ff-4590b8bf7788/media-00003.ts is 14459644.
Feb 15, 2019 22:40:50.212 [0x7f1e427ff700] DEBUG - Transcoder segment range: 0 - 6
Feb 15, 2019 22:40:50.282 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:50.283 [0x7f1e32bf9700] DEBUG - Request: [192.168.0.150:52751 (Subnet)] GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=playing&hasMDE=1&time=0&duration=1288000 (12 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:50.285 [0x7f1e32bf9700] DEBUG - Client [x32y6kx847mte1cjmd67qsup] reporting timeline state playing, progress of 0/1288000ms for guid=, ratingKey=326 url=, key=/library/metadata/326, containerKey=, metadataId=326, source=
Feb 15, 2019 22:40:50.286 [0x7f1e32bf9700] DEBUG - [Now] User is evlo (ID: 1)
Feb 15, 2019 22:40:50.286 [0x7f1e32bf9700] DEBUG - [Now] Device is WebMAF ().
Feb 15, 2019 22:40:50.286 [0x7f1e32bf9700] DEBUG - [Now] Profile is PlayStation 4 App
Feb 15, 2019 22:40:50.286 [0x7f1e32bf9700] DEBUG - [Now] Updated play state for /library/metadata/326.
Feb 15, 2019 22:40:50.286 [0x7f1e32bf9700] DEBUG - Statistics: (owfwr2yy54oxftn8ri9sbhx1) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Feb 15, 2019 22:40:50.291 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:52751] 200 GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=0&playQueueItemID=22&state=playing&hasMDE=1&time=0&duration=1288000 (12 live) TLS GZIP 7ms 823 bytes (pipelined: 8)
Feb 15, 2019 22:40:50.337 [0x7f1e333fa700] DEBUG - Transcoder segment range: 0 - 7
Feb 15, 2019 22:40:50.425 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:61396] 200 GET /video/:/transcode/universal/session/tnap4vuvctb05kvy6brpc57k/base/00003.ts (12 live) TLS 243ms 14459644 bytes (pipelined: 1)
Feb 15, 2019 22:40:50.437 [0x7f1e427ff700] DEBUG - Transcoder segment range: 0 - 8
Feb 15, 2019 22:40:50.537 [0x7f1e32bf9700] DEBUG - Transcoder segment range: 0 - 9
Feb 15, 2019 22:40:50.652 [0x7f1e553ff700] DEBUG - Transcoder segment range: 0 - 10
Feb 15, 2019 22:40:50.770 [0x7f1e333fa700] DEBUG - Transcoder segment range: 0 - 11
Feb 15, 2019 22:40:50.861 [0x7f1e427ff700] DEBUG - Session tnap4vuvctb05kvy6brpc57k (3) is throttling
Feb 15, 2019 22:40:50.862 [0x7f1e553ff700] DEBUG - [Transcoder] Throttle - Going into sloth mode.
Feb 15, 2019 22:40:58.821 [0x7f1e3d3fe700] DEBUG - Statistics: Flushing 31 expired bandwidth entries, 0 expired media entries.
Feb 15, 2019 22:40:59.757 [0x7f1e543ff700] DEBUG - Auth: authenticated user 1 as evlo
Feb 15, 2019 22:40:59.757 [0x7f1e553ff700] DEBUG - Request: [192.168.0.150:54377 (Subnet)] GET /:/timeline?ratingKey=326&key=%2Flibrary%2Fmetadata%2F326&playbackTime=9145&playQueueItemID=22&state=playing&hasMDE=1&time=9000&duration=1288000 (9 live) TLS GZIP Signed-in Token (evlo)
Feb 15, 2019 22:40:59.758 [0x7f1e553ff700] DEBUG - Client [x32y6kx847mte1cjmd67qsup] reporting timeline state playing, progress of 9000/1288000ms for guid=, ratingKey=326 url=, key=/library/metadata/326, containerKey=, metadataId=326, source=
6

Sloth mode = The transcoder has processed the required buffer full (120 seconds default) and is now waiting for the player to consume (play) it. When the player has consumed the data from the buffer (received it), the transcoder will go back to work and fill the buffer up. It repeats this until playback completed or terminated.

I have both an i3 nuc gen 7 and an i7-7700. No way does the i3 keep up with the i7 for CPU power (otherwise they’d be the same CPU model number, right? )

Plex starts one transcode per playback session. Windows isn’t Linux either. It’s entirely different how everything is handled. Here we have the Plex Media Server process (for all) and one Plex Transcoder process (if needed) for each playback session.

7

So how can I verify if cpu is overloaded during transcoding? It seems to go idle, but I still get buffering.

In 4k to 4k with subtitles it worked. Most of 1080p to 1080p works when adding subtitles, some 1080p to 1080p I get buffering, even when not adding subtitles. CPU should be more then capable enough to transcode 1080p. Usually 1080p, when there is issue works until i first seek back or i dunno for 10 minuts and then buffering starts. Maybe cpu throttle? But how do I find out on linux?

It seems to be using internet or something while it should only use lan to get transcoded stream.

I’m still not considered where there are issues on ps4pro side with some 1080p or 4k files and with all subtitles as I bought NUC to be able to transcode for ps4 and just have one player and that is it, but having these issues is not what I expected.

Feb 25, 2019 19:45:35.314 [0x7f1e2d3ee700] DEBUG - Statistics: (owfwr2yy54oxftn8ri9sbhx1) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Feb 25, 2019 19:45:35.321 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:62740] 200 GET /:/timeline?ratingKey=380&key=%2Flibrary%2Fmetadata%2F380&playbackTime=147933&playQueueItemID=40&state=playing&hasMDE=1&time=1545000&duration=3700000 (10 live) TLS GZIP 28ms 830 bytes (pipelined: 1)
Feb 25, 2019 19:45:35.612 [0x7f1e2abe9700] DEBUG - Transcoder segment range: 1400 - 1548
Feb 25, 2019 19:45:35.656 [0x7f1e4bffd700] DEBUG - Returning segment 1548 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01548.ts"
Feb 25, 2019 19:45:35.657 [0x7f1e4bffd700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01548.ts is 1353036.
Feb 25, 2019 19:45:35.677 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:62777] 200 GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01548.ts (11 live) TLS 722ms 1353036 bytes (pipelined: 1)
Feb 25, 2019 19:45:35.722 [0x7f1e427ff700] DEBUG - Request: [192.168.0.150:50194 (Subnet)] GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01549.ts (11 live) TLS Signed-in
Feb 25, 2019 19:45:35.722 [0x7f1e427ff700] DEBUG - Asked for segment 1549 from session.
Feb 25, 2019 19:45:36.425 [0x7f1e2d3ee700] DEBUG - Transcoder segment range: 1400 - 1549
Feb 25, 2019 19:45:36.524 [0x7f1e427ff700] DEBUG - Returning segment 1549 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01549.ts"
Feb 25, 2019 19:45:36.524 [0x7f1e427ff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01549.ts is 1297576.
Feb 25, 2019 19:45:36.542 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:50194] 200 GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01549.ts (11 live) TLS 820ms 1297576 bytes (pipelined: 1)
Feb 25, 2019 19:45:36.585 [0x7f1e4bffd700] DEBUG - Request: [192.168.0.150:59001 (Subnet)] GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01550.ts (12 live) TLS Signed-in
Feb 25, 2019 19:45:36.586 [0x7f1e4bffd700] DEBUG - Asked for segment 1550 from session.
Feb 25, 2019 19:45:37.218 [0x7f1e427ff700] DEBUG - Transcoder segment range: 1400 - 1550
Feb 25, 2019 19:45:37.286 [0x7f1e4bffd700] DEBUG - Returning segment 1550 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01550.ts"
Feb 25, 2019 19:45:37.287 [0x7f1e4bffd700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01550.ts is 1279716.
Feb 25, 2019 19:45:37.311 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:59001] 200 GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01550.ts (11 live) TLS 726ms 1279716 bytes (pipelined: 1)
Feb 25, 2019 19:45:37.365 [0x7f1e2d3ee700] DEBUG - Request: [192.168.0.150:62409 (Subnet)] GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01551.ts (11 live) TLS Signed-in
Feb 25, 2019 19:45:37.366 [0x7f1e2d3ee700] DEBUG - Asked for segment 1551 from session.
Feb 25, 2019 19:45:38.056 [0x7f1e2abe9700] DEBUG - Transcoder segment range: 1400 - 1551
Feb 25, 2019 19:45:38.073 [0x7f1e2d3ee700] DEBUG - Returning segment 1551 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01551.ts"
Feb 25, 2019 19:45:38.073 [0x7f1e2d3ee700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01551.ts is 1241176.
Feb 25, 2019 19:45:38.091 [0x7f1e53bfe700] DEBUG - Completed: [192.168.0.150:62409] 200 GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01551.ts (11 live) TLS 726ms 1241176 bytes (pipelined: 1)
Feb 25, 2019 19:45:38.141 [0x7f1e427ff700] DEBUG - Request: [192.168.0.150:58951 (Subnet)] GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01552.ts (12 live) TLS Signed-in
Feb 25, 2019 19:45:38.142 [0x7f1e427ff700] DEBUG - Asked for segment 1552 from session.
Feb 25, 2019 19:45:38.893 [0x7f1e4bffd700] DEBUG - Transcoder segment range: 1400 - 1552
Feb 25, 2019 19:45:38.952 [0x7f1e427ff700] DEBUG - Returning segment 1552 from session: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01552.ts"
Feb 25, 2019 19:45:38.952 [0x7f1e427ff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-pmo0kvudlajtc773pr1b2q3q-0365d95f-23aa-4f54-a4fe-3364e1f89c71/media-01552.ts is 1396464.
Feb 25, 2019 19:45:38.975 [0x7f1e543ff700] DEBUG - Completed: [192.168.0.150:58951] 200 GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01552.ts (11 live) TLS 834ms 1396464 bytes (pipelined: 1)
Feb 25, 2019 19:45:39.022 [0x7f1e2abe9700] DEBUG - Request: [192.168.0.150:49285 (Subnet)] GET /video/:/transcode/universal/session/pmo0kvudlajtc773pr1b2q3q/base/01553.ts (12 live) TLS Signed-in
Feb 25, 2019 19:45:39.023 [0x7f1e2abe9700] DEBUG - Asked for segment 1553 from session.

vk9fxON.png1025×419 25.6 KB

this is log from the time of buffering hell
but seems a bit weird that it is not able to transoce 1080p to 1080p with subtitles, but 4k to 4k with subtitles is ok, while there is no traffic on the network.

I will try to continue the episode after there is no downloading going on.

If I understand top output correctly CPU load is <60% percent. Network does not seem to be the cause, so at least there is that.

Update: I will try the verbose logging thing, thought since cpu is not used 100% i don’t think i7 would help as it does have same single thread performance.

So now no traffic on network, and so far:

Feb 25, 2019 20:52:49.613 [0x7f1e2d3ee700] VERBOSE -  * speed => 1.9

I would expect more then 1.9 this is 1080p to 1080p no subtitles, but no buffering so far

Now buffering starterd

[0x7f1e4fbff700] DEBUG - Request: [127.0.0.1:56692 (Loopback)] PUT /video/:/transcode/session/8dbk6074f7m1hekz2mzj8uhk/44e9288a-ab31-41d1-b2ee-1bca4d097709/progress?progress=67.5&size=-22&remaining=-1&vdec_packets=10409&vdec_sw_ok=8597&speed=0.0&vdec_hw_status=0 (15 live) Signed-in Token (evlo)
Feb 25, 2019 20:56:57.895 [0x7f1e4fbff700] VERBOSE -  * User-Agent => Lavf/58.9.100
Feb 25, 2019 20:56:57.896 [0x7f1e4fbff700] VERBOSE -  * Accept => */*
Feb 25, 2019 20:56:57.896 [0x7f1e4fbff700] VERBOSE -  * Range => bytes=0-
Feb 25, 2019 20:56:57.897 [0x7f1e4fbff700] VERBOSE -  * Connection => keep-alive
Feb 25, 2019 20:56:57.897 [0x7f1e4fbff700] VERBOSE -  * Host => 127.0.0.1:32400
Feb 25, 2019 20:56:57.898 [0x7f1e4fbff700] VERBOSE -  * Icy-MetaData => 1
Feb 25, 2019 20:56:57.898 [0x7f1e4fbff700] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx
Feb 25, 2019 20:56:57.898 [0x7f1e4fbff700] VERBOSE -  * progress => 67.5
Feb 25, 2019 20:56:57.903 [0x7f1e4fbff700] VERBOSE -  * size => -22
Feb 25, 2019 20:56:57.905 [0x7f1e4fbff700] VERBOSE -  * remaining => -1
Feb 25, 2019 20:56:57.913 [0x7f1e4fbff700] VERBOSE -  * vdec_packets => 10409
Feb 25, 2019 20:56:57.914 [0x7f1e4fbff700] VERBOSE -  * vdec_sw_ok => 8597
Feb 25, 2019 20:56:57.914 [0x7f1e4fbff700] VERBOSE -  * speed => 0.0

kinda weird right 0.0 - this is multiple times in succession.

Longer log with all the 0.0 and simillar speed here https://drive.google.com/file/d/1kpmo45XgtDiX8cbXkdvFlCRbdEMJ08cM/view?usp=sharing

So I started to think that maybe it is issue with usb hdd that I use for media storrage

XnEinrr.png1502×337 17.8 KB

but I dunno how to read the stats, i think sdb is the usb one

8

So just for fun I restated the VM and today, once speed 0.9, but most times speed is >2 - which I still think is rather low, but not a single buffering.

9

So I still get buffering on second episode today. and speed still goes down to 0.0.
Found few threads here with the same issue and no sollution.

Seems to me that i3 NUC is really powerful enough.

I will try resize partition of VM, which I don’t think will help.
I will also try windows VM with plex, which I think might help, or at least I can diagnose issues in windows a little.

10

I think I have found the issue

11

That would cause a problem indeed.

12

So inserting subtitles to 4k 8bit is no problem, but 10bit 4k seems too be to much for the cpu under esxi.

But 10bit to 8bit conversion introduces weird contrast/brightness/gamma bug to picture anyway - I would guess there would be dithering instead but, well, meh, not too much content that is in 10bit only. I think it was popular 10 years back in anime releases and nothing much else.

In the hindsight this NUC is not very great for ESXi and using windows + hyperV or just windows would be wiser option.
Also very hard to configure to turn the fan only when needed. BIOS settings do no result in results one would expect from the setting’s description. Again - this is most likely due to the fact that this machine is primarily intended for windows and these days I think fan management is part of windows power management.

Also for anyone interested in current i3 NUC build 4k to 1080p transcoding in CPU only mode is perfectly fight (too lazy too look speed in the log, maybe later) and I still don’t see any better option for server in any available SBC I know of (from my experience at least MMC instad of SD is a must!)

13

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