OpenDCT: An open source digital cable tuner.

[EnterNoEscape]

• Removed remuxer restarting code since it technically isn't needed if the dts can go as high as it wants and the muxer will continue to work with it.
• Increased dts threshold to differences of over 10 seconds.
• The threshold will now dynamically increase if more than 50 corrections are made over 5 seconds.

[EnterNoEscape]

Originally Posted by troll5501

Makes sense. If you can't find a better way or if an increased value may cause other issues for some users, maybe the dts tolerance could become a tunable property (with the ability to either change the value or to disable the feature entirely if it causes issues). For me, the non-transcoder consumer was working very well--I was running 0.4.27 for several weeks without any significant issues. So I'm not sure that everyone needs these corrective actions or maybe just not such aggressive ones. It seems to depend on the cable/signal provider and the quality of their data streams.

I was starting to leaning towards tunable, but it's one of those properties you really shouldn't need to tune. Anyhow, I think I've got it now.

I ran the bad recording through several different remuxers and the only one that didn't crash or create an unplayable/seekable file was FFmpeg. This situation is truly exceptional, but if it happened by chance with one of my own recordings, I'd rather have a few bad seconds than a completely broken file. This is an excellent example of why I hate making changes to the remuxer.

I might have finally witnessed that CBS issue I think Telecore was having. It looks like transitioning between the show and commercials introduces a discontinuity. I'm not sure how I didn't notice this before, but the good news is it's not going nuts.

[Greg2dot0]

Originally Posted by EnterNoEscape

I ran the bad recording through several different remuxers and the only one that didn't crash or create an unplayable/seekable file was FFmpeg. This situation is truly exceptional, but if it happened by chance with one of my own recordings, I'd rather have a few bad seconds than a completely broken file. This is an excellent example of why I hate making changes to the remuxer.

Let me know if you want more bad recordings. Happy to generate them and share them up.

My results with .41 so far have remained consistent. On any given hour, I'll get 1-2 hiccups in my streams

Thanks again for all your work on this!!!

12:45:56.582 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] WARN  ffmpeg - Last message repeated 1 time.
12:45:56.582 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] WARN  ffmpeg - [mpegts @ 0x7f35c0031840] PES packet size mismatch
12:45:56.635 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = 8410709311, new offset = -8282223076, dts = 8718642924, new dts 307936493, last dts = 307933613, new pts = 8718642924, pts = 307936493, last pts = 307933613
12:45:57.165 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307982912 <= last dts 308009827, pts 307985915, last pts 308009827, discarding frame.
12:45:57.177 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307985915 <= last dts 308009827, pts 307994924, last pts 308009827, discarding frame.
12:45:57.192 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307988918 <= last dts 308009827, pts 307988918, last pts 308009827, discarding frame.
12:45:57.226 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307991921 <= last dts 308009827, pts 307991921, last pts 308009827, discarding frame.
12:45:57.238 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307994924 <= last dts 308009827, pts 308003933, last pts 308009827, discarding frame.
12:45:57.250 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307997927 <= last dts 308009827, pts 307997927, last pts 308009827, discarding frame.
12:45:57.287 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 308000930 <= last dts 308009827, pts 308000930, last pts 308009827, discarding frame.
12:45:57.302 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 dts increment = 1, new offset = -8282223076 dts = 308003933, new dts = 308009828, last dts = 308009828, pts = 308012942, last pts = 308009827
12:45:57.319 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 308006936 <= last dts 308009828, pts 308006936, last pts 308012942, discarding frame.
12:46:26.450 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -2597595, new offset = -8279622478, dts = 307982912, new dts 310583510, last dts = 310580507, new pts = 307985915, pts = 310586513, last pts = 310589516
12:46:26.604 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = 2603478, new offset = -8282223076, dts = 313103171, new dts 310502573, last dts = 310499693, new pts = 313103171, pts = 310502573, last pts = 310499693
12:46:26.666 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = -2568960, new offset = -8279651236, dts = 307936493, new dts 310508333, last dts = 310505453, new pts = 307936493, pts = 310508333, last pts = 310505453
12:46:27.192 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310563761 <= last dts 310589516, pts 310563761, last pts 310589516, discarding frame.
12:46:27.198 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310566764 <= last dts 310589516, pts 310575773, last pts 310589516, discarding frame.
12:46:27.203 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310569767 <= last dts 310589516, pts 310569767, last pts 310589516, discarding frame.
12:46:27.244 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310572770 <= last dts 310589516, pts 310572770, last pts 310589516, discarding frame.
12:46:27.254 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310575773 <= last dts 310589516, pts 310584782, last pts 310589516, discarding frame.
12:46:27.258 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310578776 <= last dts 310589516, pts 310578776, last pts 310589516, discarding frame.
12:46:27.299 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310581779 <= last dts 310589516, pts 310581779, last pts 310589516, discarding frame.
12:46:27.306 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 dts increment = 1, new offset = -8279651236 dts = 310584782, new dts = 310589517, last dts = 310589517, pts = 310593791, last pts = 310589516
12:46:27.309 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310587785 <= last dts 310589517, pts 310587785, last pts 310593791, discarding frame.

