sle118 4 Posted May 4, 2017 Share Posted May 4, 2017 There is an issue with Live TV recording when live transcoding is enabled, resulting in record length shorter than the requested time. I've been scratching my head for a long time on this and decided today that I was tired of having to schedule the same movies multiple times in hope to get at least one copy working. In short: - Emby schedules recording, based on pre-padding duration and program start time - Start time is reached, Emby calculates total time to record - Emby launches ffmpeg, passing a duration limit - ffmpeg reads mpegts stream and starts transcoding - ffmpeg uses stream, NOT ELAPSED TIME, to decide when to stop recording - ffmpeg decides it's time to end the recording - Emby sees that everything was good and proceed with additional tasks on the recorded show Some stats : - Calculated duration in scheduled task = 1:56:00 - Pre-padding : 60 seconds - Post Padding : 120 seconds - Calculated recording duration passed to ffmpeg: 1:58:52 (close enough, as padding is done "when possible") - Log file record start time : 12:19:00 - Log file record end time : 14:09:53 - Real recording duration : 1:50:53 ** ouch almost 8 minutes short... - ffmpeg transcoding speed is ~1.08. Interestingly, this is close to the "expected time / actual time" ratio of time Partial output from ffmpeg transcode to show the stream type content: Input #0, mpegts, from 'http://192.168.10.201:8866/live?channel=999': Duration: N/A, start: 0.867044, bitrate: N/A Program 1 Stream #0:0[0x1011]: Video: h264 (Main) (HDMV / 0x564D4448), yuv420p(tv, bt709), 1920x1080 [SAR 1:1 DAR 16:9], 29.97 fps, 59.94 tbr, 90k tbn, 59.94 tbc Stream #0:1[0x1100]: Audio: ac3 (AC-3 / 0x332D4341), 48000 Hz, 5.1(side), fltp, 384 kb/s [libx264 @ 0000000003b0fb00] using SAR=1/1 [libx264 @ 0000000003b0fb00] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX [libx264 @ 0000000003b0fb00] profile High, level 4.1 [libx264 @ 0000000003b0fb00] 264 - core 148 r2665 a01e339 - H.264/MPEG-4 AVC codec - Copyleft 2003-2016 - http://www.videolan.org/x264.html - options: cabac=1 ref=1 deblock=1:0:0 analyse=0x3:0x3 me=dia subme=1 psy=1 psy_rd=1.00:0.00 mixed_ref=0 me_range=16 chroma_me=1 trellis=0 8x8dct=1 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=0 threads=12 lookahead_threads=2 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=3 b_pyramid=2 b_adapt=1 b_bias=0 direct=1 weightb=1 open_gop=0 weightp=1 keyint=250 keyint_min=25 scenecut=40 intra_refresh=0 rc_lookahead=0 rc=crf mbtree=0 crf=23.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 vbv_maxrate=25000 vbv_bufsize=50000 crf_max=0.0 nal_hrd=none filler=0 ip_ratio=1.40 pb_ratio=1.30 aq=1:1.00 [mp4 @ 000000000480d4a0] track 1: codec frame size is not set Output #0, mp4, to 'F:\Data\EmbyRecord\Movie\zzz\zzz aaaa4da212ae4f35bfb828201e90b340.mp4': Metadata: encoder : Lavf57.32.100 Stream #0:0: Video: h264 (libx264) ([33][0][0][0] / 0x0021), yuv420p, 1920x1080 [SAR 1:1 DAR 16:9], q=-1--1, 25000 kb/s, 29.97 fps, 30k tbn, 29.97 tbc Metadata: encoder : Lavc57.34.100 libx264 Side data: cpb: bitrate max/min/avg: 25000000/0/25000000 buffer size: 50000000 vbv_delay: -1 Stream #0:1: Audio: ac3 ([165][0][0][0] / 0x00A5), 48000 Hz, 5.1(side), 384 kb/s Stream mapping: Stream #0:0 -> #0:0 (h264 (native) -> h264 (libx264)) Stream #0:1 -> #0:1 (copy) End of the transcoding: frame=213800 fps= 32 q=-1.0 Lsize= 4715222kB time=01:58:53.77 bitrate=5414.7kbits/s dup=181 drop=11 speed=1.08x video:4378609kB audio:337251kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown [libx264 @ 0000000003b0fb00] frame I:3359 Avg QP:12.95 size: 74684 [libx264 @ 0000000003b0fb00] frame P:94293 Avg QP:15.59 size: 32612 [libx264 @ 0000000003b0fb00] frame B:116148 Avg QP:17.40 size: 9968 [libx264 @ 0000000003b0fb00] consecutive B-frames: 17.0% 27.3% 13.0% 42.7% [libx264 @ 0000000003b0fb00] mb I I16..4: 38.9% 42.5% 18.6% [libx264 @ 0000000003b0fb00] mb P I16..4: 13.5% 13.0% 1.0% P16..4: 43.6% 0.0% 0.0% 0.0% 0.0% skip:28.9% [libx264 @ 0000000003b0fb00] mb B I16..4: 2.0% 1.2% 0.0% B16..8: 22.2% 0.0% 0.0% direct:14.1% skip:60.4% L0:41.7% L1:52.2% BI: 6.1% [libx264 @ 0000000003b0fb00] 8x8 transform intra:45.6% inter:42.8% [libx264 @ 0000000003b0fb00] coded y,uvDC,uvAC intra: 47.7% 56.3% 18.5% inter: 9.9% 20.2% 1.1% [libx264 @ 0000000003b0fb00] i16 v,h,dc,p: 53% 20% 22% 5% [libx264 @ 0000000003b0fb00] i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 20% 16% 29% 6% 5% 7% 5% 6% 6% [libx264 @ 0000000003b0fb00] i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 31% 24% 17% 6% 5% 5% 4% 4% 5% [libx264 @ 0000000003b0fb00] i8c dc,h,v,p: 38% 24% 29% 9% Is there a way to control recording duration by monitoring recording threads and sending ffmpeg a signal when it's time to end instead of relying on stream based duration, which is subject to issues? Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 5, 2017 Share Posted May 5, 2017 Thanks for the report, we'll take a look. Link to comment Share on other sites More sharing options...
sle118 4 Posted May 8, 2017 Author Share Posted May 8, 2017 In the meantime, I have decided to not transcode automatically as current solution is only reliable 5% of the time. Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 8, 2017 Share Posted May 8, 2017 I would suggest trying the latest release of Emby Server. Thanks ! Link to comment Share on other sites More sharing options...
sle118 4 Posted May 8, 2017 Author Share Posted May 8, 2017 I would suggest trying the latest release of Emby Server. Thanks ! I'm on Beta so this would be 3.2.15.1 ? Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 8, 2017 Share Posted May 8, 2017 That would be fine, yes. Link to comment Share on other sites More sharing options...
sle118 4 Posted May 9, 2017 Author Share Posted May 9, 2017 That would be fine, yes. I tried on 3.2.15.0, as this was the version that had been pushed to the server. The end result is a set of cascading failures: - (m3u TS) One recording timer started while the "transcode" option had been turned off. TS File created fine, record successful. - (m3u TS) Later, Another recording timer started while transcode was NOT active. TS file created (copying recording stream), but ended short (~40 minutes) no trace of the job in the timer file. - (HDHR) Later (15/20 minutes after previous failure), a HDHR timer fired to record for an hour, but no file was saved. The last trace is " Info App: Opened HDHR UDP stream from ...". No "Info App: Returning mediasource streamId " sent back and the following is a cascade of failed recordings with " but the program has already ended" warning messages at the end. All the recordings from #2 above are still sitting at "active". I don't think it's related, my server might be missing a dependency System.EntryPointNotFoundException: Impossible de trouver le point d'entrée 'NetworkIsolationEnumAppContainers' dans la DLL 'FirewallAPI.dll'. Note that my FirewallAPI.dll file is at level 6.1.7600.16385 Link to comment Share on other sites More sharing options...
sle118 4 Posted May 9, 2017 Author Share Posted May 9, 2017 I'm going to try 3.2.15.2-beta now... Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 9, 2017 Share Posted May 9, 2017 I can't help without a log file, thanks. Link to comment Share on other sites More sharing options...
sle118 4 Posted May 9, 2017 Author Share Posted May 9, 2017 @@Luke, I understand this, so I'll run the beta through a few scenarios on a clean slate (after restarting the server). The "falling short" description pretty much says it all, though, and the other issues I am experiencing are of a different nature. If it's ok, I'll PM you a link to the log files as I hate to post them publicly (too much personal data in there). Link to comment Share on other sites More sharing options...
sle118 4 Posted May 10, 2017 Author Share Posted May 10, 2017 (edited) @@Luke, I sent you a PM with log files regarding the issue. It would seem that the duration works better now, but it's hard to tell because only one of the recordings was a success (the other one failed, likely because the NextPVR box was having issues with heavy disk I/O). Here is what I did: - Stop server - Download beta version (windows zip) - Backup system folder - Unzip system to Emby location - Start Server - Record a few movies From NextPVR acting as m3u video source 2X spaced From NextPVR m3u with an overlap on Legacy HDPVR capture All with transcoding enabled Once again, the server is in a state where no stream is being captured at all and no LiveTV can be watched. Thanks for looking into this. ** EDIT: I believe I have narrowed down the issue with HDHR udp streaming failure on unstable signal (i.e. when the HDHR cannot get a lock on the signal). Details posted below. Sorry for cross-posting, but I want to keep this thread focused on the recording duration issue https://emby.media/community/index.php?/topic/47346-cascading-recording-failureslive-tv-failrecordings-stuck-in-active/ Edited May 10, 2017 by sle118 Link to comment Share on other sites More sharing options...
sle118 4 Posted May 10, 2017 Author Share Posted May 10, 2017 That would be fine, yes. I have done amy first successful recording on 3.2.15.2-beta, and I am reporting that so far, the duration would seem to be fine. However, let's not call it victory just yet. I'll run more tests and report back Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 10, 2017 Share Posted May 10, 2017 If you are looking for changes between versions there are none. Link to comment Share on other sites More sharing options...
sle118 4 Posted May 10, 2017 Author Share Posted May 10, 2017 If you are looking for changes between versions there are none. I had figured that out already, which is why I'll keep testing in hope to idenfify a pattern between recordings that falling short and recordings that aren't. I would imagine that I'll find something either upstream (e.g. NextPVR buffering issues) or downstream (e.g. ffmpeg incorrectly reading the stream content). Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 10, 2017 Share Posted May 10, 2017 downstream - i thought you had recording conversion disabled? Link to comment Share on other sites More sharing options...
sle118 4 Posted May 10, 2017 Author Share Posted May 10, 2017 downstream - i thought you had recording conversion disabled? Negative, since I found that the root cause that explains 95% of all my cascading failures (the vast majority of recordings) was an unstable HDHR channel which didn't seem to send anything back to the UDP connection from Emby, I have decided to take another shot at recording multiple scenarios with transcoding enabled to ensure that I get enough details for you. Link to comment Share on other sites More sharing options...
sle118 4 Posted May 11, 2017 Author Share Posted May 11, 2017 I'm documenting my progress here in case anyone else is getting the same sort of issues. The recordings which were falling short are coming from a m3u source, NextPVR. I watched closely a few recordings, this time looking at logs on the NextPVR side (logs are rotated and don't last very long so troubleshooting can only be done within a day of the issue happening). I found out that NextPVR sometimes looses connection with the HDPVR device, which ends up closing the stream. This is a proof of an "upstream" loss resulting in a shorter recording. I will see if I can update the hauppauge drivers on that box, and if that fixes upstream recording issues. Otherwise, I'll monitor the hardware itself and see if it's heating up when drops happen. Note that I still have a "downstream" case documented where ffmpeg didn't calculate duration properly, so that "downstream" duration calculation issue is still likely real. Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 11, 2017 Share Posted May 11, 2017 yea i looked at your log where ffmpeg ended early and it looked like abrupt stream termination from the source. Link to comment Share on other sites More sharing options...
Spaceboy 2500 Posted May 12, 2017 Share Posted May 12, 2017 This does sound similar to some of the issues I'm having. I regularly get whacky program lengths and have previously reported recordings from a m3u source ending early with conversion turned on. Link to comment Share on other sites More sharing options...
Luke 37180 Posted May 12, 2017 Share Posted May 12, 2017 This does sound similar to some of the issues I'm having. I regularly get whacky program lengths and have previously reported recordings from a m3u source ending early with conversion turned on. Same symptom but different matter entirely. In your case, I think it is the remote provider that is raising an error, probably due to exceeding a limit of simultaneous connections. Link to comment Share on other sites More sharing options...
Spaceboy 2500 Posted May 12, 2017 Share Posted May 12, 2017 Same symptom but different matter entirely. In your case, I think it is the remote provider that is raising an error, probably due to exceeding a limit of simultaneous connections.yeah it's not that. I've already told you, I have 6 available Link to comment Share on other sites More sharing options...
Recommended Posts
Create an account or sign in to comment
You need to be a member in order to leave a comment
Create an account
Sign up for a new account in our community. It's easy!
Register a new accountSign in
Already have an account? Sign in here.
Sign In Now