Help with slow tuning (1 Viewer)

[octessence]

I am trying to find out why it takes my HTPC so long to tune channels. When I switch on TV mode it takes around 15 seconds and to switch channels (all FTA) it takes around 10 seconds.

My signal level and quality is on the low side (both around 80-90% depending on weather) because I am not in the central footprint area for the 28.2 Astra satellites. I have two cables running from the LMB, one to my HTPC and one to my Sky box for comparison. The Sky box doesn't seem to have a problem and switches in around 1 second.

A portion of my tv.log file is below, but I don't know what the normal times should be for each bit of the tuning sequence. PMT handling ~5 seconds seems a lot. What is that bit doing?

I have checked for thinks eating CPU/Disk IO and there is nothing much else going on. All hardware drivers are up to date.

Any help in identifying the cause would be really appreciated.


This is my system spec:
CPU: Intel core i3-2120T (Sandy Ridge §M Cache, 2.60GHz)
RAM: 8GB
System Disk (C: SSD (OCZ) (where the time shift buffer goes)
Media Disk: 5400RPM HDD (used for recordings/saved media)
GPU: Intel HD 3000 (on-board)
TV Card: TBS-6981 (DVB-S/S2)

Relevant bit of log:

2012-11-03 21:03:00.326043 [(19)]: Controller: TimeShiftingWouldUseCard BBC 2 Wales 24
2012-11-03 21:03:00.422048 [(19)]: Controller: find free card for channel BBC 2 Wales
2012-11-03 21:03:00.510053 [(19)]: Controller: find card for channel BBC 2 Wales
2012-11-03 21:03:00.599058 [(19)]: Controller:  got 1 tuning details for BBC 2 Wales
2012-11-03 21:03:00.688063 [(19)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 2 Wales Freq:10788000 ONID:2 TSID:2046 SID:10312 PMT:0x108 FTA:True LCN:24 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-11-03 21:03:00.775068 [(19)]: Controller:    card:4 type:DvbC cannot tune to channel
2012-11-03 21:03:00.865073 [(19)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-11-03 21:03:00.953078 [(19)]: Controller:    card:3 type:DvbS can tune to channel
2012-11-03 21:03:01.041083 [(19)]: Controller:    card:3 type:DvbS users: 0
2012-11-03 21:03:01.128088 [(19)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-11-03 21:03:01.217094 [(19)]: Controller:    card:2 type:DvbS channel not mapped
2012-11-03 21:03:01.304099 [(19)]: Controller: found 1 card(s) for channel
2012-11-03 21:03:01.391104 [(19)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 881 msec
2012-11-03 21:03:01.487109 [(19)]: Controller:    card:3 type:DvbS is available
2012-11-03 21:03:01.575114 [(19)]: Controller: found 1 free card(s)
2012-11-03 21:03:01.663119 [(19)]: AdvancedCardAllocation.GetFreeCardsForChannel took 1241 msec
2012-11-03 21:03:01.774125 [(19)]: Controller: StartTimeShifting BBC 2 Wales 24
2012-11-03 21:03:01.861130 [(19)]: Controller: find free card for channel BBC 2 Wales
2012-11-03 21:03:01.948135 [(19)]: Controller: find card for channel BBC 2 Wales
2012-11-03 21:03:02.040141 [(19)]: Controller:  got 1 tuning details for BBC 2 Wales
2012-11-03 21:03:02.126146 [(19)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 2 Wales Freq:10788000 ONID:2 TSID:2046 SID:10312 PMT:0x108 FTA:True LCN:24 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-11-03 21:03:02.212150 [(19)]: Controller:    card:4 type:DvbC cannot tune to channel
2012-11-03 21:03:02.298155 [(19)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-11-03 21:03:02.384160 [(19)]: Controller:    card:3 type:DvbS can tune to channel
2012-11-03 21:03:02.473165 [(19)]: Controller:    card:3 type:DvbS users: 0
2012-11-03 21:03:02.564171 [(19)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-11-03 21:03:02.651176 [(19)]: Controller:    card:2 type:DvbS channel not mapped
2012-11-03 21:03:02.737181 [(19)]: Controller: found 1 card(s) for channel
2012-11-03 21:03:02.825186 [(19)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 876 msec
2012-11-03 21:03:02.910190 [(19)]: Controller:    card:3 type:DvbS is available
2012-11-03 21:03:03.001196 [(19)]: Controller: found 1 free card(s)
2012-11-03 21:03:03.091201 [(19)]: AdvancedCardAllocation.GetFreeCardsForChannel took 1229 msec
2012-11-03 21:03:03.176206 [(19)]: Controller: try max 1 of 1 cards for timeshifting
2012-11-03 21:03:03.262211 [(19)]: tvcard:FreeSubChannel: subchannels count 1 subch#1 keep graph=True
2012-11-03 21:03:03.349216 [(19)]: tvcard:FreeSubChannel :1 - is timeshifting (skipped)
2012-11-03 21:03:03.437221 [(19)]: TVServerXBMC: OnTvServerEvent: StartZapChannel
2012-11-03 21:03:03.530226 [(19)]: card: CardTune 3 BBC 2 Wales htpc:3:1
2012-11-03 21:03:03.617231 [(19)]: card: Tune 3 to BBC 2 Wales
2012-11-03 21:03:03.704236 [(19)]: card: user: htpc:3:1 tune DVBS:tv:BSkyB BBC 2 Wales Freq:10788000 ONID:2 TSID:2046 SID:10312 PMT:0x108 FTA:True LCN:24 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-11-03 21:03:03.795241 [(19)]: tvcard:FreeSubChannel: subchannels count 1 subch#1 keep graph=False
2012-11-03 21:03:03.881246 [(19)]: tvcard:FreeSubChannel :1 - is timeshifting (skipped)
2012-11-03 21:03:03.967251 [(19)]: TimeShifter.OnBeforeTune: resetting audio/video events
2012-11-03 21:03:04.058256 [(19)]: dvbs: Tune:DVBS:tv:BSkyB BBC 2 Wales Freq:10788000 ONID:2 TSID:2046 SID:10312 PMT:0x108 FTA:True LCN:24 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-11-03 21:03:04.145261 [(19)]: dvbs:  Tune:DVBS:tv:BSkyB BBC 2 Wales Freq:10788000 ONID:2 TSID:2046 SID:10312 PMT:0x108 FTA:True LCN:24 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-11-03 21:03:04.231266 [(19)]: dvb:Submiting tunerequest Channel:BBC 2 Wales subChannel:1
2012-11-03 21:03:04.317271 [(19)]: dvb:using existing subchannel:1
2012-11-03 21:03:04.402276 [(19)]: dvb:Submit tunerequest size:1 new:1
2012-11-03 21:03:04.488281 [(19)]: subch:1 OnBeforeTune
2012-11-03 21:03:04.650290 [(19)]: subch:1 OnAfterTune
2012-11-03 21:03:04.735295 [(19)]: RunGraph
2012-11-03 21:03:04.825300 [(19)]: dvb:  LockedInOnSignal ok
2012-11-03 21:03:04.910305 [(19)]: subch:1 OnGraphStart
2012-11-03 21:03:04.996310 [(19)]: subch:1 Graph already running - WaitForPMT
2012-11-03 21:03:05.091315 [(19)]: subch:1 SetupPmtGrabber:pid 108 sid:2848
2012-11-03 21:03:05.177320 [(19)]: subch:1 set pmt grabber pmt:108 sid:2848
2012-11-03 21:03:05.296327 [(19)]: TimeShifter.OnAfterTune: resetting audio/video time
2012-11-03 21:03:05.382332 [(19)]: WaitForPMT: Waiting for PMT 108
2012-11-03 21:03:05.680349 [(17)]: subch:1 OnPMTReceived() pmt:108 ran:True dynamic:False
2012-11-03 21:03:05.770354 [(19)]: WaitForPMT: Found PMT after 0.3870222 seconds.
2012-11-03 21:03:05.861359 [(19)]: subch:1 SendPmt:2848 2848 FFFFFFFF 1
2012-11-03 21:03:05.946364 [(19)]: Decode pmt
2012-11-03 21:03:06.033369 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:06.124374 [(19)]: Set descriptor data with length 6
2012-11-03 21:03:06.211379 [(19)]: PROBLEM : descriptor lengths dont match 3 9
2012-11-03 21:03:06.297384 [(19)]: Set descriptor data with length 12
2012-11-03 21:03:06.383389 [(19)]: PROBLEM : descriptor lengths dont match 3 15
2012-11-03 21:03:06.469394 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:06.558399 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:06.648404 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:06.735409 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:06.821414 [(19)]: Set descriptor data with length 10
2012-11-03 21:03:06.907419 [(19)]: PROBLEM : descriptor lengths dont match 3 13
2012-11-03 21:03:06.992424 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:07.083429 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:07.171434 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:07.258439 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:07.345444 [(19)]: Set descriptor data with length 3
2012-11-03 21:03:07.430449 [(19)]: subch:1 SendPMT: Channel is FTA, nothing to do.
2012-11-03 21:03:07.516454 [(19)]: subch:1 SetMpegPidMapping
2012-11-03 21:03:07.608459 [(19)]: subch:1  pid:1644 pcr
2012-11-03 21:03:07.694464 [(19)]: subch:1  pid:108 pmt
2012-11-03 21:03:07.780469 [(19)]: subch:1  pid:1644 video type:MPEG-2
2012-11-03 21:03:07.867474 [(19)]: subch:1    map pid:1644 video type:MPEG-2
2012-11-03 21:03:07.990481 [(19)]: subch:1  pid:1645 audio lang: type:MPEG-1
2012-11-03 21:03:08.082486 [(19)]: subch:1    map pid:1645 audio lang: type:MPEG-1
2012-11-03 21:03:08.205493 [(19)]: subch:1  pid:1647 teletext type:6
2012-11-03 21:03:08.291498 [(19)]: subch:1    map pid:1647 teletext type:6
2012-11-03 21:03:08.378503 [(19)]: subch:1  pid:F06 type:B
2012-11-03 21:03:08.464508 [(19)]: subch:1  pid:F07 type:B
2012-11-03 21:03:08.552513 [(19)]: subch:1  pid:F08 type:B
2012-11-03 21:03:08.646519 [(19)]: subch:1  pid:F09 type:B
2012-11-03 21:03:08.732523 [(19)]: subch:1  pid:1648 subtitle type:6
2012-11-03 21:03:08.819528 [(19)]: subch:1    map pid:1648 subtitle type:6
2012-11-03 21:03:08.906533 [(19)]: subch:1  pid:F00 type:5
2012-11-03 21:03:08.992538 [(19)]: subch:1  pid:F01 type:5
2012-11-03 21:03:09.077543 [(19)]: subch:1  pid:F02 type:5
2012-11-03 21:03:09.168548 [(19)]: subch:1  pid:F03 type:5
2012-11-03 21:03:09.257553 [(19)]: subch:1  pid:F04 type:5
2012-11-03 21:03:09.345558 [(19)]: subch:1  pid:90F type:5
2012-11-03 21:03:09.435564 [(19)]: subch:1  pid:910 type:5
2012-11-03 21:03:09.524569 [(19)]: subch:1  pid:911 type:5
2012-11-03 21:03:09.620574 [(19)]: subch:1  pid:916 type:5
2012-11-03 21:03:10.167606 [(19)]: subch:1 stop tif
2012-11-03 21:03:10.253610 [(17)]: PID seen - type = Video
2012-11-03 21:03:10.340615 [(19)]: WaitForPmt: PMT handling took 4.3932513 seconds.
2012-11-03 21:03:10.425620 [(17)]: audioVideoEventHandler Video
2012-11-03 21:03:10.512625 [(19)]: card: Tuner locked: True
2012-11-03 21:03:10.605631 [(17)]: video last seen at 03/11/2012 21:03:10
2012-11-03 21:03:10.697636 [(19)]: **************************************************
2012-11-03 21:03:10.808642 [(19)]: ***** SIGNAL LEVEL: 83, SIGNAL QUALITY: 79 *****
2012-11-03 21:03:10.910648 [(19)]: **************************************************
2012-11-03 21:03:11.011654 [(19)]: card: tuned user: htpc subchannel: 1
2012-11-03 21:03:11.108659 [(17)]: PID seen - type = Audio
2012-11-03 21:03:11.197664 [(19)]: user:htpc add
2012-11-03 21:03:11.284669 [(17)]: audioVideoEventHandler Audio
2012-11-03 21:03:11.370674 [(19)]: card2:htpc 3 1
2012-11-03 21:03:11.457679 [(17)]: audio last seen at 03/11/2012 21:03:11
2012-11-03 21:03:11.542684 [(19)]: Controller: htpc 3 1
2012-11-03 21:03:11.647690 [(19)]: TVServerXBMC: OnTvServerEvent: EndZapChannel
2012-11-03 21:03:11.739695 [(19)]: control2:htpc 3 1
2012-11-03 21:03:11.834701 [(19)]: TVServerXBMC: OnTvServerEvent: StartTimeShifting
2012-11-03 21:03:11.929706 [(19)]: card: StartTimeShifting 3 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live3-1.ts
2012-11-03 21:03:12.023712 [(19)]: card: CAM enabled : False
2012-11-03 21:03:12.129718 [(19)]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo
2012-11-03 21:03:12.220723 [(19)]: card: WaitForTimeShiftFile - video and audio are seen after 0.0910052 seconds
2012-11-03 21:03:12.313728 [(19)]: Controller: StartTimeShifting started on card:3 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live3-1.ts

 

[erichzann]

Are you using an XBMC frontend?

Also, may be worth moving your timeshift off the SSD onto a mechanical drive. It won't make any noticeable differences and it will save excessive writes to the SSD. Edit: Also it's probably preferable to have the timeshift on a separate drive to the OS.

 

[octessence]

OK I'll do that thanks for the advice.

I have the XBMC frontend installed but I'm not using it for these tests. When using XBMC frontend it's even slower.

EDIT: Spelling

 

[erichzann]

The other benefit of having it on a separate drive is that you can (and should) disable any virus scans etc. and prevent the drive spinning down etc. Sometimes if the drive is idle I find the first channel tune can take a bit longer.

Also can you post a screenshot to show the priority of yours card in TV Server config?

Edit: I think the problem is that your priority of cards is not set and it is trawling through all the cards to find the one to tune to the channel you selected. If you set the priority correctly it should pick up the card quicker.

 

[octessence]

I have tried disabling virus scanning based on other posts but there really is nothing else going on in terms of CPU and Disk IO so I don't think that's the answer. It's also consistently slow and the slowness does not vary so it's not a disk access thing.

The log shows that it only takes 3 of the 12 seconds to find a free card for the channel and start zapping. This is slow yes and I can fix that by playing with the priorities.

It's the rest of the log I'm more concerned with (i.e. the tuning speed between StartZapChannel and EndZapChannel. If someone can tell me more about what's going on there then maybe I can do something about it such as getting a bigger dish to improve signal or getting a different TV card if the one I have it a load of s***. I don't want to go buying anything until I know what the problem is though.

 

[octessence]

Right, well I have been trying out DVBlink based on something I read in their forum about recently improving the zapping speed of "old TBS cards". With that and WMC it is switching channels in around 2 seconds. I'm very impressed with that apart from the fact that I have to use WMC.

There seem to be an xbmc PVR client being written for DVBlink but all of this is not very mature yet so it would be great to get MP to tune in a reasonable time. At least now I know it's not an issue with any of my hardware.

 

[onelegend]

Zapping time should be around 5/6 secs for dvb s2 without the tbs specific code.
2/3 seconds for dvb s.

Basically when tuning dvbs2, the tbs driver checks dvbs first and then dvb s2. Thus slow times. The quick channel change code allows mepo to tell the driver to tune dvb s2 first. This code is done but requires a mod/branch atm

But if your standard sd dvb s channels are slow then I'd say something else in mepo is causing the slow change. The quick change code will only effect HD dvbs2

Even without the quick change code you should be around 6 seconds on HD dvb s2

I have the 6981 also btw

 

[onelegend]

What codec do you have set in tv config?

I use lav for all settings.

May I also suggest running in debug mode, this will test with no plugins loaded. Do a few tunes (with 20 secs in between to separate it). When you close mepo the debug mode will create a zip file on your desktop (default).

Attach the zip here and hopefully can spot what's causing the slow down

 

[octessence]

It's purely dvb-s channels I'm talking about above. The dvb-s2 ones take longer again. I have tried using LAV codecs but it doesn't really make much of a difference (for dvb-s channels at least). In any case the codec is a property of the MP frontend and it's the backend that's being really slow before the frontend even gets hold of the stream.

This morning, I'm getting quicker "PMT handling" results at 2.1 seconds giving a total tuning speed for dvb-s now 8 seconds (which is still very slow). The signal is actually worse so I can rule that out at a problem as well. It's now I've love to know what this actually is and what could slow it down.

I also noticed in my above log that it is trying to find a card for the channel twice, wasting over a second. Why is it doing that?



2012-11-03 21:03:00.510053 [(19)]: Controller: find card for channel BBC 2 Wales

2012-11-03 21:03:01.304099 [(19)]: Controller: found 1 card(s) for channel

2012-11-03 21:03:01.948135 [(19)]: Controller: find card for channel BBC 2 Wales

2012-11-03 21:03:03.001196 [(19)]: Controller: found 1 free card(s)


P.S. I will switch on debugging to see if that reveals anything.

EDIT: There doesn't seem to be a debug option for the TV Server (only the MediaPortal frontend).

 

[octessence]

OK I misread the last post. I will do a full debug dump and upload.