But in watching the videos, all seem to be working well with no broken streams.

[troll5501]

Originally Posted by EnterNoEscape

• Removed remuxer restarting code since it technically isn't needed if the dts can go as high as it wants and the muxer will continue to work with it.
• Increased dts threshold to differences of over 10 seconds.
• The threshold will now dynamically increase if more than 50 corrections are made over 5 seconds.

0.4.41 is looking good so far. I've seen a few dts corrections and some discarded frames, but nothing major and no excessive amounts of corrections.

On a different topic, can you tell me what your JVM initial heap and maximum heap values are defaulting to? I've been noticing frequent garbage collection, and looking at the wrapper config I see that the heap sizes are not explicitly defined. So I think each user gets something different based on the physical memory size of the machine (or VM).

Mine is defaulting to initial of 30MB and max of 460MB. I'm just curious if this could be affecting app performance and/or could explain different user experiences. I started looking at this because I'm still getting occasional "Continuity check failed for pid 405090464 expected 0 got 0" errors that result in brief hiccups in the recordings and I can't seem to get rid of them no matter what I try.

[EnterNoEscape]

Originally Posted by Greg2dot0

Let me know if you want more bad recordings. Happy to generate them and share them up.

My results with .41 so far have remained consistent. On any given hour, I'll get 1-2 hiccups in my streams

Thanks again for all your work on this!!!

12:45:56.582 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] WARN  ffmpeg - Last message repeated 1 time.
12:45:56.582 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] WARN  ffmpeg - [mpegts @ 0x7f35c0031840] PES packet size mismatch
12:45:56.635 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = 8410709311, new offset = -8282223076, dts = 8718642924, new dts 307936493, last dts = 307933613, new pts = 8718642924, pts = 307936493, last pts = 307933613
12:45:57.165 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307982912 <= last dts 308009827, pts 307985915, last pts 308009827, discarding frame.
12:45:57.177 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307985915 <= last dts 308009827, pts 307994924, last pts 308009827, discarding frame.
12:45:57.192 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307988918 <= last dts 308009827, pts 307988918, last pts 308009827, discarding frame.
12:45:57.226 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307991921 <= last dts 308009827, pts 307991921, last pts 308009827, discarding frame.
12:45:57.238 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307994924 <= last dts 308009827, pts 308003933, last pts 308009827, discarding frame.
12:45:57.250 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 307997927 <= last dts 308009827, pts 307997927, last pts 308009827, discarding frame.
12:45:57.287 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 308000930 <= last dts 308009827, pts 308000930, last pts 308009827, discarding frame.
12:45:57.302 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 dts increment = 1, new offset = -8282223076 dts = 308003933, new dts = 308009828, last dts = 308009828, pts = 308012942, last pts = 308009827
12:45:57.319 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 308006936 <= last dts 308009828, pts 308006936, last pts 308012942, discarding frame.
12:46:26.450 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -2597595, new offset = -8279622478, dts = 307982912, new dts 310583510, last dts = 310580507, new pts = 307985915, pts = 310586513, last pts = 310589516
12:46:26.604 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = 2603478, new offset = -8282223076, dts = 313103171, new dts 310502573, last dts = 310499693, new pts = 313103171, pts = 310502573, last pts = 310499693
12:46:26.666 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 2 timestamp discontinuity diff = -2568960, new offset = -8279651236, dts = 307936493, new dts 310508333, last dts = 310505453, new pts = 307936493, pts = 310508333, last pts = 310505453
12:46:27.192 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310563761 <= last dts 310589516, pts 310563761, last pts 310589516, discarding frame.
12:46:27.198 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310566764 <= last dts 310589516, pts 310575773, last pts 310589516, discarding frame.
12:46:27.203 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310569767 <= last dts 310589516, pts 310569767, last pts 310589516, discarding frame.
12:46:27.244 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310572770 <= last dts 310589516, pts 310572770, last pts 310589516, discarding frame.
12:46:27.254 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310575773 <= last dts 310589516, pts 310584782, last pts 310589516, discarding frame.
12:46:27.258 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310578776 <= last dts 310589516, pts 310578776, last pts 310589516, discarding frame.
12:46:27.299 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310581779 <= last dts 310589516, pts 310581779, last pts 310589516, discarding frame.
12:46:27.306 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - fixing stream 0 dts increment = 1, new offset = -8279651236 dts = 310584782, new dts = 310589517, last dts = 310589517, pts = 310593791, last pts = 310589516
12:46:27.309 [FFmpegTransSageTVConsumerImpl-2055:DCT-HDHomeRun Prime Tuner 13142E5A-0] DEBUG FFmpegTranscoder - stream 0, dts 310587785 <= last dts 310589517, pts 310587785, last pts 310593791, discarding frame.

