HDHomeRun: Bad Recordings

[Billy Macdonald <billymacdonald@…>]

I've been troubleshooting some bad recording issues on .25 for the

past few days and haven't been able to figure out the issue. I have two HDHR & one HD Prime. Seven total tuners. Whenever I record more than one or two shows, the logs (with -v record) will output tons of the following messages.

2012-03-01 23:45:16.849449 W [7383/7464] HDHRStreamHandler dtvrecorder.cpp:1301 (ProcessAVTSPacket) - DTVRec(3): A/V PID 0x800 discontinuity detected ((1+1)%16!=6) 0.03%

And the recordings end up in horrible shape. There doesn't seem to be any other mythtv activity around when the errors start/stop (they come in clumps it seems).

So far, I've validated that the cable feed is good, that I can watch all the tuners fine through the HD config GUI, and that I can stream four at a time to my mythtv BE using VLC without a single hiccup. But when I try to record in Myth, it falls apart.

Also, CPU usage is extremely high recording from HDHR devices. I'm recording four tunners and mythbackend is running at 193% (AMD Phenom(tm) II X4 960T Processor).

I upgraded to Fedora 16 hoping for some relief, but it did not help. At this point I've rolled back to .24. I will attempt to upgrade to .25 again when I have some time to investigate further. Please let me know what further data I can provide. I've attached a log from a couple of days ago when I last tested .25.

[danielk]

Does this happen with the latest HDHomeRun firmware? I assume some if it happens with the prime as well; but I want to be sure you are using RTP and not UDP streaming.

[Github]

Refs #10414. Fix HDHomeRun makefile so it can compile firmware update tool.

Branch: master Changeset: d8053e4570260518537fcdafac72c59e3962509c

[Github]

Fixes #10414. Ensure sufficient buffering and sleep longer when there is no data.

The HDHomeRun StreamHandler? depended on a not-well known setting for the buffer size and was using more CPU than it should checking for more data when there was no more data on the wire. This bakes in a reasonable value for the buffer size and sleeps longer after thre is no data.

Branch: master Changeset: 2be3dd91fba8d438cb25d81a1ba9d0d5e8657fb6

[danielk]

This appears not to be fixed by [2be3dd91fba8d438cb25d81a1ba9d0d5e8657fb6], as reported on mailing list.

[Scott <snharris99@…>]

As requested, I am following up from ticket:10430 this does appear to be the same issue I am seeing, apologies for the duplicate submission.

When testing on my laptop (the only 0.25 environment I now have due to this issue), my CPU usage hangs around 30% - 40% on both cores while recording (with or without simultaneous playback). The CPU usage does not appear to vary much with additional recordings (i.e. 40% with one recording, 40% with 3 recordings). I actually can't test more than 3 recordings because this issue is so severe that simultaneous recordings > 2 or 3 almost always fail.

I have 3 HDHomeRuns (non Primes). Have tried with both OTA and Comcast signals on two different setups (specs posted in ticket:10430).

I am not quite sure how to gather logs yet with the new logging changes in 0.25, but if you would like me to gather anything, I am quite happy to if you point me in the right direction.

[Scott <snharris99@…>]

One additional followup, I am running the most current firmware (20120128) on all 3 HdHomeRun? units.

[Scott <snharris99@…>]

I need to correct some previously reported information. Further testing reveals that my CPU usage does indeed increase with each simultaneous recording. The reason I thought otherwise was because when I try to start a 3rd recording, the output is so poor, that it is typically failing almost immediately so I didn't see the CPU usage increase. I finally got a 3rd recording to go for a few minutes before failing and CPU usage rises to 80% - 90% on both cores. A fourth recording is an impossibility at this point.

[Github]

Refs #10414. Lower DTVRecorder CPU use.

David Engel narrowed down increase CPU usage to some QDateTime usage. This uses some counters to avoid updating the value quite so often.

Branch: master Changeset: 2f6c4eec57121a652e60c8e426e5bec5250a9076

[Github]

Refs #10414. Lower HDHomeRun recorder CPU usage a tiny bit more.

Branch: master Changeset: 0542a100237dd26bcbc60212c443f4619586f15b

[danielk]

It appears that CPU usage was the culprit and that [2f6c4eec5] and [0542a100] have addressed the issue.

[spartacus06@…]

