OpenDCT: An open source digital cable tuner.

[EnterNoEscape]

Originally Posted by HelenWeathers

I changed producer.rtp.nio.stalled_timeout_s=5 to producer.rtp.nio.stalled_timeout_s=30. Started OpenDCT, waited 15 sec & started SageTV service.

Sage now gives me a > 30 second jump ahead in time line for both DCT recordings each time an OTA recording is started.

With WMPlayer when I hit the first of these spots it plays thru it but on the second occurance the video just freezes. In VideoRedo using frame advance, when I hit the segment VR freezes.

I've attached OpenDCT & Sage logs below.

In normal use I never saw this issue until one night I was recording two sports events on ESPN & ESPN2 and happened to have 3 OTA recordings triggered at 9:59PM, 10:00PM and 10:01PM. That's when I decided to set up my test.

A rare event, though.

I would change the stall detection back to 5 seconds. That's a truly strange issue you're having. I'll need to add more logging to track down the state of the HDHomeRun Prime when the packets stop coming in. The assumption was that the if we stop getting data the device must have been manipulated (rebooted, stopped, etc) outside of OpenDCT, so we just re-tune it and hope for the best. There's no logging that actually tries to get the current state of the device before re-tuning in 0.3, so I'm going to add more of that kind of logging, but I won't be making further changes to the current stable build unless it turns out to be a another nasty bug. I want it to be easy for people to choose between stable and the latest features. I see that some people have found the testing repo beyond the individuals I have pointed there. It's public; I expected that to happen eventually. I'll PM you when a new version is available with the improved logging. That will probably be some time tomorrow.

[HelenWeathers]

Originally Posted by EnterNoEscape

I would change the stall detection back to 5 seconds......

Will do. It seems to be a rare occurance under normal conditions (but I still am behind on watching some recordings made during peak times). I'm glad I'm able to dupliccate it for testing though.

Thanks very much!

[troll5501]

Originally Posted by EnterNoEscape

PES packet size mismatch errors are usually uncorrectable errors in the stream itself. High network traffic for whatever reason can increase this error in my experience. This has happened to me even with a dedicated NIC. The strangest part to me is that the RTP continuity is fine (UDP packets are not being missed), yet the stream quality gets very bad.

Originally Posted by EnterNoEscape

It looks like you're actually missing many UDP packets when you remote in. That's more out of my control. You can try increasing the the value of producer.nio.udp_receive_buffer significantly to try to counteract the effects. Unfortunately UDP does not have any means to recover missed packets, so once you're computer has decided to drop them, they are gone for good.

Thanks for this analysis. I've done more testing and it's looking like I was experiencing two different issues:

1) My Windows 7 test environment was indeed dropping some packets and the VMware performance monitors confirmed it. The OpenDCT logs for this issue looked like this:

WARN  RTPPacketProcessor - Expected frame number xxxx, received frame number yyyy
DEBUG ffmpeg - Continuity check failed for pid xxxx expected y got z
WARN  ffmpeg - PES packet size mismatch

I was able to fix it by increasing the NIC receive buffer in the VM. I noticed this also a few times in XP, but it was very rare.

2) After fixing the above issue I was still seeing occasional corruption in the streams when the CPU spiked. But there were no dropped packets per VMware statistics, and the logs looked similar to the first issue but without any RTP warnings:

DEBUG ffmpeg - Continuity check failed for pid xxxx expected y got z
WARN  ffmpeg - PES packet size mismatch

This was much worse on XP, maybe due to the different kernel scheduling vs Windows 7. I figured out that I could run a "find" in regedit to spike the CPU and it would cause a burst of errors in the OpenDCT logs and stream corruption every time I did it.

Since there were no dropped packets at the network level, I started thinking it was some issue in the application and maybe the app was not able to keep up with the data stream. After some experimenting, I figured out that increasing the consumer.ffmpeg.rw_buffer_size to 262144 completely eliminated the errors/warnings when I spiked the CPU. 32K and 128K helped slightly but 256K seems to have fixed it.

So I'm wondering are there any negative effects to increasing this parameter and does this solution seem reasonable? And should it be a multiple of something (188?) or is 262144 OK?