But in watching the videos, all seem to be working well with no broken streams.

Unfortunately, your situation is likely as good as it's going to get. So long as your streams have those errors coming from the source, you'll see these in your log from time to time. On the plus side it's good to hear the corrections aren't causing the recording to be hard to watch.

Originally Posted by troll5501

On a different topic, can you tell me what your JVM initial heap and maximum heap values are defaulting to? I've been noticing frequent garbage collection, and looking at the wrapper config I see that the heap sizes are not explicitly defined. So I think each user gets something different based on the physical memory size of the machine (or VM).

Mine is defaulting to initial of 30MB and max of 460MB. I'm just curious if this could be affecting app performance and/or could explain different user experiences. I started looking at this because I'm still getting occasional "Continuity check failed for pid 405090464 expected 0 got 0" errors that result in brief hiccups in the recordings and I can't seem to get rid of them no matter what I try.

My Ubuntu 14.04 VM is running OpenJDK and is defaulted to 64MB-1GB and my Fedora 23 VM is running Oracle and is defaulted to 132MB-2GB. Ubuntu has 4GB of RAM and Fedora has 8GB. I'm running SageTV on the Fedora 23 vm set to 4GB for the max heap size, I guess because I can. You can define the size if you want by uncommenting and changing the values of wrapper.java.initmemory=3 and wrapper.java.maxmemory=64 in /opt/opendct/jsw/conf/wrapper.conf.