I had the same issue with multiple recordings from a dual tuner HDHomeRun with 0.25. Had no problem with 0.24. Running mythbuntu 12.04. Added the mythbuntu 0.25 update PPA with:

sudo add-apt-repository ppa:mythbuntu/0.25
sudo apt-get update
sudo apt-get install mythbackend

After that:

$ mythbackend --version
Please attach all output as a file in bug reports.
MythTV Version : v0.25.1-2-g648f0ae
MythTV Branch : fixes/0.25
Network Protocol : 72
Library API : 0.25.20120506-1
...

Even though I didn't see high CPU (23% from top/vmstat) or disk utilization (8% from iostat -x) before, the issue is resolved by the update.

I did notice that the after the update, the number of context switches and CPU utilization have been cut in half.

[spartacus06@…]

Ok, scratch all of that. I'm a moron and didn't really have two recordings going. I'm still seeing this issue and found out that the discontinuity is due to UDP packet receive errors as reported by netstat -s --udp

$ mythbackend --version
Please attach all output as a file in bug reports.
MythTV Version : v0.25.1-39-geffb32b
MythTV Branch : fixes/0.25
Network Protocol : 72
Library API : 0.25.20120506-1
QT Version : 4.8.1

Each burst of UDP receive errors corresponds to a group of discontinuity warnings

Udp:
    977748 packets received
    40 packets to unknown port received.
    3134 packet receive errors <---
    647 packets sent

2012-06-19 23:02:48.996735 W  DTVRec(2): A/V PID 0x31 discontinuity detected ((10+1)%16!=9)  0.04%
2012-06-19 23:02:48.996989 W  DTVRec(1): A/V PID 0x31 discontinuity detected ((10+1)%16!=9)  0.01%
2012-06-19 23:02:49.429389 I  RingBuf(/var/lib/mythtv/livetv/1421_20120619230237.mpg): Waited 0.2 seconds for data 
			to become available... 65536 < 393216
2012-06-19 23:02:49.434635 W  DTVRec(2): A/V PID 0x31 discontinuity detected ((8+1)%16!=0)  0.04%
2012-06-19 23:02:49.434705 W  DTVRec(2): A/V PID 0x34 discontinuity detected ((2+1)%16!=4)  0.04%

Not sure if the socket receive buffer is filling up or what... but it's still a problem.

I'm doing two recordings and playing back another with a frontend. CPU stats for mythbackend system in this state are 5% user, 20% sys, 75% idle, ~1% wait with 8% wait peak, 3202 int/s, 6613 cs/s. So neither CPU nor disk saturation is the issue.

System baseline with mythbackend running is 100% idle, 40 int/s, 65 cs/s.

$ hdhomerun_config XXXX get /sys/model
hdhomerun3_atsc
$ hdhomerun_config XXXX get /sys/version
20120405

[spartacus06@…]

Watching /proc/net/udp confirms that packets are being dropped on the sockets receiving data from the hdhomerun, and the drops correspond to the discontinuity warnings.

Every 0.5s: cat /proc/net/udp                                                                           Wed Jun 20 00:06:15 2012

  sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode ref pointer drops
   67: FFFFFFFF:076C 00000000:0000 07 00000000:00000000 00:00000000 00000000  1000        0 41198 2 0000000000000000 0
   67: FAFFFFEF:076C 00000000:0000 07 00000000:00000000 00:00000000 00000000  1000        0 41196 2 0000000000000000 0
  103: 00000000:E590 00000000:0000 07 00000000:00000000 00:00000000 00000000  1000        0 41237 2 0000000000000000 846
  108: 00000000:1995 00000000:0000 07 00000000:00000000 00:00000000 00000000  1000        0 41176 2 0000000000000000 0
  268: 0100007F:0035 00000000:0000 07 00000000:00000000 00:00000000 00000000     0        0 11671 2 0000000000000000 0
  283: 00000000:0044 00000000:0000 07 00000000:00000000 00:00000000 00000000     0        0 9401 2 0000000000000000 0
  338: 8101A8C0:007B 00000000:0000 07 00000000:00000000 00:00000000 00000000     0        0 10983 2 0000000000000000 0
  338: 0100007F:007B 00000000:0000 07 00000000:00000000 00:00000000 00000000     0        0 10982 2 0000000000000000 0
  338: 00000000:007B 00000000:0000 07 00000000:00000000 00:00000000 00000000     0        0 10975 2 0000000000000000 0
  443: 00000000:88E4 00000000:0000 07 00000000:00000000 00:00000000 00000000  1000        0 40124 2 0000000000000000 1035
  448: 00000000:14E9 00000000:0000 07 00000000:00000000 00:00000000 00000000   107        0 9312 2 0000000000000000 0
  465: 00000000:9CFA 00000000:0000 07 00000000:00000000 00:00000000 00000000   107        0 9314 2 0000000000000000 0

