Live TV Falling short ** wrong ffmpeg time calculation on TS

[sle118 4]

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?

 

 

[Luke 37068]

Thanks for the report, we'll take a look.

[sle118 4]

In the meantime, I have decided to not transcode automatically as current solution is only reliable 5% of the time. 

[Luke 37068]

I would suggest trying the latest release of Emby Server. Thanks !

[sle118 4]

I would suggest trying the latest release of Emby Server. Thanks !

I'm on Beta so this would be 3.2.15.1 ?

[Luke 37068]

That would be fine, yes.

[sle118 4]

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

[sle118 4]

I'm going to try 3.2.15.2-beta now...

[Luke 37068]

I can't help without a log file, thanks.

[sle118 4]

@@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).  

[sle118 4]

@@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

[sle118 4]

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

[Luke 37068]

If you are looking for changes between versions there are none.

[sle118 4]

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).

[Luke 37068]

downstream - i thought you had recording conversion disabled?

[sle118 4]

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. 

[sle118 4]

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.

[Luke 37068]

yea i looked at your log where ffmpeg ended early and it looked like abrupt stream termination from the source.

[Spaceboy 2493]

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.

[Luke 37068]

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.

[Spaceboy 2493]

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