I suspect the issue you're seeing is the HDHomeRun silently dropping frames because the HTTP stream isn't keeping up. If you want to see how it fairs while using RTP (where you'll actually see in the log when the frames are dropped), change hdhr.allow_http_tuning to false in opendct.properties.

It's interesting that you're seeing frequent garbage collection. There should be very little as a result of the actual recording threads once they are actually streaming. The biggest amounts would likely be if the queue buffer was overflowed into since that's entirely a garbage collection situation. I know that garbage collection apparently stops the entire JVM when it happens, so it's a good place to look for performance losses. Maybe the lowish heap size is causing it to be more aggressive than it needs to be.

[troll5501]

Originally Posted by EnterNoEscape

It's interesting that you're seeing frequent garbage collection. There should be very little as a result of the actual recording threads once they are actually streaming. The biggest amounts would likely be if the queue buffer was overflowed into since that's entirely a garbage collection situation. I know that garbage collection apparently stops the entire JVM when it happens, so it's a good place to look for performance losses. Maybe the lowish heap size is causing it to be more aggressive than it needs to be.

The GC was occurring every few seconds with the default settings. Now with a 128MB initial heap and (just for fun) enabling the G1GC collector, they are now occurring about every 30 seconds. These are not full GC however.

I've been watching the JVM with jvmtop and jstat and the heap ramps up to around the minimum size (this happens quicker with more active recordings)--and then I get a GC operation in wrapper.log and the usage drops way down and grows again, and this repeats. I guess because of the continuous allocation of new objects to handle the streaming data? Or is this not the way it should be working?

[EnterNoEscape]

Originally Posted by troll5501

The GC was occurring every few seconds with the default settings. Now with a 128MB initial heap and (just for fun) enabling the G1GC collector, they are now occurring about every 30 seconds. These are not full GC however.

I've been watching the JVM with jvmtop and jstat and the heap ramps up to around the minimum size (this happens quicker with more active recordings)--and then I get a GC operation in wrapper.log and the usage drops way down and grows again, and this repeats. I guess because of the continuous allocation of new objects to handle the streaming data? Or is this not the way it should be working?

I may need to take a closer look at what's going on while streaming. A circular buffer is being used for the significant data amounts, so what you're seeing shouldn't really be happening all that quickly. I may need to optimize my most recent changes so we don't keep re-creating anything that could just be recycled.

[EnterNoEscape]

I think I figured out at least part of the problem. I may be generating too many string objects in the FFmpeg logger. At present it's allocating 1024 bytes and creating a string just to figure out if the message needs to be logged. The strings don't change much, so I'm reworking it so it will re-use those strings instead of creating them.

[troll5501]

Originally Posted by EnterNoEscape

I think I figured out at least part of the problem. I may be generating too many string objects in the FFmpeg logger. At present it's allocating 1024 bytes and creating a string just to figure out if the message needs to be logged. The strings don't change much, so I'm reworking it so it will re-use those strings instead of creating them.

Thanks for looking into the GC issue. I'll be happy to test the changes when they are ready.

Some bad news: this morning 0.4.41 got into a dts correction loop for the entire length of a 3 hour recording (from 07:00 until 10:00). See the attached log starting at 07:00:03.990.

Unfortunately the new threshold adjustments, even occurring after every 50 corrections, never got close to the diff value. Here are the last few log entries from the end of the recording (the full logfile was too big to attach, so I only attached the first 30-45 minutes of logs):

10:00:00.467 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 1 timestamp discontinuity diff = 4191806943, new offset = -8382982671, dts = 5489684141, new dts 1297880078, last dts = 1297877198, new pts = 5489684141, pts = 1297880078, last pts = 1297877198
10:00:00.467 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] INFO  FFmpegTranscoder - Adjusting threshold to 952200000. Errors = 51
10:00:00.585 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -4191801060, new offset = -4191178608, dts = 1297930646, new dts 5489734709, last dts = 5489731706, new pts = 1297933649, pts = 5489737712, last pts = 5489734709

[EnterNoEscape]

Originally Posted by troll5501

Thanks for looking into the GC issue. I'll be happy to test the changes when they are ready.

Some bad news: this morning 0.4.41 got into a dts correction loop for the entire length of a 3 hour recording (from 07:00 until 10:00). See the attached log starting at 07:00:03.990.

Unfortunately the new threshold adjustments, even occurring after every 50 corrections, never got close to the diff value. Here are the last few log entries from the end of the recording (the full logfile was too big to attach, so I only attached the first 30-45 minutes of logs):

10:00:00.467 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 1 timestamp discontinuity diff = 4191806943, new offset = -8382982671, dts = 5489684141, new dts 1297880078, last dts = 1297877198, new pts = 5489684141, pts = 1297880078, last pts = 1297877198
10:00:00.467 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] INFO  FFmpegTranscoder - Adjusting threshold to 952200000. Errors = 51
10:00:00.585 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -4191801060, new offset = -4191178608, dts = 1297930646, new dts 5489734709, last dts = 5489731706, new pts = 1297933649, pts = 5489737712, last pts = 5489734709