[danielk]

spartacus06, can you try decreasing the usleep() on hdhrstreamhandler.cpp line 155. Try 5000 first, if that doesn't work try 2500, if it does try 10000, etc.

[spartacus06@…]

I can try that.

I have compensated for the problem by doing two things:

1) Increasing my socket receive buffer to 2MB using the method described on the SiliconDust? website under "Packet Loss" (​http://www.silicondust.com/support/hdhomerun/instructions/mythtv/)

2) Rebased libmythhdhomerun against the latest source from SiliconDust? (20120405 vs 20110925 in-tree)

However, I didn't need to do this in 0.24, so this "fix" is more of a compensation.

I'll try different usleep() durations and get back to you.

[toby@…]

Any updates on this, it seems to be affecting a growing number of users as people begin to upgrade to Ubuntu 12.04. I was running Ubuntu 11.12 with latest Myth 0.25 and didn't have the problem, but the upgrade to 12.04 has caused the exact symptoms above.

I have also raised a ticket with Silicon dust to see if they can help: ​https://www.silicondust.com/support/tickets/default.asp?16187_q1i5cq7n5v12brpn

[cflynt@…]

I honestly have no idea if my issues are the same as the others here, but as well have had nothing but trouble since upgrading to Ubuntu 12.04/MythTV 0.25.1 and I use HDHomeRun Prime and regular HDHomeRun tuners. Video is choppy at times, never crashes just have artifacts every so many seconds or so. I have ran the PVR Frontend on XBMC and verified it is working just fine on the same computer. So it definitely has something to do with Myth in some way. I have thought about trying to downgrade Ubuntu to the previous release but still run 0.25 to see if that works any better, just haven't had the time yet. So definitely looking for any insight anyone might have.

Thanks

[danielk]

Please! no more me too's.

If someone experiencing this problem can test the usleep() change this will add something. Any more me too's and we'll be forced to lock the ticket. No response on the usleep() question in the next 24 hours and we'll have to close the ticket for no response in 7 days.

[spartacus06@…]

I reverted to the stock 0.25 libmythhdhomerun and restored my socket receive buffer to 128k (the default). I tried 5000 and still observed UDP packet loss with discontinuity error during recording. I tried 2500 after that with no difference. This doesn't seem to be having any effect.

[danielk]

The default receive buffer is set to 1MB not 128k in hdhomerun_video.c@103

Are you saying running this:

sysctl -w net.core.rmem_max=1048576

Fixes the problem for you?

If that is the case there isn't much we can do other than maybe adding something like that to the sample init.d file and hoping distro's pick it up.

[spartacus06@…]

I don't imagine the setsockopt() on 103 has any effect since it exceeds the default rmem_max:

(on an Ubuntu 12.04 with default networking tunables) $ sysctl net.core.rmem_max net.core.rmem_max = 131071

The return value for setsockopt() is not checked, but IIUC, it probably isn't setting the receive buffer to 1MB.

[David Walker <David@…>]

Replying to danielk:

The default receive buffer is set to 1MB not 128k in hdhomerun_video.c@103

Are you saying running this:

sysctl -w net.core.rmem_max=1048576

Fixes the problem for you?

If that is the case there isn't much we can do other than maybe adding something like that to the sample init.d file and hoping distro's pick it up.

A quick test (three simultaneous half-hour recordings) shows great improvement on my openSUSE 12.1 system, using the most current MythTV from Packman. Prior to setting net.core.rmem_max=1048576, I would lose several minutes of the recordings with this test. After setting it, I didn't notice any loss.

Here are some specifics of what I'm running:

