[IanPH]

I don't use "On the fly" recordings often, but yesterday I was so tired I couldn't finish watching the show. So I pressed the record button and I noticed a popup in the lower right of the screen that the show was scheduled. No problem up to that point.

But then the video started to stutter and stop while audio was still running. XBMC suddenly ran very slow.

This was on my OpenELEC Gotham nightly HTPC (25-jan-2014). Only minutes ago I was able to reproduce the exact same "bug" on my Windows machine with XBMC Gotham Nightly of 21-jan-2014.

I guess the bug is XBMC related but wanted to ask if any of you have the same problem with "On-the-fly" recordings.

Then an idea. I noticed that an "On-the-fly" recording is done by ServerWMC itself. Could it be possible to let ServerWMC directly schedule the recording in WMC itself?

I'm not sure if this a bug or standard behaviour, but the recording I did "On-the-fly" had no meta data. When ServerWMC schedules the recording directly in WMC (like for instance Remote Patato does, which I use the schedule recordings when I'm from home), WMC will save (and handle) the metadata of that recording to the wtv file.

[krustyreturns]

Ian,

The instant recording thing doesn't cause that problem for me, and it really shouldn't because the only change when instant recordings is on is that a hard link to the recording file is made in the recTV folder. So I am curious what is happening on your setup. Since you can reproduce the problem we should be able to figure it out. Can you start swmc and start an instant record of a live stream, and when you see the problems save the log file? If you do, post a link to it here.

Also, did the final wtv playback smoothly?

The metadata should have been written out when the recording stopped, it can't be written before (same with when wmc does is). Did you abort the end of the recording once you started having problems?

It is possible to just have the rec serviced do the recording, but due to some weirdness it will kill the live-tv stream you are watching when it does.

[IanPH]

I've just installed the very last Win32 Gotham Nightly (Compiled Feb 5 2014) to test it again. And again as soon as I pressed record and the show scheduling was confirmed it started to stutter and stop.

The recording itself played fine. No problem at all!

Actually about the metadata, I was in error, I'm sorry. The recording did have metadata!

Here's the a fresh log file I created from start of the ServerWMC service till the moment I closed XBMC (and ofcource the tuning and direct recording in between)

ServerWMC-XBMCStutter.zip

I also added a small screencapture video of the action (not the action that belongs to the log above though). ServerWMC-XBMCStutter.WMV

At 0:45 I pressed the record button followed by the confirmation popup a second later and immediately thereafter the video slowed and halted.
At 1:10 I select channel 2 which starts to play few seconds later, but as choppy as channel 1 was.
Then on 1:31 after going fullscreen I stopped the channel just to start the same channel again at 1:37 where it now start to play normally again.

[scarecrow420]

This is quite interesting as krusty says, performing an "instant record" is really not any different to watching a live stream. Because the channel you are watching is arleady being recorded and remuxed, we basically just hardlink the existing file into the recordings directory, so when the live stream finishes and the live file is deleted, the hardlink keeps the reference of that file in the recordings folder. You wouldnt expect hardlinking a file to really cause any issues.

What I do notice from your log is that right when you do the instant record, a GetRecordings call is triggered. This call took 4.5 seconds which isnt that long really but stood out to me. I also noticed that earlier on when loading the data the first time, the GetRecordings call completed in 2.9 seconds. Not a huge difference but something I noticed. Now I know that when we get recordings we do scrape them for metadata so potentially this could be a hit on the filesystem - basically Im wondering whether the triggred GetRecordings call (which is seen to take longer than an earlier call) is impacting the performance of the WTV recording or TS remuxing.

Now you said the WTV file recording plays back just fine afterwards, but what about the remuxed TS file of the live stream? You might have to uncheck the debug option to "delete temporary stream files" so it isnt cleaned up. It would be interesting if the TS had stutters/playback problems or not. Note that there is nothing in the log to indicate any file system slow downs or trouble in the remuxer so it's a bit of a leap when the only possible clue is the GetRecordings call happening right at this time and appearing to take longer than the previous GetRecordings call.

