Recordings stop saving data much too early
Added by Steve Miller almost 12 years ago
I am running 3.2.18 on a Pogoplug which talks to a single tuner HDHOMERUN. Thus far, I have not been able to get any recording to record the allotted amount of time. (Note: I have only started using TVH with 3.2, and have never gotten recording to work.) Even a 10 minute recording will fail. After a couple of minutes of saving data to the USB hard drive, it just stops adding more data. The drive is not full, and TVH closes the *.mkv file at the end of the recording time with a "Completed OK" message. During the recording, the time stamps of the *.mkv file quit updating. However, after the "Completed OK", the time stamp jumps to the stop time of the recording. This suggests to me that TVH still has control of the file and its not an issue of writing this file to the hard drive.
I have the HDHOMERUN driver running in another console window. It does not print out any errors or warning, it appears to continue to run as normal. At the end of the recording time, the message "stop writing to dvro" appears in the console of the HDHOMERUN driver. I am assuming that this corresponds to TVH releasing the tuner at the "Completed OK".
I put some print statements in dvr_thread of dvr_rec.c. Right before the switch statement, I print out the type of packet that was received. It starts out with packet type 0x00 which I believe is the streaming data packet. When it fails, it just continues to get packet type 0x03 which I think is the signal strength packet. These 0x03 continue to the end of the recording, then it gets a 0x04 and a 0x07. While, I thought the 0x03 packet type was killing it, I found this was not the case, because suppressing them did not improve anything. Closer monitoring of the initial printout when it is working, show an occasional 0x03 within the large group of 0x00.
Questions:
1. Is there a recommended earlier version of TVH that I should try building to use as a baseline test? Remember this system actually never worked, so I cannot rule out anything. The HDHOMERUN was working with some script based recordings several weeks ago, so I believe that hw is OK.
2. Where does the streaming data from the tuner first enter the TVH software? I believe the problem is upstream of dvr_thread. I can put additional print statements, but I really do not know the program flow. With some rough idea of the data flow, I can use the old "half split" method to get an idea of where its getting into trouble.
Thanks.
----- Steve
Replies (26)
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
OK, I floundered around in the code some more and ended up in dvb_adapter.c in the function dvb_adapter_input_dvr. This function has a while (1) loop that appears to me to be gathering up the data. I put some print statements within this while loop and a print statement immediately after the while loop to see if I am breaking out of the loop.
Attached is a text file that has the while loop with and added print statements and the output from two code runs with these print statements. For clarity, print statements added by me start with "Steveo". I have some additional prints in dvr_rec.c. These let me know when the recording is hosed. "sm_type = 0x3" is a signal strength check. These happen only once a second. If I get a couple of these in a row, without any other printouts, then I know the recording is hosed.
The two sample outputs attached are only the last fragment of printouts. There are way too many prints to include them all.
Based on the printouts, it appears to be getting stuck at the top of the while loop. Apparently, epoll_wait(efd, &ev, 1, -1) keeps returning -1, as I stop getting the "got input" message.
I am out of time for this morning, so I will continue the hunt later. If anyone has insights as to the location and history of epoll_wait, I would greatly appreciate the info.
Thanks.
----- Steve
TVHLOG4.txt (13.8 KB) TVHLOG4.txt |
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
OK, a little googling informed me that epoll_wait() is a Linux kernel function that waits for an IO event. The -1 as the last parameter tells it to wait forever until the event is received. I changed this parameter to 2000, which should wait 2 seconds for said event. Then after this returns with a return code less than 1, I printout the error number. Unfortunately, the error number is 0x0. Trying to convert this to a string gives me the word "SUCCESS". [ Linux kernel version is 3.1.10-13-ARCH]
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
Googling for epoll and hang got me the following hit:
http://www.kernel.org/doc/man-pages/online/pages/man4/epoll.4.html
Lunchtime is over, so I do not have time to decipher this right now. However, the above URL gives an example of how consuming only part of the info from the buffer can hang epoll. At least, that is what I think it says.
---- Steve
RE: Recordings stop saving data much too early - Added by Adam Sutton almost 12 years ago
The mention of epoll() hanging is related to the use of epoll() for true edge triggered polling, this can be useful in special circumstnaces but is not used in TVH. I think the main reason for using epoll() rather than poll() or select() is its easy of use for adding/removing files from the set (though Andreas may have had other reasons).
The fact that epoll_wait() is returning -1 is also enough to tell you nothing is hanging. What would be interesting is knowing what errno is when this occurs (its not currently logged in the code, which is a fault and should probably be fixed).
Adam
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
I did not explain the results well. With the TVH code as written, epoll_wait() does hang. The reason is that the last parameter being a "-1" tells it to wait as long as required for a new IO event. Since it believes that no IO events are seen, it hangs there forever.
I changed the last parameter to 2000 in my code to see what the return code would be and what error number I received. The "2000" should make it wait a maximum of 2000 milliseconds, 2 sec. When I did this, it returned -1 and the error code was 0x0. This error code is meaningless since it means SUCCESS. The man page I saw for epoll_wait stated that an error code would be set even on a timeout. After my printout of the return code and error code, it hits the continue statement on the next line of the TVH code and tries epoll_wait() again. This will again time out after 2 seconds in my test code and print the same return code and error code.
Right now, I have no idea why it believes that no IO events are being received. Perhaps something is broken in the dvb driver of HDHOMERUN. All I know is that HDHOMERUN does not report any errors.
I guess one thing I could try is using the original wait forever code, get it into a broken state and then run out to the utility room where all the HW is installed and yank out the Ethernet cable from the HDHOMERUN, if it sees that event and issues an error message, then it would suggest that the IO event is being skipped somehow.
--- Steve
RE: Recordings stop saving data much too early - Added by Adam Sutton almost 12 years ago
Sorry my mistake, I misread what you typed (I was scanning through a lot of issues ).
Yeah, if that function is getting no data from upstream that would explain everything nicely. But whether its HDHR related or not I'm not sure. I don't think the other user that's reported this is using HDHR? But I'll let him comment.
Adam
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Nope, assuming that was my cue: I'm getting it on an Haupppaaaaguge (never could spell that) DVB-T stick and a TBS Q-Box II DVB-S2 box. No HDR in sight.
I'm connecting by USB2 if that's relevant - I guess the HDR is coming in as an IP stream, though, so I doubt that's an avenue...
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
OK, in my case the reason that it is getting hung in epoll_wait() is that there really is no data available. After my 2 second time out, I attempted to read a few bytes out of the file descriptor "fd". The return code from this read was -1, the array that I passed in was not changed, and the error number was 0xB. This seems to indicate that there is no data.
I then tried closing this file descriptor and reopening. The close and reopen did not produce any errors. However, after being re-opened, there still was no data to be read.
Now, the funny part. If I set up a 10 minute recording, it fails within a minute or so of starting. If I CTRL-C out of TVH and then immediately restart it. Then it sees that there is a pending record and immediately goes back into record mode. For another minute or so, there is plenty of data available to be read. Therefore, it is odd that a restart of TVH could cure the condition if it was something stuck in the kernel dvb driver.
In directory, /dev/dvb/adapter0, I see three files demux0, dvr0, and frontend0. These seem to stick around whether TVH is running or not. However, if I delete dvr0, then TVH will crash and will not restart. I have to exit TVH, stop the usermode portion of the HDHR and then stop the HDHR kernel driver before I can then restart and get it running again.
RE: Recordings stop saving data much too early - Added by Adam Sutton almost 12 years ago
Prof Y - HDHR does come in as an IP stream, but TVH sees it like any other DVB driver as there is some library that talks HDHR over the network and translates this into standard linux DVB api etc.. <- Note: just for info
Steve,
Stopping/Starting TVH could indeed allow problems in the driver to become "unstuck", because there are far more FDs open than just the one you're looking at. At the very least there will also be the frontend one and possibly (depending on version and setup) several demux ones as well. It may well be that the driver has gotten itself into a state that it cannot recover from until ALL device files are closed.
frontend0 - this is the frontend tuner control (it's where we get status info and send tuning commands etc... this will be open at most once within TVR)
dvr0 - this is where the raw PES is received for the subscribed services (and in later version, depending on config, the entire mux). This can be open at most once in TVH.
demux0 - this is where we receive table data that has been extracted from the raw mux stream based on requested filters. This will be open many times, once for each filter (some drivers do have limitations on the number you can open due to HW limits, since that's typically where the filtering takes place. This will not be the case with HDHR).
Messing about with these files, which are essentially the FS interface to your hardware, is a BAD idea and will no doubt result in undesirable behaviour
It sounds to me like the problem you're having is that the HDHR drivers are getting in a mess. Something you could try:
Configuration->Adapters-> (for each HDHR tuner you have):
skip initial scan = on
idle scan = off
close device handle when idle = on
Note: there is a bug in 3.2 which means these settings don't properly take effect on startup, but it probably won't affect what you're about to do.
1. Start TVH with debugging enabled (-s or -d)
2. Start the recording (ensure that you have no other clients accessing TVH that might also subscribe to stuff - XBMC etc...)
3. Wait for recording to actually start (writing to disk)
a. sudo lsof -p $(cat /var/run/tvheadend.pid) | grep /dev/dvb
Note: the above should show you what devices are currently open during recording
4. When the recording stops writing data:
a. Stop the recording
b. sudo lsof -p $(cat /var/run/tvheadend.pid) | grep /dev/dvb
Note: at this point you should hopefully see that all DVB devices are closed (i.e. nothing is listed by the above)
5. Try to restart the recording (or simply use something to view the live stream)
See what happens when you do this, also capture the debug log (either from console or syslog, depending on which you did etc...)
Prof Y,
Can you maybe repeat some of the things Steve has tried to see if you are getting data into the dvb_adapter_input_dvr() routine (in src/dvb/dvb_adapter.c).
Adam
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Adam Bark - do you want me to just pull the latest git master code, or is it safer to go to release/3.2? It's easier to just clone git from my fading memory of building things yourself, but I'm sure I can flounder along to the release branch if desired.
Steve R - I find that the problem is most likely to manifest if I've had a lot of recordings back-to-back... it's almost as if a quick rest resets everything, as if there's a timeout or similar that clears the problem (buffers, closed files, natural housekeeping, garbage collection, whatever). You seem to be getting this reliably with every recording, though, but I don't know if things improve if you leave things settle for a while.
@both - is there a suitable public IP stream that maybe we could both test, see if we can eliminate the drivers?
RE: Recordings stop saving data much too early - Added by Adam Sutton almost 12 years ago
Prof Y,
I'd start by trying 3.2, stuff is changing quite a lot in master so lets stick with something that's more stable.
I personally don't think there is any need to "eliminate" the drivers. I think its pretty much a given that the problem is related in some way to your specific setups (though we may have 2 diff problems causing similar symptons here). Whether its actually the drivers/system or some interaction with TVH is what I'm not sure of at this stage (or more importantly if there is something TVH can do to stop it happening or recover if it does).
If the problem was a more systematic within TVH then I'd be getting screamed at left right and centre and I'm not Personally I record a few things back to back (though admittedly my own gross level of recording is quite light) and I've had no problems.
Another point that would be interesting that I've thus far not asked, what happens when you're watching live streams? Does this problem ever manifest itself in that case? Because all the frontend control and reception code is the same in both cases, it only starts to differ at the point where data is directed to the subscriber.
Adam
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Just to make sure I haven't cocked this up unintentionally, then:
I've...
- Cloned the release branch with
git clone -b release/3.2 https://github.com/tvheadend/tvheadend.git
- Edited
~/tvheadend/src/dvb/dvb_adapter.c
to insert the printf statements as per Steve Miller's attachment - Installed dependencies as per wiki page
./configure
and./make
sudo service tvheadend stop
to shut down my normal tvheadend service- started this one with
/home/xbmc/tvheadend/build.linux/tvheadend -f -u hts -g video -s -d
I had to use the full path, otherwise the daemon would come up but the web interface didn't work - I think it's taking the path-to-binary as the root, so was getting screwed up with /src/...
instead of /home/xbmc/tvheadend/src...
I'm also assuming that I need -d because I won't automatically pick up the DEBUG= statement - so, combined with -s, this should be writing debug statements to syslog.
ps shows that it's started okay:
xbmc@revo:~/tvheadend/src/dvb$ ps -eaf | grep tvh hts 22148 1 6 14:58 ? 00:00:13 /home/xbmc/tvheadend/build.linux/tvheadend -f -u hts -g video -s -d xbmc 22183 20378 0 15:01 pts/0 00:00:00 grep --color=auto tvh xbmc@revo:~/tvheadend/src/dvb$
... so I'll now fill up the recording schedule and see what happens. I appear to have picked up the existing adapter config from /home/hts...
as expected, so all looks well.
The only oddity of note is that I currently have EIT, Freeview, Freesat and an XMLTV combiner enabled because of various missing channels from one or the other. I might have to drop something here, otherwise I'll spend most of my life getting EPG data - but it should only be noise if I don't.
Watch this space, but feel free to wade in if I've done something wrong here. As I said, the last time I wrote a printf statement, pointers were still a pretty neat idea...
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Okay, I'm not getting anything of note... actually, anything at all. I can't imagine that the modified dvb_adapter.c wasn't used when I compiled, so I'm feeing pretty stupid at the moment at the complete lack of any new output...!
Refresh my fading UNIX memory - printf will go to STDOUT, yes? Which will be mapped to /dev/null for a daemon, not automatically to syslog, despite the -s parameter...?
So, I guess I can try 2>&1 or similar with a bit more floundering...
Alternatively, I'll look at the syntax of the tvhlog
call and see if that's more useful. Seems to be:
tvhlog(log_level, "message type", "formatted message with variables", variable_1, variable_2, variable_n)
So I guess I can use something like:
tvhlog(LOG_DEBUG, "wibble", "a string %s and a number %d", string_var, numeric_var)
... or use LOG_NOTICE and it'll write whether I have DEBUG set or not.
As I said, feeling pretty helpless at the moment. That move into management all those years ago did my technical skills no end of harm...! :-)
RE: Recordings stop saving data much too early - Added by Adam Sutton almost 12 years ago
For test/dev/debug purposes much better to simply run TVH locally as yourself. E.g.
- Add yourself to video group (so you can access DVB device)
sudo usermod -a -G video $(whoami)
- Get copy of your current config (replace ~hts accordingly)
sudo cp ~hts/.hts/tvheadend test-conf
- Build/run
./configure
make
./build.linux/tvheadend -d -c test-conf
One day I'll get around to writing this in a wiki article.
Adam
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Thanks, Adam - I'm still trying to use this as my production box at the same time, so I need to ride both horses.
No worries, I've modified the code in dvb_adapters.c and dvr_rec.c with a load of tvhlog() calls, and the daemon is back up and running, recording whatever drivel Channel 5 broadcasts in the next 12 hours or so. Let's see what happens...
EDIT
Good news - it's logging perfectly.
Bad news - it's generating over 3000 messages per second, so I either need to prune the logging somehow or else buy a bigger hard disc and switch off rate limiting on imuxsock :-)
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
Ok, in my case, I believe this is a memory issue with the DVB driver for HDHR. In may actually only be operator error on my part. I am running TVH on a Pogoplug which is a headless NAS type device. It only has 256Meg of RAM. Since I don't have the device fully configured yet, I am running it through multiple SSH sessions via Putty. Since all were logged in as root, I was assuming that they all shared the same memory space as the same user. Now, I suspect that these multiple sessions were eating up more of my RAM. I suspect that each root login is being treated as a separate user called "root". For example, from a SSH connection that is not running TVH, there is no such file as /var/run/tvheadend.pid.
One of my SSH connections was starting and monitoring the output of the DVB driver. The userspace part of the driver is called userhdhomerun. This never printed out any error messages or hinted about anything wrong. However, when I grepped dmesg, I found several page allocation failures. Since I did not know when these occurred. I rebooted and then checked dmesg. It was clean. I started a 10 minute record, and it completed. I checked dmesg and it was again clean. I started another 10 minute record and it failed. I checked dmesg and got:
[ 1722.748912] userhdhomerun: page allocation failure: order:7, mode:0x40d0
Therefore, I believe that the record failures are directly linked to the DVB driver page allocation failures. The root cause of the page allocation failure is not known right now. It may simply be the fact of how I was running the Pogoplug via large numbers (4 or more) SSH connections. It may be a configuration setting within the DVB driver. Or it may be the effect of a memory leak somewhere else in the system.
--- Steve
P.S. The results of running lsof before and after the recording problem occurred gave exactly the same results. There were no differences in the number of type of connections in either snapshot.
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
FYI, a Google search for userhdhomerun:page allocation failure found this forum post:
http://sourceforge.net/projects/dvbhdhomerun/forums/forum/1223414/topic/5046505?message=11184668
Applying this change, seems to have fixed it. I did two 30 minute recordings and several 10 minute recordings without any problems. I would suggest anyone using HDHR to look at adding this config change. What is not covered in the forum posts is that apparently when this page allocation fails, the driver will not crash, TVH will not see it as an error, and you are left with recordings that are too short.
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Steve R - it's with mixed feelings that I say congratulations for finding your problem, since that means it's entirely personal on my system!
I recorded the entire output of Channel 5 last night with no apparent ill-effect (well, other than the 1.3m-line syslog - and the Steven Seagal film they broadcast, that really was uncalled for :-) ).
Sooo... assuming it's personal... I've trashed and recreated my tvheadend setup, and am now recording another day's random output using the normal tvh binary. If that starts to hiccough, I'll switch over to my modified version and see what debug messages I get - now I've started hacking into the code then it's relatively easy to insert various "I'm in this routine!" messages, although working out the code flow is easier said than done.
And I'm also considering a complete rebuild, just to see if that eliminates anything.
RE: Recordings stop saving data much too early - Added by Steve Miller almost 12 years ago
Prof Y,
I would suggest a good inspection of dmesg. Look for any instances referring to the tuner or anything USB related that seems out of place. Then I would suggest making a map of how everything is connected right now. Next, reboot to get a clean version of dmesg and start a recording. Take a small screwdriver and hold it by the blade and use the handle to tap on the USB cable, and attached hub, and power cable to said hub and the tuner itself. Notice if the recording dies or whether dmesg shows any events.
Start a new recording and then when it gets started unplug and reconnect the USB cable to the tuner. Do the messages and symptoms in TVH appear the same or different to the record problem you are having? What does dmesg say about this event?
If the tuner is connected to a USB hub, I would suggest removing the hub and connecting directly if possible. Remember a USB hub is a connection sharing device. Should the hub believe that some other port needs access, it will suspend the tuner while handling the other requests.
Finally, using the hw map, swap to a different USB cable and a different USB port on the computer. If the problem is flaky connections or HW, this may move the problem to a different device in the system.
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Steve R - thanks for the thoughts - I've already swapped things around (and remember that this machine will stop halfway through a recording but then work okay later - so the only realistic movement is heat-related), things are plugged into the motherboard USB ports (not the daughterboard, not a hub), and so on.
But certainly I'll have a think to see if I can systematically find what's happening. It must be something unique to my system... I'd blame the coax cable/signal if it were on one tuner only, but two? Of different technologies? Hmmm.
I might try a total rebuild to the new XBMCBuntu beta or similar - different kernel, different everything. What I'm desperately avoiding is making the switch to Myth or (shudder) one of the Windows back-ends. I think the work Adam and the team are doing here is great for the future of the lightest, easiest backend and I want to stick with that - if it works for me.
I even considered switching TVH to my NAS, but the prospect of trying to compile TBS drivers on that makes me shudder (plus the lack of grunt without swapping that out for a different unit).
Again, thanks for the thoughts, let me sit awhile in uffish thought.
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
Update to this: either trashing my old config or running the new binary against what was left of it (the latter really unlikely) seems to have cured a long-standing issue: I'm now the proud owner of several days' worth of crap from both Dave and Channel 5 with no apparent glitches whatsoever. I recorded it all back-to-back, nothing missed, nothing stopped early.
Sooo... that suggests a config error of some kind. Still strange, though, as I can't see or think of anything that could cause this behaviour unless it's buried deep in how TVH handles the muxes/services/channels. Whether that feeds any thoughts, I'll leave for other people, but for now I can go back to normal.
Thanks for the thoughts, guys. Until the next issue... ;-)
RE: Recordings stop saving data much too early - Added by C E almost 12 years ago
Hi,
Not sure if I have the same issue but I've just switched from running the master GIT tvheadend (on a high power[W] machine) to a lower power ION machine running XBMC with the TVHEADEND addon.
The problem is that on the TVHEADEND 3.2.18 addon all my records start on time and record perfectly, except that after a few minutes (anywhere from 5 mins to 20 mins) the recording just stops. TVHEADEND believes the recording is working fine and stops the recording at the correct time, it just hasn't recording 95% of the movie etc.
I've got the following adapters:
Hardware
Device path:
/dev/dvb/adapter0
Device name:
DiBcom 7000PC
Host connection:
USB (480 Mbit/s)
Hardware
Device path:
/dev/dvb/adapter1
Device name:
Sony CXD2820R
Host connection:
USB (480 Mbit/s)
I've completely trashed the config in the TVHEADEND addon and recreated it, but the issue still seems to be occuring. (I did get one completely perfect recording after the trashing), but still had a few failures.
It maybe just fluke but I have the feeling it is on the PCTV (CXD2820R) adapter which things are failing on, but nothing is reported in the config file.
Ideas?
Thanks,
Chris
RE: Recordings stop saving data much too early - Added by Prof Yaffle almost 12 years ago
I never did get a definitive cause - all I found was that the problem disappeared (in that I haven't had it since) when I trashed the tvheadend config. So that's not anything to do with the XBMC addon, but the server config itself. If you're running ordinary Linux, this will be in /home/hts/.hts/tvheadend, I think - if you're on Openelec, though, I'm not sure where it'll be.
RE: Recordings stop saving data much too early - Added by m 321liftoff over 11 years ago
Did anyone find the source of this behavior? I'm using TVHeadend 3.3.392 on a QNAP connected to a HDHomeRun and am running into the same issue that Steve described in the first post: some recordings complete, while other will be a minute long, or sometimes even shorter. I don't have the skills that Steve does to poke around in the code, but wanted to inform everyone that a different configuration is having the same issue. Let me know if there is something I can do to help! I might try reverting to an older version to see if I have the same behavior.
RE: Recordings stop saving data much too early - Added by Steve Miller over 11 years ago
I suspect the issue is the same one I found. The problem was not actually in TVH. The problem is the HDHomeRun driver. Look at
http://sourceforge.net/projects/dvbhdhomerun/forums/forum/1223414/topic/5046505?message=11184668
I would suggest searching dmesg for page allocation faults. The details can be found in this topic about 10 or so replies from the end.