dhwalker> mythbackend --version
Please attach all output as a file in bug reports.
MythTV Version : v0.25.1
MythTV Branch : 
Network Protocol : 72
Library API : 0.25.20120506-1
QT Version : 4.7.4
Options compiled in:
 linux release use_hidesyms using_alsa using_jack using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_dvb using_firewire using_frontend using_hdhomerun using_ceton using_hdpvr using_iptv using_ivtv using_joystick_menu using_libcrypto using_libdns_sd using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl_video using_qtwebkit using_qtscript using_qtdbus using_v4l2 using_x11 using_xrandr using_xv using_bindings_perl using_bindings_python using_bindings_php using_mythtranscode using_opengl using_vaapi using_vdpau using_ffmpeg_threads using_live using_mheg using_libass using_libxml2

> uname -a
Linux server 3.1.10-1.16-default #1 SMP Wed Jun 27 05:21:40 UTC 2012 (d016078) i586 i586 i386 GNU/Linux

> sysctl net.core.rmem_max
net.core.rmem_max = 1048576

[David Walker <David@…>]

Spoke too soon. While I think setting net.core.rmem_max to 1MB helped, I'm still losing several minutes from half-hour to hour recordings. Upgrading the libmythhdhomerun source takes more work, but I'll do it over the weekend unless someone tells me that it's not really a useful fix.

[spartacus06@…]

David, I can save you a little trouble. I've pushed my branch that syncs libmythhdhomerun with libhdhomerun version 20120405 from SiliconDust?.

​https://github.com/spartacus06/mythtv/tree/hdhdrfix

I haven't taken this fix out to see if only increasing the receive buffer fixes my issue, but I do know that the two of them together fix it for me.

[David Walker <David@…>]

I've compiled a new mythbackend with the 20120405 version of libhdhomerun and ran it with net.core.rmem_max = 1048576. This improved things, but it was only a compensation, as spartacus06 said. Mythbackend's log still reported gaps in recorded programs.

While waiting for compiles, though, I did some packet traces with tcpdump and noticed something pretty suspicious. While a recording is in progress, there are long, uninterrupted strings of 1328-byte UDP packets, as expected. A few seconds before the start of a recording gap, though, the HDHomeRun Prime starts sending ARP requests for the MythTV server once a second. The server responds to each of the ARP requests. After a few seconds, the UDP stream stops, causing the recording gap. While the UDP stream stops, the once-a-second ARP requests continue. I'll attach a tcpdump output file (tcp.log.gz) showing this behavior; I've edited long runs of the UDP packets out, as you will see in the file.

I could see that the ARP requests stopped eventually, and I had a hunch that they stopped when the HDHomeRun Prime received a unicast packet from the MythTV server, so I tried running

ping -q -n <HDHomeRun Prime address>

from the server to generate a once-a-second stream of unicast ping packets. I scheduled several recordings, and no gaps! Then I reverted to the Packman version of mythbackend and the standard default for net.core.rmem_max (114688), but left the ping running. Still no recordings gaps. The once-per-second ARP requests still occur, but the pings seem to keep the UDP stream going.

So, I think the HDHomeRun Prime has an issue. It may be aggravated by something that MythTV is doing, but it looks like a bug in the HDHomeRun network code to me.

Is someone from SiliconDust? following this? Is this known behavior?

[David Walker <David@…>]

tcpdump out showing unusual ARP behavior by HDHomeRun Prime

[Gary Buhrmaster <gary.buhrmaster@…>]

Replying to David Walker <David@…>: ....

So, I think the HDHomeRun Prime has an issue. It may be aggravated by something that MythTV is doing, but it looks like a bug in the HDHomeRun network code to me.

This would be a completely different issue/bug that the two others that Danielk has addressed (excessive cpu usage (in general), and not keeping up with the stream (the usleep fix)). Commingling issues/bugs make tickets impossible to follow (or resolve).

There are numerous debugging recommendations that I can suggest for this new issue, but those should be taken to the discussions lists, and this ticket should be able to be resolved for the bug(s) it fixes.

[David Walker <David@…>]

My apologies, Gary; I had gotten focused on the issues that spartacus06 raised. I'll move my comments to SiliconDust?, as the strange behavior is in the HDHomeRun Prime, not MythTV.

[danielk]

Ok, this may be controversial but I'm going to close this.

The main issue appears to be that the Ubuntu 12.04 rbuf_max needs to be increased for libmythhdhomerun to get the level of buffering it requires. The usleep() change should be unnecessary with the greater buffering in the kernel and is a band-aid anyway.

The HDHomeRun Prime issues and the libhdhomerun resync should get their own separate tickets.

I'm resolving this as fixed rather than upstream because there was a MythTV issue (excessive CPU usage) that was fixed.