Can you give a rundown of the serverWMC machine specs and storage setup for recorded TV?

There is also an option in the XML config file "UseMetaDataForRecordings" that you could turn off to see if it made any difference to the GetRecordings call.

[IanPH]

My server is an AMD based setup with an Athlon X4 605 (2,3GHz quadcore) and 8GB memory.
The bootdisk is a 120GB SDD and the storage is a RAID5 setup with 4 disks of 2GB. This is where the Recorded TV is going to.

The partition for Recorded TV is 1TB with 400GB free space.

It's OS is Windows 7 x64 SP1 and I use DVBLogic TVSource with 4 sat tuners configured in Windows Media Center.

At the moment WMC has 133 scheduled recordings (I have a lot of timers for various programs), 105 active channels with a total of about 17000 EPG entries.

The strangest thing is, when I first press "STOP" in XBMC and directly select another TV channel to watch the stutter is gone.

Yet if I do NOT press "STOP" first and just select another channel to watch, the stutter continues on the newly open channel!

And all this time the "On the fly" recording goes on without any problem.

[krustyreturns]

Have you seen this problem with Frodo? Because in this thread:

http://forum.xbmc.org/showthread.php?tid=182847&page=5

it was reported some strange behavior that only occurs with the newer gothams. The two problems are starting to sound similar. If you don't want to switch back to frodo, I have been using this gotham nightly (if you can still get it):

XBMCSetup-20131118-0018656-master.exe

here is the bug ticket:
http://trac.xbmc.org/ticket/14849

[IanPH]

I just downloaded XBMCSetup-20131118-0018656-master.exe and installed it. With this version I get the stutter video bug for WTV files and Live TV which was mentioned in this bug ticket:
http://trac.xbmc.org/ticket/14622

But is does not halt or seems influenced in any other way when starting an "On the fly" recording!

As I said in my first post, I believe the bug is XBMC related.

I also have a problem (in either Win32, OpenELEC and Android XBMC) where only sometimes(!) after some random time, this very same video stutter/stop occurs suddenly while watching Live TV. And also in that case, it can only be solved by stopping and restarting a TV channel. Quite simular as the post you just mentioned.

I will download newer nightlies and check at which nightly the problem starts to surface.

[krustyreturns]

Good info Ian! If you can find the nightly where the problem starts, that would be very helpful. It will be interesting if the nightly where the stutter stops, is also when the on-the-fly problem starts.

[IanPH]

I just finished testing a total of 22 nightlies and found out the bugger was introduced from XBMCSetup-20140106-c4251c3-master.exe to XBMCSetup-20140109-3751d14-label-settings-fixup.exe.

Every version before XBMCSetup-20140109-3751d14-label-settings-fixup.exe does have a slight reaction to the start of an "On the fly" recording in the form of a second of artifacts but then continues to play without further problems.

From XBMCSetup-20140109-3751d14-label-settings-fixup.exe and later it simply almost stops playing and the the menu's even get sluggish.

My thought is that the creation of the file hardlink causes a tiny corruption in the stream which is recoverably with the older versions and has only the artifacts as a small side-effect. But something changed in XBMCSetup-20140109-3751d14-label-settings-fixup.exe and later which makes it more vulnarable to corruption in the stream. That might also explain why this same effect sometimes happen during Live TV as data corruption (atleast with my satellite setup) is quite common.

[krustyreturns]

Great work!

I also typically see a slight stream pause when I start an instant recording. It might not be due to hard link creation, it could also be a call we make to the rec service to see if there are any conflicts with the new recording.

I hesitate to ask, but could you test one more thing? Since I am in the US I don't see the stutter problem (http://trac.xbmc.org/ticket/14622). Is this also the rev that fixed the stutter problem?

[IanPH]