You hit one of the possible wrap around thresholds. 2 ^ 33 / 2. What I don't understand is how one ends up with a 13~ hour disparity between the audio and video time stamps. Normally it's no more than 3 seconds.

I re-wrote how ffmpeg logging discards logging entries to create a lot fewer objects and it even recycles the arrays if possible. I noticed that so long as Cling is running, the JVM will always periodically create a bunch of young GC objects. The problem comes from it creating a new byte array every time a packet comes in to process the packet asynchronously.

I'll see if I can figure out a better way to determine what's really happening since in your situation, if I started to just discard all frames behind a certain timestamp, you would either loose all of your audio or all of your video for the next few hours.

[troll5501]

Originally Posted by EnterNoEscape

You hit one of the possible wrap around thresholds. 2 ^ 33 / 2. What I don't understand is how one ends up with a 13~ hour disparity between the audio and video time stamps. Normally it's no more than 3 seconds.

I'll see if I can figure out a better way to determine what's really happening since in your situation, if I started to just discard all frames behind a certain timestamp, you would either loose all of your audio or all of your video for the next few hours.

Thanks. I'm guessing this is a rare situation, but when it happens things get out of control quickly. Hopefully you can find a way to detect this wrap-around and adjust the thresholds more aggressively or else disable the corrections when the diff is so large.

I saw this yesterday but it only lasted for 1 second and didn't cause any problems, but since the diff is so large I wanted you to see the logs in case it's another variation of the same issue:

16:37:40.435 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] WARN  ffmpeg - Last message repeated 1 time.
16:37:40.436 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] WARN  ffmpeg - [mpegts @ 0x7f5009e903c0] Invalid timestamps stream=405090464, pts=(null), dts=(null), size=0
16:37:40.437 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -8589931589, new offset = 4398755984, dts = -952805634, new dts 7637128958, last dts = 7637125955, new pts = -952796625, pts = 7637137967, last pts = 7637125955
16:37:40.437 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 1 timestamp discontinuity diff = 8589937472, new offset = -4191178608, dts = 16227018733, new dts 7637084141, last dts = 7637081261, new pts = 16227018733, pts = 7637084141, last pts = 7637081261
16:37:40.446 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -8589931589, new offset = 4398755984, dts = -952802631, new dts 7637131961, last dts = 7637128958, new pts = -952802631, pts = 7637131961, last pts = 7637137967
16:37:40.593 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 1 timestamp discontinuity diff = 8589937472, new offset = -4191178608, dts = 16227033133, new dts 7637098541, last dts = 7637095661, new pts = 16227033133, pts = 7637098541, last pts = 7637095661
16:37:40.603 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -8589931589, new offset = 4398755984, dts = -952787616, new dts 7637146976, last dts = 7637143973, new pts = -952778607, pts = 7637155985, last pts = 7637143973
16:37:40.752 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 1 timestamp discontinuity diff = 8589937472, new offset = -4191178608, dts = 16227047533, new dts 7637112941, last dts = 7637110061, new pts = 16227047533, pts = 7637112941, last pts = 7637110061
16:37:40.763 [FFmpegTransSageTVConsumerImpl-13051:DCT-HDHomeRun Prime Tuner 13191941-1] DEBUG FFmpegTranscoder - fixing stream 0 timestamp discontinuity diff = -8589931589, new offset = 4398755984, dts = -952766595, new dts 7637167997, last dts = 7637164994, new pts = -952766595, pts = 7637167997, last pts = 7637174003

I re-wrote how ffmpeg logging discards logging entries to create a lot fewer objects and it even recycles the arrays if possible. I noticed that so long as Cling is running, the JVM will always periodically create a bunch of young GC objects. The problem comes from it creating a new byte array every time a packet comes in to process the packet asynchronously.

Thanks for all of the recent fixes! I looked at the changes so far, and if they reduce CPU usage as well as memory consumption that will be great!

[EnterNoEscape]

Originally Posted by troll5501

Thanks for all of the recent fixes! I looked at the changes so far, and if they reduce CPU usage as well as memory consumption that will be great!

