DVR Periodically Starts Late or Ends Early

General Discussions Plex Features
1

I have found that periodically my DVR starts late or ends early. The ending early is far more common and almost happens at the 90 minute mark (recordings should be 2+ hours).

Looking through the log files, it looks like one of the transcoding jobs exits early, but there are no errors or anything. Why is there even a transcoding job running (in fact I think I see 2 transcoding jobs)? I don’t have that feature enabled!

I am running a HDHR Prime with a FIOS CableCard on a CentOS 7 Server and PMS v1.13.4.5271

Here is a snippet of the log when the job is stopped:

Jul 26, 2018 14:30:55.888 [0x7fa4413ff700] VERBOSE - JobManager: child process with PID 12776 exited
Jul 26, 2018 14:30:55.888 [0x7fa4413ff700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 12776 is 0 (success)
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - DVR:Recorder: Asked to stop recording 'Inglourious Basterds (2009)'.
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - DVR:Recorder: Stopping transcode session.
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - Killing job.
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - Signalling job ID 11946 with 9
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - Job was already killed, not killing again.
Jul 26, 2018 14:30:55.888 [0x7fa43e3fe700] DEBUG - Stopping transcode session 8d593e89-f240-4736-a989-51edf1ed8b91
Jul 26, 2018 14:30:55.888 [0x7fa4447ff700] DEBUG - Cleaning directory for session 8d593e89-f240-4736-a989-51edf1ed8b91 (/usr/local/data/plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-8d593e89-f240-4736-a989-51edf1ed8b91)
Jul 26, 2018 14:30:55.941 [0x7fa43e3fe700] DEBUG - DVR:Grabber: Freed a tuner (now 3 available)
Jul 26, 2018 14:30:55.941 [0x7fa43e3fe700] DEBUG - DVR:Grabber: Recording for 'Inglourious Basterds (2009)' stopped with status complete.
Jul 26, 2018 14:30:55.941 [0x7fa43e3fe700] DEBUG - DVR:Grabber: Using recording status.
Jul 26, 2018 14:30:55.941 [0x7fa43e3fe700] DEBUG - Activity: updated activity 68b4ce45-a78a-41d5-9b90-0e569f5d2a3f - completed 100% - Recording

Log of PID 12776 launching:

Jul 26, 2018 12:59:03.692 [0x7fa415ffe700] DEBUG - Cleaning directory for session fda98efd-b227-468b-bd75-6b4873604845 ()
Jul 26, 2018 12:59:03.693 [0x7fa415ffe700] DEBUG - Starting a transcode session fda98efd-b227-468b-bd75-6b4873604845 at offset -1.0 (state=3)
Jul 26, 2018 12:59:03.693 [0x7fa415ffe700] DEBUG - Streaming Resource: Added session 0x7fa412c366e0:fda98efd-b227-468b-bd75-6b4873604845
Jul 26, 2018 12:59:03.698 [0x7fa415ffe700] VERBOSE - Sufficient disk space: 0B source file, 3.1TB capacity, 3.07TB available on "/usr/local/data/plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions"
Jul 26, 2018 12:59:03.698 [0x7fa415ffe700] DEBUG - Job running: EAE_ROOT='/tmp/pms-c02e19c1-f2db-4284-a402-a5171fad941b/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/usr/local/data/plex/Library/Application\ Support/Plex\ Media\ Server/Codecs/e944d3a-1309-linux-ubuntu-x86_64/' XDG_CACHE_HOME='/usr/local/data/plex/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' 'mpeg2video' '-noaccurate_seek' '-live_start_index' '0' '-i' 'http://127.0.0.1:32400/livetv/sessions/8d593e89-f240-4736-a989-51edf1ed8b91/fda98efd-b227-468b-bd75-6b4873604845/index.m3u8?offset=-1.000000&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx' '-map' '0:0' '-codec:0' 'copy' '-map' '0:1' '-metadata:s:1' 'language=eng' '-codec:1' 'copy' '-copypriorss:1' '0' '-map' '0:2' '-metadata:s:2' 'language=spa' '-codec:2' 'copy' '-copypriorss:2' '0' '-f' 'mpegts' '-map_metadata' '-1' '-map_chapters' '-1' '-t' '9480' '/nas-tank-1/tv/movies/.grab/eb67236b1bc3f25978f124fb36e954a7900ae3bc/Inglourious Basterds (2009).ts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/fda98efd-b227-468b-bd75-6b4873604845/0d7fecb6-13f9-40cb-942c-58c09f3cbc37/progress'
Jul 26, 2018 12:59:03.704 [0x7fa415ffe700] DEBUG - Jobs: Starting child process with pid 12776

Launching of PID 11946

Jul 26, 2018 12:59:01.018 [0x7fa415ffe700] DEBUG - Cleaning directory for session 8d593e89-f240-4736-a989-51edf1ed8b91 ()
Jul 26, 2018 12:59:01.019 [0x7fa415ffe700] DEBUG - Starting a transcode session 8d593e89-f240-4736-a989-51edf1ed8b91 at offset -1.0 (state=3)
Jul 26, 2018 12:59:01.019 [0x7fa415ffe700] DEBUG - Streaming Resource: Added session 0x7fa412c35e20:8d593e89-f240-4736-a989-51edf1ed8b91
Jul 26, 2018 12:59:01.023 [0x7fa415ffe700] VERBOSE - Sufficient disk space: 0B source file, 3.1TB capacity, 3.07TB available on "/usr/local/data/plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions"
Jul 26, 2018 12:59:01.023 [0x7fa415ffe700] DEBUG - Job running: EAE_ROOT='/tmp/pms-c02e19c1-f2db-4284-a402-a5171fad941b/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/usr/local/data/plex/Library/Application\ Support/Plex\ Media\ Server/Codecs/e944d3a-1309-linux-ubuntu-x86_64/' XDG_CACHE_HOME='/usr/local/data/plex/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Transcoder' '-noaccurate_seek' '-ignore_unknown' '-scan_all_pmts' '-1' '-rw_timeout' '30000000' '-fflags' '+discardcorruptts+fillwallclockdts' '-i' 'http://192.168.0.134:5004/auto/v869' '-map' '0:V?' '-codec:V' 'copy' '-map' '0:a?' '-codec:a' 'copy' '-copypriorss:a' '0' '-map' '0:s?' '-codec:s' 'copy' '-segment_format' 'mpegts' '-f' 'ssegment' '-individual_header_trailer' '0' '-segment_time' '1' '-segment_start_number' '0' '-segment_time_delta' '0.0625' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/8d593e89-f240-4736-a989-51edf1ed8b91/ce39000a-754b-4292-97b2-7b09a199658b/seglist' '-segment_list_type' 'csv' '-segment_list_size' '2147483647' '-segment_list_separate_stream_times' '1' '-max_delay' '5000000' '-map_metadata' '-1' '-map_chapters' '-1' 'media-%05d.ts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/8d593e89-f240-4736-a989-51edf1ed8b91/ce39000a-754b-4292-97b2-7b09a199658b/progress'
Jul 26, 2018 12:59:01.028 [0x7fa415ffe700] DEBUG - Jobs: Starting child process with pid 11946

I am still trying to capture logs for one of the recordings that starts late.

2

Have the same issue using an HDHomeRun Extend. Occurs with shows that are 2 hours long. Sometimes starts up to 10 minutes late and then ends 15 minutes early.

3

So I was never able to reproduce the starting late issue so I wasn’t able to grab any logs for that.

However, I did some digging on the ending early and I suspect that Plex wasn’t playing nicely with my ZFS pool that I was using to store the PLEX_MEDIA_SERVER_APPLICATION_SUPPORT_DIR. Inside that directory there is the “Cache/Transcode/Sessions” folder that stores 1 TS file for each second of recording and my suspicion is that when there were a large number of files in this folder it caused the Transcode session to end early.

I moved my PLEX_MEDIA_SERVER_APPLICATION_SUPPORT_DIR to a XFS volume on a SSD and I have had much better luck so far. I think I’ve had 10 movies that are 90+ minutes record without any early cutouts.

Not sure if any of this will help your situation though.

4

Running Win10 and not Linux, so your solution is unavailable but might be a clue. Will have to do some playing at the NTFS file system level.

This being the case, I am surprised more people are not having issues. Most movies are 90-120 minutes.

5

I’m having the same issue when I record football games. The recording starts late in the 1st quarter or early in the 2nd quarter consistently.

I’m on Fedora 28 with the latest plex server as of 8/20/2018.

6

I am having the same DVR recording ending early. I am running windows 10 plex version 1.13.8

7

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