No problem. I tested a few builds again and the stutter problem (http://trac.xbmc.org/ticket/14622) was fixed in:

XBMCSetup-20131204-24bc3c5-master.exe

Yet a few builds before that a bug was introduced which caused the PVR system not to load EPG data from the client.

That bug was fixed in:

XBMCSetup-20131213-7e22dc9-master.exe

Now if only I knew how to add a ticket to the XBMC bugtracker for this issue.

[krustyreturns]

I saw that you added your experimental results to this ticket (http://trac.xbmc.org/ticket/14849). I think that's good enough.

I am relieved that whatever is causing this problem is - likely - not related to the stutter fix!

Thanks again Ian.

[IanPH]

Just to let you know, the XBMCSetup-20140225-0c04283-master.exe (Windows version, have not tested other versions yet) seems to fix the problem described in this thread.

Unfortunately XBMCSetup-20140226-d5fa138-master.exe and XBMCSetup-20140228-3ada898-master.exe break WMC. The channel logo's aren't loaded and when starting a channel it says "Working" for a few seconds and then does nothing. The ServerWMC log shows that XBMC signals error opening stream and therefore closes it.

Code:

2014-03-01 08:39:22.337    Received client request: IAN|OpenLiveStream|743604|0|5|RTL5 HD
2014-03-01 08:39:22.337    OpenLiveStream> -----------------start------------------------
2014-03-01 08:39:22.337    OpenLiveStream> client: IAN requesting live stream
2014-03-01 08:39:22.347    StreamProc> live-tv started
2014-03-01 08:39:22.370    SetChannel> Tuner: DVBLink PBDA Tuner #8 / 164e3c85-a4e2-438b-b3d6-f8b4e1772036
2014-03-01 08:39:22.370    SetChannel> > Digital: True
2014-03-01 08:39:22.370    SetChannel> > Encrypted: False
2014-03-01 08:39:22.373    SetChannel> > RecorderInfo found: True
2014-03-01 08:39:22.376    SetChannel > busy: False, client: none
2014-03-01 08:39:22.377    SetChannel> > tuner is available  => stopping search
2014-03-01 08:39:22.377    SetChannel> Recorder Content Protection: PROT_COPY_FREE
2014-03-01 08:39:22.380    SetChannel> Recorder acquired: True
2014-03-01 08:39:22.383    SetChannel> TuneRequest set
2014-03-01 08:39:22.562    StreamProc> wtv recording started in 0,21 sec
2014-03-01 08:39:22.562    StreamProc> stream output file: LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.ts
2014-03-01 08:39:22.564    StreamProc> started remux thread: 'RTL5 HD-5: 743604'
2014-03-01 08:39:22.704    Remux::FindDescriptors> Scanning wtv for streams...
2014-03-01 08:39:25.741    Parse> Guid: 0 took 3,04 sec, it was attempted 1503 times
2014-03-01 08:39:27.837    Parse> Last number of attempts for Guid header was large: 1031
2014-03-01 08:39:30.104    Parse> Descriptor pass done, using 738 guids in 4,36 sec
2014-03-01 08:39:30.104    Parse> Unknown Guid summary: 1 instances of 1 unique unknown guids encountered
2014-03-01 08:39:30.104     >  63 36 EB FE A1 7E D9 11 83 08 00 07 E9 5E AD 8D {feeb3663-7ea1-11d9-8308-0007e95ead8d}
2014-03-01 08:39:30.104    Parse> Total Descriptor parse time: 7,40 sec
2014-03-01 08:39:30.104    Pass 'Descriptor':
2014-03-01 08:39:30.104     >  WtvToPesDemuxer::Parse> total guid headers processed: 738
2014-03-01 08:39:30.104     >  WtvToPesDemuxer::Parse> total data packets processed: 117
2014-03-01 08:39:30.178    Remux::FindDescriptors> wtv scanned (7,47 sec), Streams found:
2014-03-01 08:39:30.178     >  Audio: ID:35 (dut) AC3 5.1 48000 Hz 384 kb/s
2014-03-01 08:39:30.178     >  Video: ID:36 AVC High-4.0 1920x1080i fps: 25
2014-03-01 08:39:30.178     >  Other: ID:37 MS TV Caption
2014-03-01 08:39:30.178    Remux::FindDescriptors> Output streams:
2014-03-01 08:39:30.178     >  Audio: ID:35 (dut) AC3 5.1 48000 Hz 384 kb/s
2014-03-01 08:39:30.178     >  Video: ID:36 AVC High-4.0 1920x1080i fps: 25
2014-03-01 08:39:30.194    StreamProc> 'ts' file created, size: 32.768 in 7,63 sec
2014-03-01 08:39:30.194    StreamProc> total time: 7,85 sec
2014-03-01 08:39:30.210    OpenLiveStream> stream path returned to client: \\192.168.2.1\Recorded TV\TempSWMC\LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.ts
2014-03-01 08:39:30.210    OpenLiveStream> -----------------done-------------------------
2014-03-01 08:39:30.210    Finished request OpenLiveStream in 7,87s
2014-03-01 08:39:30.214    Received client request: IAN|StreamStartError|\\192.168.2.1\Recorded TV\TempSWMC\LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.ts
2014-03-01 08:39:30.214    StreamStartError> client 'IAN' reports error opening stream, will close stream down
2014-03-01 08:39:30.214    StreamStartError> client 'IAN' path to stream file: '\\192.168.2.1\Recorded TV\TempSWMC\LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.ts'
2014-03-01 08:39:30.214    StreamStartError> client 'IAN' calling CloseStream
2014-03-01 08:39:30.223    Pass 'mux2ts':
2014-03-01 08:39:30.223     >  WtvToPesDemuxer::Parse> total guid headers processed: 935
2014-03-01 08:39:30.223     >  WtvToPesDemuxer::Parse> total data packets processed: 149
2014-03-01 08:39:30.229    Remux> ENDED, >>>>>>>>>> Run Time: 0,00 min <<<<<<<<<<
2014-03-01 08:39:30.234    StreamProc::Close> remux stopped successfully
2014-03-01 08:39:30.234    RecordToWTV::Close> isPassive is False => COM recorder will be stopped
2014-03-01 08:39:30.489    StreamProc::Close> wtv closed successfully
2014-03-01 08:39:30.572    StreamProc::Close> wtv file size: 1.048.576
2014-03-01 08:39:30.573    StreamProc::Close> file deleted: G:\Recorded TV\TempSWMC\LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.wtv
2014-03-01 08:39:30.623    StreamProc::Close> ts file size: 655.360
2014-03-01 08:39:30.624    StreamProc::Close> file deleted: G:\Recorded TV\TempSWMC\LiveTV_IAN_DVB-T_5_2014_03_01_08_39_22.ts
2014-03-01 08:39:30.624    StreamProc::Close> closed in 0,41 sec
2014-03-01 08:39:30.624    Close> closed stream for client: IAN
2014-03-01 08:39:30.626    Finished request StreamStartError in 0,41s

I think this is another XBMC bug, not something caused by ServerWMC/WMC.PVR

***EDIT***: I just downloaded and checked OpenELEC Gotham build nightly (OpenELEC-Generic.x86_64-devel-20140228232008-r17833-gd7825fd.tar) and this works perfectly. It does not stutter (yeah, only a brief hick-up but nothing more) and unlike the Win32 build, Live TV and channel logo's are working.

[scarecrow420]

Do you have an XBMC log of this?

So "IAN" is your ServerWMC PC also with a local XBMC client? It is reporting it is unable to access G:\Recorded TV\TempSWMC for the live stream, and also that is where the channel logos are stored. If it wasnt for the fact that it's a local drive and not a remote client, you would almost think that it's just a permission issue

[krustyreturns]

That's great news that the playback problem in gotham might be solved - hopefully this new problem is just an unstable nightly. I agree with scarecrow that it does look like the rec folder is either down or not accessible. Thanks for staying on top of this Ian.