The memory consumption will always be around 10MB per loaded tuner because of the buffers involved, so there's not a whole lot I can do there, and some of the sawtooth looking profile for young GC while streaming is coming from objects being created when FFmpeg returns objects, plus the Cling activity mentioned before, so it should be better, but it will likely never be perfect.

The diff was surprisingly large and likely was a successful wrap around, but as long as you're not having any problems as a result, then I'm happy. I'm working on tracking the diffs per stream and syncing them up after the "anomaly" so we don't go back and forth so much. They need to all be on the same offset eventually though because otherwise they will start to drift apart.

[EnterNoEscape]

• Changed the old FFmpeg consumer to only do dts == last dts discarding since that's the way it used to do it and there are fewer variables to consider when doing it this way. It is still no longer the default.
• Changed the dts fixing code so it will deal with streams individually, then sync them when it makes sense or an attempt limit is reached.
• The local IP address override is now created, but not automatically populated in opendct.properties. If needed, you can set the IP address, but while it is blank, it will be determined automatically.
• FFmpeg logger now recycles most temporary objects and avoids creating strings as much as possible.
• Adjusted some other polling times to reduce the number of shortly lived objects being created and overall CPU utilization.
• Profiled streaming code and optimized when possible.
• Internal: Removed some logging stack traces that don't need to exist.

[troll5501]

Originally Posted by EnterNoEscape

OpenDCT 0.4.42-RC7

Installed 0.4.42 this morning and no issues and no dts corrections so far today. I reverted back to the default GC and heap sizes for the first round of testing. GC is currently occurring every 5 to 10 seconds with two active recordings but it isn't causing any problems.

[EnterNoEscape]

Originally Posted by troll5501

Installed 0.4.42 this morning and no issues and no dts corrections so far today. I reverted back to the default GC and heap sizes for the first round of testing. GC is currently occurring every 5 to 10 seconds with two active recordings but it isn't causing any problems.

That sounds about right. I suspect we have seen the end of complete runaways regarding dts corrections too. The current code will not tolerate it for more than 20 packets before it basically forces things to behave. You likely will only see about 7 messages regarding the entire ordeal. If the current code can't fix your stream fairly quickly, there's a good chance you've got bigger problems.

I am planning after I consider this version "stable" and final, a future version to redo the UPnP so it's just used to find the InfiniTV devices, then stops running since we won't actually be using it for tuning and only starts back up if the device goes missing or the computer comes out of standby. Everyone as far as I know, but Bill have been using the default http (POST) method and I haven't heard any complaints about it that are any worse than UPnP tuning. To get UPnP tuning completely optimized so it's as fast as the http method, you need to leave the device in a state that could be disrupted. The difference between http and UPnP from a dead start can be as much as 4 seconds. Of course if we found a device that people wanted supported that could only talk via UPnP, I'd have to change this behavior when that device was detected, but I suspect that's unlikely. This change alone might help you out more than you'd expect.

Currently I'm wrangling CCExtractor. I started to parse the binary output and reformat it to .srt until I realized it's outputting completely raw captions and I really don't want to re-invent the wheel since the program is far better at making them more presentable than me. So now I'm looking at modifying the source code so I can create the .srt files before the recording starts and it will overwrite them, so the subtitles option always appears on live tv. Annoyingly it has an option to specify all desired file names, but the option is broken, yet it's still documented like it actually works. The alternative I guess would be to only support one caption stream and export it via stdout from CCExtractor, but I really wanted to be able to export all possible streams. I also really want the subtitles to show up as CC1, CC2, CC3, CC4 although CC1 is 99% of the time going to be the right one, so maybe I'm being finicky. This feature is really in my opinion only going to be helpful to people who are live transcoding since you lose the captions when the video is transcoded. Everyone else I think would be better served by a plugin that works similar to the Comskip plugin.

I forgot to mention that CCExtractor uses over 150MB of RAM per instance, so if you have a large number of tuners, you'll need more RAM that you'd expect.

[jgsouthard]

Several recordings into 0.4.42-RC7, and all looks good so far.

[EnterNoEscape]

Thanks for the feedback.

