Transcoder is killed as idle when playing

General Discussions
1

I’m having an issue when transcoding (either audio, video or both) the transcoder appears to stop after ~30 seconds and the video being played will stop buffering, then stops when it reaches that point. Restarting the video will restart the transcoder but again stops after ~30 seconds.

After some digging through the logs it appears that PMS is reporting the session as idle and killing the transcoder. If videos are direct play/stream it works flawlessly. I have recently optimized the database and cleaned bundles, but the issue still exists.

Has anybody had a similar issue, or have any tips?

Nov 28, 2018 10:43:36.468 [0x7fad16bfe700] DEBUG - Completed: [192.168.1.3:18950] 200 GET /video/:/transcode/universal/dash/d2oqr3u71oh63m4fj8559w8i/1/5.m4s (13 live) TLS GZIP 302ms 31149 bytes (pipelined: 59)
Nov 28, 2018 10:43:36.472 [0x7fad183ff700] DEBUG - Request: [192.168.1.3:18950 (Subnet)] GET /video/:/transcode/universal/dash/d2oqr3u71oh63m4fj8559w8i/1/6.m4s (12 live) TLS GZIP Signed-in
Nov 28, 2018 10:43:36.472 [0x7fad183ff700] DEBUG - Asked for segment 6 from session.
Nov 28, 2018 11:44:11.891 [0x7fad0affe700] DEBUG - Shutting down idle session d2oqr3u71oh63m4fj8559w8i (idle time is 180 seconds)
Nov 28, 2018 11:44:11.891 [0x7fad0affe700] DEBUG - Killing job.
Nov 28, 2018 11:44:11.891 [0x7fad0affe700] DEBUG - Signalling job ID 32514 with 9
Nov 28, 2018 11:44:11.891 [0x7fad0affe700] DEBUG - Job was already killed, not killing again.
Nov 28, 2018 11:44:11.891 [0x7fad0affe700] DEBUG - Stopping transcode session d2oqr3u71oh63m4fj8559w8i
Nov 28, 2018 11:44:11.892 [0x7fad0affe700] DEBUG - Transcoder: Cleaning old transcode directories.
Nov 28, 2018 11:44:11.893 [0x7fad0affe700] DEBUG - Transcoder: Cleaning old transcode directory: "/tmp/Transcode/Sessions/plex-transcode-d2oqr3u71oh63m4fj8559w8i-9bf46566-0ce1-4db9-b1ea-4cee2e11a317"
Nov 28, 2018 11:44:11.895 [0x7fad0affe700] DEBUG - Whacked session d2oqr3u71oh63m4fj8559w8i, 0 remaining.
Nov 28, 2018 11:44:11.895 [0x7fad0affe700] DEBUG - Killed 1 idle sessions out of a total of 1.
Nov 28, 2018 10:43:36.600 [0x7fad0dbff700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 32514 is -9 (signal: Killed)
Nov 28, 2018 10:43:36.600 [0x7fad113ff700] WARN - Transcode runner appears to have died.
Nov 28, 2018 10:43:36.600 [0x7fad113ff700] DEBUG - Session was stopped.
Nov 28, 2018 10:43:36.601 [0x7fad173ff700] DEBUG - Completed: [192.168.1.3:19009] 404 GET /video/:/transcode/universal/dash/d2oqr3u71oh63m4fj8559w8i/0/6.m4s (10 live) TLS GZIP 206ms 452 bytes (pipelined: 7)
Nov 28, 2018 10:43:36.673 [0x7fad183ff700] WARN - Transcode runner appears to have died.
Nov 28, 2018 10:43:36.673 [0x7fad183ff700] DEBUG - Session was stopped.

Full Logs:
Plex Media Server Logs_2018-11-27_20-07-38.zip (3.4 MB)

2

This is happening on the latest version of PMS (1.14.0.5470) but was also still an issue prior to updating. It also doesn’t matter if its local or remote, direct is still fine and transcoder gets killed.

Any help will be hugely appreciated

3

The attached log does not contain the same time period shown above

Last lines in the logs shown are:

Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - Client [b77gzwvhgkjmed223hwr8uxr] reporting timeline state paused, progress of 41/8089088ms for guid=, ratingKey=29430 url=, key=/library/metadata/29430, containerKey=, metadataId=29430, source=
Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - [Now] User is tracy.butler7@gmail.com (ID: 18405685)
Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - [Now] Device is Konvergo (PlexMediaPlayer).
Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - [Now] Profile is Konvergo
Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - [Now] Updated play state for /library/metadata/29430.
Nov 27, 2018 20:07:32.999 [0x7fe7967fa700] DEBUG - Statistics: (jv3lz0o5lr2wpy9c7i8u84cx) Reporting active playback in state 1 of type 1 (scrobble: 0) for account 18405685
Nov 27, 2018 20:07:33.001 [0x7fe7aa7fe700] DEBUG - Completed: [192.168.1.143:38192] 200 GET /:/timeline?hasMDE=1&ratingKey=29430&key=%2Flibrary%2Fmetadata%2F29430&state=paused&playQueueItemID=38889&time=41&duration=8089088 (13 live) TLS GZIP 3ms 450 bytes (pipelined: 231)
Nov 27, 2018 20:07:33.006 [0x7fe7aafff700] DEBUG - Auth: authenticated user 1 as a123oclock
Nov 27, 2018 20:07:33.006 [0x7fe7977fc700] DEBUG - Request: [192.168.1.3:12847 (Subnet)] GET /status/sessions (13 live) TLS GZIP Signed-in Token (a123oclock)
Nov 27, 2018 20:07:33.006 [0x7fe7977fc700] DEBUG - [Now] Adding 2 sessions.
Nov 27, 2018 20:07:33.008 [0x7fe7aafff700] DEBUG - Completed: [192.168.1.3:12847] 200 GET /status/sessions (13 live) TLS GZIP 2ms 1913 bytes (pipelined: 17)
Nov 27, 2018 20:07:35.048 [0x7fe7a73ff700] DEBUG - [CompanionProxy] player c1b5yyafhymwktp0gh4z5km6 was last refreshed 30 seconds ago
Nov 27, 2018 20:07:36.620 [0x7fe7aa7fe700] DEBUG - WebSocket: client initiated close
Nov 27, 2018 20:07:36.621 [0x7fe7aafff700] DEBUG - NotificationStream: Removing because of close
Nov 27, 2018 20:07:36.627 [0x7fe7aa7fe700] DEBUG - Auth: authenticated user 1 as a123oclock
Nov 27, 2018 20:07:36.627 [0x7fe7967fa700] DEBUG - Request: [192.168.1.3:12859 (Subnet)] GET /diagnostics/logs (13 live) TLS GZIP Signed-in Token (a123oclock)
Nov 27, 2018 20:07:36.628 [0x7fe7967fa700] DEBUG - Diagnostics: Building logfile zip
4

Apologies, I attached the wrong zip!

Plex Media Server Logs_2018-11-28_15-12-08.zip (4.6 MB)

5

THank you.

The Android player is not reporting that it’s actually playing.

Nov 28, 2018 14:46:31.890 [0x7fad173ff700] DEBUG - Completed: [127.0.0.1:50870] 206 PUT /video/:/transcode/session/753be18314d4987c-com-plexapp-android/85b58792-b781-4a1d-ad4c-a516679d2924/progress/streamDetail?index=1&id=0&codec=ac3&type=audio&bitrate=384000&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (12 live) 0ms 256 bytes (pipelined: 7) (range: bytes=0-) 
Nov 28, 2018 14:46:31.892 [0x7fad123ff700] DEBUG - Request: [127.0.0.1:50870 (Loopback)] PUT /video/:/transcode/session/753be18314d4987c-com-plexapp-android/85b58792-b781-4a1d-ad4c-a516679d2924/progress?duration=3648.192000 (12 live) Signed-in Token (a123oclock)
Nov 28, 2018 14:46:31.892 [0x7fad057ff700] DEBUG - Started session successfully: 753be18314d4987c-com-plexapp-android
Nov 28, 2018 14:46:31.892 [0x7fad16bfe700] DEBUG - Completed: [127.0.0.1:50870] 204 PUT /video/:/transcode/session/753be18314d4987c-com-plexapp-android/85b58792-b781-4a1d-ad4c-a516679d2924/progress?duration=3648.192000 (12 live) 0ms 203 bytes (pipelined: 8) (range: bytes=0-) 
Nov 28, 2018 14:46:31.892 [0x7fad057ff700] DEBUG - HLS: Building an M3U8 for 3649 total seconds with 8 seconds/segment, target duration of 8.
Nov 28, 2018 14:46:31.893 [0x7fad16bfe700] DEBUG - Completed: [82.26.91.119:45965] 200 GET /video/:/transcode/universal/session/753be18314d4987c-com-plexapp-android/base/index.m3u8 (12 live) TLS 82ms 12651 bytes (pipelined: 1)
Nov 28, 2018 14:46:32.275 [0x7fad123ff700] DEBUG - Request: [82.26.91.119:45966 (WAN)] GET /video/:/transcode/universal/session/753be18314d4987c-com-plexapp-android/base/00000.ts (13 live) TLS Signed-in
Nov 28, 2018 14:46:32.275 [0x7fad123ff700] DEBUG - Asked for segment 0 from session.
Nov 28, 2018 14:46:32.396 [0x7fad057ff700] DEBUG - Transcoder: session 753be18314d4987c-com-plexapp-android indicated fallback to software decoding
Nov 28, 2018 14:46:32.666 [0x7facfffff700] DEBUG - Transcoder segment range: 0 - 0
Nov 28, 2018 14:46:32.676 [0x7fad123ff700] DEBUG - Returning segment 0 from session: "/tmp/Transcode/Sessions/plex-transcode-753be18314d4987c-com-plexapp-android-85b58792-b781-4a1d-ad4c-a516679d2924/media-00000.ts"
Nov 28, 2018 14:46:32.677 [0x7fad123ff700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-753be18314d4987c-com-plexapp-android-85b58792-b781-4a1d-ad4c-a516679d2924/media-00000.ts is 977224.
Nov 28, 2018 14:46:33.193 [0x7fad173ff700] DEBUG - Completed: [82.26.91.119:45966] 200 GET /video/:/transcode/universal/session/753be18314d4987c-com-plexapp-android/base/00000.ts (14 live) TLS 917ms 977224 bytes (pipelined: 1)
Nov 28, 2018 14:46:33.234 [0x7facfffff700] DEBUG - Request: [82.26.91.119:45967 (WAN)] GET /video/:/transcode/universal/session/753be18314d4987c-com-plexapp-android/base/00001.ts (14 live) TLS Signed-in
Nov 28, 2018 14:46:33.234 [0x7facfffff700] DEBUG - Asked for segment 1 from session.
Nov 28, 2018 14:46:33.311 [0x7fad057ff700] DEBUG - Transcoder segment range: 0 - 1
Nov 28, 2018 14:46:33.335 [0x7facfffff700] DEBUG - Returning segment 1 from session: "/tmp/Transcode/Sessions/plex-transcode-753be18314d4987c-com-plexapp-android-85b58792-b781-4a1d-ad4c-a516679d2924/media-00001.ts"
Nov 28, 2018 14:46:33.335 [0x7facfffff700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-753be18314d4987c-com-plexapp-android-85b58792-b781-4a1d-ad4c-a516679d2924/media-00001.ts is 481468.
Nov 28, 2018 14:46:33.434 [0x7fad173ff700] DEBUG - Completed: [82.26.91.119:45967] 200 GET /video/:/transcode/universal/session/753be18314d4987c-com-plexapp-android/base/00001.ts (14 live) TLS 200ms 481468 bytes (pipelined: 1)
Nov 28, 2018 14:46:33.904 [0x7fad173ff700] DEBUG - Auth: authenticated user 1 as a123oclock
Nov 28, 2018 14:46:33.904 [0x7facfffff700] DEBUG - Request: [192.168.1.77:39938 (Subnet)] GET /library/recentlyAdded (15 live) TLS Page 0-49 Signed-in Token (a123oclock)
Nov 28, 2018 14:46:33.907 [0x7fad16bfe700] DEBUG - Auth: authenticated user 1 as a123oclock
Nov 28, 2018 14:46:33.907 [0x7fad057ff700] DEBUG - Request: [192.168.1.77:39936 (Subnet)] GET /status/sessions (15 live) TLS Signed-in Token (a123oclock)
Nov 28, 2018 14:46:33.907 [0x7fad057ff700] DEBUG - [Now] Adding 0 sessions.
Nov 28, 2018 14:46:33.907 [0x7fad173ff700] DEBUG - Completed: [192.168.1.77:39936] 200 GET /status/sessions (15 live) TLS 0ms 292 bytes (pipelined: 1)
Nov 28, 2018 14:46:33.965 [0x7facfffff700] DEBUG - Setting container serialization range to [0, 49] (total=-1)
Nov 28, 2018 14:46:33.988 [0x7fad173ff700] DEBUG - Completed: [192.168.1.77:39938] 200 GET /library/recentlyAdded (14 live) TLS Page 0-49 83ms 57531 bytes (pipelined: 1)
Nov 28, 2018 14:46:34.067 [0x7fad123ff700] DEBUG - Transcoder segment range: 0 - 2
Nov 28, 2018 14:46:34.824 [0x7facfffff700] DEBUG - Transcoder segment range: 0 - 3
Nov 28, 2018 14:46:35.488 [0x7facfffff700] DEBUG - Transcoder segment range: 0 - 4
Nov 28, 2018 14:46:36.180 [0x7fad123ff700] DEBUG - Transcoder segment range: 0 - 5
Nov 28, 2018 15:47:12.003 [0x7fad0affe700] DEBUG - Shutting down idle session 753be18314d4987c-com-plexapp-android (idle time is 180 seconds)
Nov 28, 2018 15:47:12.003 [0x7fad0affe700] DEBUG - Killing job.
Nov 28, 2018 15:47:12.003 [0x7fad0affe700] DEBUG - Signalling job ID 18389 with 9
Nov 28, 2018 15:47:12.003 [0x7fad0affe700] DEBUG - Job was already killed, not killing again.
Nov 28, 2018 15:47:12.003 [0x7fad0affe700] DEBUG - Stopping transcode session 753be18314d4987c-com-plexapp-android
Nov 28, 2018 15:47:12.004 [0x7facf77ff700] DEBUG - Cleaning directory for session 753be18314d4987c-com-plexapp-android (/tmp/Transcode/Sessions/plex-transcode-753be18314d4987c-com-plexapp-android-85b58792-b781-4a1d-ad4c-a516679d2924)

Above, you can see the data being sent. The transcoder sends 5 segments. The Android app is not responding. It has not sent any progress messages indicating it’s receiving the data. Normal PMS behavior is to stop an idle / non-responsive transcoder session on WAN in order to free up the slot.

6

Hi Chuck,

Thanks for taking a look, I do understand that is the standard behaviour for PMS however this issue was also affecting me on the same network as PMS from the web client too. I have no problem with genuinely idle sessions being killed, but currently it is impossible to watch anything other than a direct stream/play.

Is there a way i can turn off or adjust the timeout for debugging? Because it seems to timeout and kill the session less than 180s in.

Thanks again

7

Please fall back to 1.13.9.5456-ecd600442 (PMS public release)

Comparing your logs to my local logs, there might be a regression in the 1.14.0 beta.

Installing the public 1.13.9 on top of the existing 1.14.0 beta will allow us to determine if indeed a regression.

8

Thanks for the quick reply, I have fallen back to 1.13.9.5456-ecd600442 but the issue persists.

Logs:
Plex Media Server Logs_2018-11-28_16-29-12.zip (3.7 MB)

9

For a bit more context the PMS is running in a VM on my VMware hypervisor. The data is stored on a NAS and is accessed by the VM via a SMB share. The Transcoder temp write dir is /tmp/ on the vm which is a SSD in the hypervisor with ~300gb free.

I’d like to at least narrow down the issue to a PMS issue, Network issue or issue with my VM

10

I am looking at the following:

This is normal web playback. Please notice the “Transcoder segment”

Nov 28, 2018 16:26:59.986 [0x7fdf94bf4700] DEBUG - [Now] User is a123oclock (ID: 1)
Nov 28, 2018 16:26:59.986 [0x7fdf94bf4700] DEBUG - [Now] Device is Firefox (Firefox).
Nov 28, 2018 16:26:59.986 [0x7fdf94bf4700] DEBUG - [Now] Profile is Firefox
Nov 28, 2018 16:26:59.986 [0x7fdf94bf4700] DEBUG - [Now] Updated play state for /library/metadata/34229.
Nov 28, 2018 16:26:59.987 [0x7fdf94bf4700] DEBUG - Statistics: (c1b5yyafhymwktp0gh4z5km6) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Nov 28, 2018 16:26:59.988 [0x7fdfa87ff700] DEBUG - Completed: [192.168.1.3:35172] 200 GET /:/timeline?ratingKey=34229&key=%2Flibrary%2Fmetadata%2F34229&playbackTime=16580&playQueueItemID=40050&state=playing&hasMDE=1&time=16000&duration=3500000 (13 live) TLS GZIP 3ms 841 bytes (pipelined: 8)
Nov 28, 2018 16:27:00.003 [0x7fdfa97ff700] DEBUG - Transcoder segment range: 0 - 66
Nov 28, 2018 16:27:00.011 [0x7fdfa4fff700] DEBUG - Returning segment 66 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00067.m4s"
Nov 28, 2018 16:27:00.011 [0x7fdfa4fff700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream1.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00067.m4s is 33328.
Nov 28, 2018 16:27:00.014 [0x7fdfa87ff700] DEBUG - Completed: [192.168.1.3:35170] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/66.m4s (13 live) TLS GZIP 204ms 33328 bytes (pipelined: 73)
Nov 28, 2018 16:27:00.020 [0x7fdfa6fff700] DEBUG - Request: [192.168.1.3:35170 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/67.m4s (13 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:00.020 [0x7fdfa6fff700] DEBUG - Asked for segment 67 from session.
Nov 28, 2018 16:27:00.047 [0x7fdf913fe700] DEBUG - Returning segment 66 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00067.m4s"
Nov 28, 2018 16:27:00.048 [0x7fdf913fe700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream0.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00067.m4s is 826584.
Nov 28, 2018 16:27:00.050 [0x7fdfa7ffe700] DEBUG - Completed: [192.168.1.3:35163] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/66.m4s (13 live) TLS GZIP 202ms 826584 bytes (pipelined: 82)
Nov 28, 2018 16:27:00.062 [0x7fdfa5fff700] DEBUG - Request: [192.168.1.3:35163 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/67.m4s (13 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:00.062 [0x7fdfa5fff700] DEBUG - Asked for segment 67 from session.
Nov 28, 2018 16:27:00.260 [0x7fdfa97ff700] DEBUG - Transcoder segment range: 0 - 67
Nov 28, 2018 16:27:00.263 [0x7fdfa5fff700] DEBUG - Returning segment 67 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00068.m4s"
Nov 28, 2018 16:27:00.263 [0x7fdfa5fff700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream0.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00068.m4s is 831017.
Nov 28, 2018 16:27:00.265 [0x7fdfa87ff700] DEBUG - Completed: [192.168.1.3:35163] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/67.m4s (13 live) TLS GZIP 202ms 831017 bytes (pipelined: 83)
Nov 28, 2018 16:27:00.280 [0x7fdf94bf4700] DEBUG - Request: [192.168.1.3:35163 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/68.m4s (13 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:00.280 [0x7fdf94bf4700] DEBUG - Asked for segment 68 from session.
Nov 28, 2018 16:27:00.321 [0x7fdfa6fff700] DEBUG - Returning segment 67 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00068.m4s"
Nov 28, 2018 16:27:00.321 [0x7fdfa6fff700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream1.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00068.m4s is 33862.
Nov 28, 2018 16:27:00.321 [0x7fdfa87ff700] DEBUG - Completed: [192.168.1.3:35170] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/67.m4s (13 live) TLS GZIP 301ms 33862 bytes (pipelined: 74)
Nov 28, 2018 16:27:00.327 [0x7fdfa4fff700] DEBUG - Request: [192.168.1.3:35170 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/68.m4s (13 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:00.327 [0x7fdfa4fff700] DEBUG - Asked for segment 68 from session.
Nov 28, 2018 16:27:00.539 [0x7fdfa5fff700] DEBUG - Transcoder segment range: 0 - 68

Thank you for that. I was about to inquire about the network.
What I appear to be seeing, specifically not seeing, is a lack of progress timeline reports

It runs down all the way to segment 205 (which is just over 180 seconds) and then terminates.

Nov 28, 2018 16:27:35.794 [0x7fdf913fe700] DEBUG - Transcoder segment range: 0 - 202
Nov 28, 2018 16:27:35.887 [0x7fdf94bf4700] DEBUG - Request: [192.168.1.3:35193 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/122.m4s (11 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:35.888 [0x7fdf94bf4700] DEBUG - Asked for segment 122 from session.
Nov 28, 2018 16:27:35.888 [0x7fdf94bf4700] DEBUG - Returning segment 122 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00123.m4s"
Nov 28, 2018 16:27:35.888 [0x7fdf94bf4700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream0.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream0-00123.m4s is 1406482.
Nov 28, 2018 16:27:35.897 [0x7fdfa7ffe700] DEBUG - Completed: [192.168.1.3:35193] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/0/122.m4s (11 live) TLS GZIP 9ms 1406482 bytes (pipelined: 8)
Nov 28, 2018 16:27:36.024 [0x7fdfa97ff700] DEBUG - Transcoder segment range: 0 - 203
Nov 28, 2018 16:27:36.266 [0x7fdfa4fff700] DEBUG - Transcoder segment range: 0 - 204
Nov 28, 2018 16:27:36.505 [0x7fdfa5fff700] DEBUG - Transcoder segment range: 0 - 205
Nov 28, 2018 16:27:36.732 [0x7fdf94bf4700] DEBUG - Request: [192.168.1.3:35193 (Subnet)] GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/123.m4s (12 live) TLS GZIP Signed-in
Nov 28, 2018 16:27:36.732 [0x7fdf94bf4700] DEBUG - Asked for segment 123 from session.
Nov 28, 2018 16:27:36.732 [0x7fdf94bf4700] DEBUG - Returning segment 123 from session: "/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00124.m4s"
Nov 28, 2018 16:27:36.732 [0x7fdf94bf4700] DEBUG - Content-Length of /tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/init-stream1.m4s,/tmp/Transcode/Sessions/plex-transcode-8yd5bal8okqv27pfboyblj4h-a7e190fe-55f4-4433-818b-3088023fba6b/chunk-stream1-00124.m4s is 33403.
Nov 28, 2018 16:27:36.733 [0x7fdfa87ff700] DEBUG - Completed: [192.168.1.3:35193] 200 GET /video/:/transcode/universal/dash/8yd5bal8okqv27pfboyblj4h/1/123.m4s (12 live) TLS GZIP 0ms 33403 bytes (pipelined: 9)
Nov 28, 2018 16:27:36.751 [0x7fdf913fe700] DEBUG - Transcoder segment range: 0 - 206
Nov 28, 2018 17:28:12.037 [0x7fdf9d3fe700] DEBUG - Shutting down idle session 8yd5bal8okqv27pfboyblj4h (idle time is 180 seconds)
Nov 28, 2018 17:28:12.037 [0x7fdf9d3fe700] DEBUG - Killing job.

If you are running in the browser or any Plex app, there should be a progress / status update from the client. The lack of any updates appears to be the root cause.

11

Thats nice to at least confirm, any ideas what would be stopping the client sending status updates?

I temporarily disabled the host firewall on my PC and PMS but the issue still exists. Interestingly subsequent attempts to resume the same video result in the transcoder being killed much quicker than the first time.

Plex Media Server Logs_2018-11-28_16-45-13.zip (3.8 MB)

12

How much memory did you allocate to the VM?

13

The VM currently has 8GB memory, but i have plenty of headroom on my ESXI to give this more if you think its required.

I have attempted to use the web app in different browsers without adblocking/tracking protection but this doesn’t seem to be the cause either.

I am also getting the same behaviour on the PS4 app.

Plex Media Server Logs_2018-11-28_16-59-39.zip (3.9 MB)

14

While transcoding the CPU does spike to ~90% but memory usage never goes higher than 10%

15

CPU usage will always spike during software trancoding until the buffer fills. This is normal behavior.

Configuration wise, other than the SMB shares for the media, is any part of PMS or the VM stored on a network share?

16

Nothing else other than the media is stored on a network share, the VM data is stored on the local disk of my ESXI host. At the moment everything (ESXI, NAS and PC) is connected to the same physical switch and is all on the same VLAN too. All devices are using 1Gb NICs

17

Please explain the VLAN?

By default, all NICs are on VLAN 1 (not configured). PMS itself does not understand the concept of a VLAN.

Please show me the ifconfig output

18

Its just i have a separate VLAN for guest WiFi and for IOT devices, but the VM shouldnt care about that. Everything on that switch is all on the same VLAN and my setup has always been this way.

plex@butflix:~# ifconfig
ens160: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.1.77  netmask 255.255.255.0  broadcast 192.168.1.255
        inet6 fe80::20c:29ff:fe54:5584  prefixlen 64  scopeid 0x20<link>
        ether 00:0c:29:54:55:84  txqueuelen 1000  (Ethernet)
        RX packets 20546206  bytes 81420532942 (81.4 GB)
        RX errors 0  dropped 270  overruns 0  frame 0
        TX packets 15962424  bytes 19990659395 (19.9 GB)
        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 799045  bytes 1074087134 (1.0 GB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 799045  bytes 1074087134 (1.0 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
19

Were you playing on one of your IOT-tagged devices?

Remember, if you put something in a VLAN, you must also remember to manually tag is back to VLAN 1.

If you don’t have tagging correct, data can flow one way but not the other. This would explain why PMS isn’t seeing the UDP timeline progress updates whereas it’s seeing the TCP requests / interactions to play

20

I havent played anything from any IOT Tagged devices, the devices i have tested from are all on same VLAN and same subnet (PC 192.168.1.3 & PS4 192.168.1.173)