Modify
Warning Please read the Ticket HowTo before creating or commenting on a ticket. Failure to do so may cause your ticket to be rejected or result in a slower response.

Opened 2 years ago

Closed 21 months ago

#10414 closed Bug Report - General (Fixed)

HDHomeRun: Bad Recordings

Reported by: Billy Macdonald <billymacdonald@…> Owned by: danielk
Priority: minor Milestone: 0.26
Component: MythTV - Recording Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

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.

Attachments (2)

mythbackend.20120302000601.1684.log.gz (112.4 KB) - added by Billy Macdonald <billymacdonald@…> 2 years ago.
tcp.log.gz (577 bytes) - added by David Walker <David@…> 21 months ago.
tcpdump out showing unusual ARP behavior by HDHomeRun Prime

Download all attachments as: .zip

Change History (30)

Changed 2 years ago by Billy Macdonald <billymacdonald@…>

comment:1 Changed 2 years ago by danielk

  • Summary changed from Bad Recordings - Choppy Playback to HDHomeRun: Bad Recordings

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.

comment:2 Changed 2 years ago by Github

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

Branch: master
Changeset: d8053e4570260518537fcdafac72c59e3962509c

comment:3 Changed 2 years ago by Github

  • Milestone changed from unknown to 0.25
  • Resolution set to fixed
  • Status changed from new to closed

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

comment:4 Changed 2 years ago by danielk

  • Resolution fixed deleted
  • Status changed from closed to new

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

comment:5 Changed 2 years ago by 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.

comment:6 Changed 2 years ago by Scott <snharris99@…>

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

comment:7 Changed 2 years ago by 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.

comment:8 Changed 2 years ago by 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

comment:9 Changed 2 years ago by Github

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

Branch: master
Changeset: 0542a100237dd26bcbc60212c443f4619586f15b

comment:10 Changed 2 years ago by danielk

  • Resolution set to Fixed
  • Status changed from new to closed

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

comment:11 Changed 23 months ago by 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.

comment:12 Changed 22 months ago by 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

comment:13 Changed 22 months ago by spartacus06@…

  • Resolution Fixed deleted
  • Status changed from closed to new

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

comment:14 Changed 22 months ago by danielk

  • Milestone changed from 0.25 to 0.26
  • Status changed from new to accepted
  • Version changed from Unspecified to Master Head

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.

comment:15 Changed 22 months ago by 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.

comment:16 Changed 22 months ago by 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

comment:17 Changed 22 months ago by 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

comment:18 Changed 22 months ago by 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.

comment:19 Changed 22 months ago by 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.

comment:20 follow-up: Changed 21 months ago by 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.

comment:21 Changed 21 months ago by 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.

comment:22 in reply to: ↑ 20 Changed 21 months ago by 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

comment:23 Changed 21 months ago by 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.

comment:24 Changed 21 months ago by 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.

comment:25 follow-up: Changed 21 months ago by 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?

Changed 21 months ago by David Walker <David@…>

tcpdump out showing unusual ARP behavior by HDHomeRun Prime

comment:26 in reply to: ↑ 25 Changed 21 months ago by 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.

comment:27 Changed 21 months ago by 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.

comment:28 Changed 21 months ago by danielk

  • Resolution set to Fixed
  • Status changed from accepted to closed

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.

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'new'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.