I will continue testing to see if everything remains stable.

[EnterNoEscape]

It's good to see that you appear to have figured some of these issues out. This may help someone else in a similar situation.

If OpenDCT was having issues keeping up, you would see buffer full errors and I haven't been seeing any of those. I haven't seen any of those either in any of the logs I've seen so far. The primary buffer is 7MB. I've only seen it get choked up when I was trying make it happen. That being said adjusting the rw buffer does help in some cases which means of course that something doesn't like delays, just not the primary buffer.

Your logic is fine with the rw buffer adjustments. The original default well before the first public release was around 10k and it gave me issues in my VM on occasion, so I bumped it up to 20k-ish and the problems went away. I don't know if there are any benefits to this being a multiple of 188, but it doesn't hurt since that's the kind of data we're working with. I was never able to conclusively determine what's the best practice; there may not really be one since this buffer technically could be reading from any video format. I'll just say that if it's working, use it.

There are only two downsides to increasing the rw buffer size. The first is the time until you start streaming live can be negatively impacted. That's because when FFmpeg is reading that's the number of bytes it will always read from the buffer before processing the new data. The other downside is the increased memory usage. At around 256k you're actually using a little over 512k of RAM for the secondary buffers. This is because the read and write buffers are not shared and have additional padding for various reasons added regardless of this value. We aren't talking about anything crazy here, but depending on how many tuners you load it can add up.

Update: I take it back about slower time to live streaming. Your setting actually dropped 100ms off my average detection time. I think its because it reduces the number of times the FFmpeg native process needs to return to the JVM for data. 256k looks like a good compromise since it's a little over 1/3 the size of the smallest amount of data allowed for detection. I tried larger sizes, but the results got a lot worse, so I think you unintentionally found a gem. The only down side that I was able to find with such a large size is if a channel requires more data because we are still missing audio or video it appears to take a little longer than it did before. For that reason I'm going to say this is a very good tweak, but I don't think I'll change the default for future releases.

[troll5501]

Originally Posted by EnterNoEscape

If OpenDCT was having issues keeping up, you would see buffer full errors and I haven't been seeing any of those.

Your setting actually dropped 100ms off my average detection time. I think its because it reduces the number of times the FFmpeg native process needs to return to the JVM for data. 256k looks like a good compromise since it's a little over 1/3 the size of the smallest amount of data allowed for detection.

Thanks very much, I'll keep running with a 256K buffer for now. Glad to hear that it may improve the tuning times. And I don't mind an occasional slower tuning time if it avoids stream corruption. Compared to my STB+HD-PVR, OpenDCT still tunes much faster!

I'm guessing that when the CPU gets busy, a larger buffer size helps because the data can be processed more efficiently by reducing the number of read operations (similar to using a larger block size on disk to reduce IOPS). With the smaller buffer, I don't see any buffer full errors but obviously something is struggling to process the stream correctly (or fast enough) and ffmpeg becomes unhappy.

FYI, I also tried increasing the circular_buffer_size but that only delayed the time between CPU busy (my regedit test) and the start of the ffmpeg warnings.

To summarize, this is everything I've changed so far, and I'm back to using only 2 CPU cores in the VM:

opendct: consumer.ffmpeg.upload_id_enabled=false
opendct: consumer.ffmpeg.rw_buffer_size=262144
opendct: consumer.ffmpeg.min_upload_id_transfer_size=262144 (probably not needed)
Windows: NIC buffer size
  -> for E1000, set "Receive Buffers"=2048
  -> for VMXNET3, set "Small Rx Buffers"=8192

[HelenWeathers]

Originally Posted by EnterNoEscape

I'm going to add more of that kind of logging......I'll PM you when a new version is available with the improved logging.

Completed install and re-ran the test startimg at 14:00. Logs attached.

I was in the room where the HDHRPrime is when the test was run and I noticed that the tuner 0 & 2 leds went out each time an OTA recording stared (14:05, 14:06, 14:07 & 14:08) and came back on a few seconds later.

[EnterNoEscape]

Originally Posted by troll5501