I'm really glad to I was able to get a fix in place to correct the timestamps. I was talking to Bill about this earlier in the week and he confirmed it was a particular commercial for him that was breaking his recordings. He also confirmed that when he tried RC6, he no longer had the issue. What I think is happening is when local commercials are inserted into the transport stream, whomever/whatever is inserting the commercials is not always correcting the timestamps to bring the local commercial in line with the last timestamp in the actual stream. The providers own STB can probably tolerate this, but I've found plenty of popular players that have no idea what's going on when they encounter this and do strange things like report the recording is 2 minutes when it's actually an hour. That means that if you live in an area where this is happens you really have no choice but to use FFmpeg to clean up your recordings.

[troll5501]

I had one issue with a recording last night but it doesn't seem related to dts. The resulting recording was just a black screen and unwatchable, and when I tried to FF (even far into it) it would always jump back to around the 30 second mark. However the recording file was 24GB which seems normal for the length of the show (3.5 hours).

Log is attached. The recording starts at timestamp 19:00:01.648.

I recorded the same channel at the same time on my other Sage box with HD-PVR and STB and it was fine.

[troll5501]

I also noticed several thousand dts correction errors all at one time in today's log (I left live TV running overnight), so I am attaching it just so you can take a look...again just in case it's some other scenario that you haven't seen. The errors start at 00:35.

I'm also including my wrapper.log so you can see the frequency of the GC. If it's occurring more frequently that you think it should (it's now happening every 2-3 seconds with a Full GC every 2-3 minutes), then maybe the minimum/initial heap should be explicitly set since it ends up being so small on systems without lots of memory (my VM currently has 2GB allocated).

In other news, since installing 0.4.42 I have not seen any of the "Continuity check failed" errors, so maybe something you did related to the code optimizations unexpectedly helped with this issue. I still get the occasional "PES packet size mismatch" but usually it's when a program switches to/from commercial and it doesn't cause any visual or audio break in the recording.

[EnterNoEscape]

Originally Posted by troll5501

I had one issue with a recording last night but it doesn't seem related to dts. The resulting recording was just a black screen and unwatchable, and when I tried to FF (even far into it) it would always jump back to around the 30 second mark. However the recording file was 24GB which seems normal for the length of the show (3.5 hours).

Log is attached. The recording starts at timestamp 19:00:01.648.

I recorded the same channel at the same time on my other Sage box with HD-PVR and STB and it was fine.

It looks like the first attempt could not get everything it needed about the video. Unfortunately that's all FFmpeg. If it can't find the video dimensions, usually that means something is particularly interesting about the video stream which might be why you are having playback issues with the file that was produced. If you want to chop off a chunk of that file, or just upload the whole thing and make it available to me, I am interested in what's so special about that stream.

Originally Posted by troll5501

I also noticed several thousand dts correction errors all at one time in today's log (I left live TV running overnight), so I am attaching it just so you can take a look...again just in case it's some other scenario that you haven't seen. The errors start at 00:35.

I'm also including my wrapper.log so you can see the frequency of the GC. If it's occurring more frequently that you think it should (it's now happening every 2-3 seconds with a Full GC every 2-3 minutes), then maybe the minimum/initial heap should be explicitly set since it ends up being so small on systems without lots of memory (my VM currently has 2GB allocated).

In other news, since installing 0.4.42 I have not seen any of the "Continuity check failed" errors, so maybe something you did related to the code optimizations unexpectedly helped with this issue. I still get the occasional "PES packet size mismatch" but usually it's when a program switches to/from commercial and it doesn't cause any visual or audio break in the recording.

I mostly see it dropping frames because the last value is higher than the current value. I think there might have been an error in my thinking because I can tell exactly why it thinks they are too far apart, but actually they technically are right next to each other. I actually did test this exact scenario with different results, so I need to re-think my strategy. Fortunately I have an idea.

I'm thinking you're right about defining the values. I think 128MB min and 768MB max should be sufficient. On my primary, usually see things hover around 235MB with 9 tuners loaded. I figure no one is running SageTV on a computer with less than 2GB of ram.

Also the excessive garbage collection at first is because every 5 seconds for 30 seconds, it tries to find any available InfiniTV devices via UPnP. It will go longer if you have the device count specified until the number of expected devices is loaded or it reaches it's own timeout.