FYI, I also tried increasing the circular_buffer_size but that only delayed the time between CPU busy (my regedit test) and the start of the ffmpeg warnings.

To summarize, this is everything I've changed so far, and I'm back to using only 2 CPU cores in the VM:

opendct: consumer.ffmpeg.upload_id_enabled=false
opendct: consumer.ffmpeg.rw_buffer_size=262144
opendct: consumer.ffmpeg.min_upload_id_transfer_size=262144 (probably not needed)
Windows: NIC buffer size
  -> for E1000, set "Receive Buffers"=2048
  -> for VMXNET3, set "Small Rx Buffers"=8192

Thanks for making the circular buffer larger that kind of test did not occur to me, but if increasing that delays the issue, that could suggest something in the buffer is getting out of sync at high load and the corruption you're seeing is the end result. After taking a quick look at the code, I think you may have uncovered a race condition in the circular buffer. I'll do some more of my own testing, write a few tests to verify my fixes and hopefully have something soon.

You are correct. The minimum transfer size parameter will have no effect since you're not using upload id.

Originally Posted by HelenWeathers

Completed install and re-ran the test startimg at 14:00. Logs attached.

I was in the room where the HDHRPrime is when the test was run and I noticed that the tuner 0 & 2 leds went out each time an OTA recording stared (14:05, 14:06, 14:07 & 14:08) and came back on a few seconds later.

You have a very interesting problem. I saw in the log that when OpenDCT queried the HDHomeRun Prime among the returned values Target: none, Lockkey: none which basically means the Prime turned streaming off. These issues came to be without OpenDCT sending anything to the Prime. You said you saw some of the lights go out. I know that if you have the Silicondust software installed, the software also provides a BDA driver which is what SageTV uses in Windows. It looks like your ATSC cards are using a BDA driver too. If you have the Silicondust software installed, I'm curious if you could try uninstalling it and testing. OpenDCT doesn't require any of that software since it contains a complete Java translation of what their binary does.

This line makes me think the BDA driver is present.

Sat 1/9 13:51:38.393 [main@541b02] Capture device 'HDHomeRun Prime Tuner 13221B33-0' is found in BDA_NETWORK_TUNER, but don't have a BDA_MPEG2_TRANSPORT pin, drop it!

[HelenWeathers]

Originally Posted by EnterNoEscape

I know that if you have the Silicondust software installed, the software also provides a BDA driver which is what SageTV uses in Windows. It looks like your ATSC cards are using a BDA driver too. If you have the Silicondust software installed, I'm curious if you could try uninstalling it and testing. OpenDCT doesn't require any of that software since it contains a complete Java translation of what their binary does.

This line makes me think the BDA driver is present.

Sat 1/9 13:51:38.393 [main@541b02] Capture device 'HDHomeRun Prime Tuner 13221B33-0' is found in BDA_NETWORK_TUNER, but don't have a BDA_MPEG2_TRANSPORT pin, drop it!

I uninstalled the SDust software after setting up the M-card several weeks ago. I suppose it is possible that some residue was left behind but am unsure of how to test. Any ideas?

EDIT: When I check device manager the HDHRPrime shows up twice under other devices & says no drivers are installed for both.

[Telecore]

Originally Posted by EnterNoEscape

It's not you, it's me. We made some logging adjustments in the latest version to get rid of some nuisances and it looks like I introduced a little bit of delay when SageTV is getting PROPERTIES. It's very sensitive to this; it basically just stopped accepting data right in the middle. I'll need to mess around with it a little, but I can't imagine this will take long to fix.

Update: Just so everyone knows, this issue only effects people using the 0.4 versions, not the 0.3 versions that most people should be using right now.

Here's a couple log files that may contain some info. related to the standby / functioning = FALSE problem. I don't see any SageTV log files with anything of interest - I may have to turn on debug logging and get you that later but got some recordings going on for a while - thanks.

[troll5501]

Originally Posted by EnterNoEscape

After taking a quick look at the code, I think you may have uncovered a race condition in the circular buffer. I'll do some more of my own testing, write a few tests to verify my fixes and hopefully have something soon.

Thanks for looking into this. I'll be happy to test any fixes when you are ready.

[EnterNoEscape]

Originally Posted by HelenWeathers

I uninstalled the SDust software after setting up the M-card several weeks ago. I suppose it is possible that some residue was left behind but am unsure of how to test. Any ideas?

EDIT: When I check device manager the HDHRPrime shows up twice under other devices & says no drivers are installed for both.

Other than removing the devices from Device Manager by just right-click uninstall, I can't think of another way to get rid them. Without the accompanying software I'm not sure they are even functional as you said they say no drivers installed. Your situation is a little confusing. I believe there's a way to be more thorough by removing some registry keys, but I'm not sure how comfortable you would be with that approach.

Originally Posted by Telecore

Here's a couple log files that may contain some info. related to the standby / functioning = FALSE problem. I don't see any SageTV log files with anything of interest - I may have to turn on debug logging and get you that later but got some recordings going on for a while - thanks.

The suspend behavior is odd in your logs. It looks like when your computer went into standby, it didn't tell OpenDCT it was planning on doing that. OpenDCT finds out about it after it has already returned from standby. Which Windows version is the computer you can't get to go into standby?

[Telecore]

The OpenDCT standby (functioning=FALSE) problem happens on my Win7 x64 Pro machine running SageTV v7. The other machine, Windows10/SageTV V9 never sleeps for some reason.

[EnterNoEscape]

Sorry if I make people repeat themselves about configuration information. My memory can be less than reliable at times and I do actually make an effort to double-check things before I ask questions, but it's still going to happen.

I think Windows 7 x64 is the most tested platform right now, so I'm extra surprised that it's the one with problems with standby. Anyway, hopefully the latest beta will get you working. I'm not too surprised about Windows 10 with the constant updates. Microsoft has pretty much put everyone on a perpetual beta.

[Telecore]

Not a problem. I tried 0.4.11 late last night, same issue - hopefully there's something useful in the attached log files. Thanks again for working on openDCT!

[EnterNoEscape]

Originally Posted by Telecore

Not a problem. I tried 0.4.11 late last night, same issue - hopefully there's something useful in the attached log files. Thanks again for working on openDCT!

In the same folder that you retrieved opendct.log, there's another folder called archive. Can you get me all of the .gz files dated yesterday (1/10/2016)?

[Telecore]

No problem - attached.

[EnterNoEscape]

I think I see the problem now and I'm very certain I can fix it.

[HelenWeathers]

PROBLEM RESOLVED:

Originally Posted by HelenWeathers

I've run into an issue with OpenDCT. This only happens when recordings on my OTA tuners start while recordings on DCT tuners are in progress. This is with Sage 7 and win 7/32 with 4 OTA
tuners and OpenDCT w HDHR Prine CC tuner. OpenDCT is running on the same machine (my Sage server).

DCT tuner recordings exibited 6-8 second glitches each time one of the OTA tuners kicked in.

Resolution:

Stopped SageTV and OpenDCT services. Uninstalled OpenDCT.

Disabled HDHRTuners in device manager that were showing up under "Other Devices" and were generating errors at startup of drivers not found. (why they were there or how they got there is a mystery)

Went thru registry and located/removed everything related to HDHRPrimes, OpenDCT, SageDCT, Silicondust etc.

Discovered that Windows Media Center was activated so deactivated it under programs & features.

Restarted server, installed OpenDCT, restarted again and let it go thru normal startup and loading of OpenDCT and SageTV services.

Repeated my test recordings twice and everything now works beautifully.

Not sure what the issue was, but am leaning to WMC as the culprit. I usually remove WMC from my Sage servers but somehow this time it got by me.

Thanks for everyone's time & help!!!

[EnterNoEscape]

Wow. You were motivated. Good for you!

Did you go back to the 0.3 or are you still using 0.4? I'm just curious if you're using 0.4 how things are going since you fixed this.

[HelenWeathers]

Originally Posted by EnterNoEscape

Did you go back to the 0.3 or are you still using 0.4? I'm just curious if you're using 0.4 how things are going since you fixed this.

I'm now running 4.11. So far so good. I'll keep running the latest releases to help with testing.