How fast is your channel switching? (2 Viewers)

[vlukinius]

I have been trying to figure out what happens when I change channel.

I choose to switch channel at 23:37:28. From tv.log

2008-08-17 23:37:28.984375 [14]: Controller: TimeShiftingWouldUseCard SVT Barn&Kunskap 7

then it ends at

2008-08-17 23:37:31.093750 [14]: Controller: StartTimeShifting started on card:1 to C:\Documents and Settings\All Users\Application Data\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live1-0.ts

About 3 seconds. Sounds ok. but I dont get the picture yet.

Nothing in the TVServer logs seams to be showing any problems. They all ended at that time.
How ever in the Mediaportal logs I see things still continuing.

In the TSReader.log I find what looks like the thing that takes time. this is the end of that log.

17-08-2008 23:37:33.156 [f5c]Pes header 0-0-1 fail
17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.265 [f5c]Pes header 0-0-1 fail
17-08-2008 23:37:33.421 [6cc]Pes header 0-0-1 fail
17-08-2008 23:37:33.421 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.531 [6cc]vid:set discontinuity
17-08-2008 23:37:33.531 [6cc]vid:set discontinuity
17-08-2008 23:37:33.578 [f5c]aud:set discontinuity
17-08-2008 23:37:33.578 [f5c]aud:set discontinuity
17-08-2008 23:37:33.578 [f5c]aud:compensation:2.578
17-08-2008 23:37:34.156 [efc]CTsReaderFilter::Run(41229.26)
17-08-2008 23:37:34.156 [efc]CTsReaderFilter::Run(41229.26) -->done

It looks like TVserver creates the timeshift file and then Mediaportal reads it.
Here it looks like something is failing. I cant understand what. Might this be related to codecs or are they not involved at this point?

I attach the logs in a zip file.

 

[ThaClown]

TV Server setup FireDTV-C:
Anywhere between 1,5 and 4 seconds...

Seems going from HD to 'normal' is slower, as is changing transponder...

 

[stoked]

I have been trying to figure out what happens when I change channel.

I choose to switch channel at 23:37:28. From tv.log.

I get the same problem occasionally. Channel change, sound comes in pretty quick a round 3sec, but no video, and I get those Pes 0-0-1 errors. My setup is last week's SVN in multi-seat setup with DVB-S. I am using an unsupported "filter" but if you're getting the same problem, it may likely be a MP issue and not the plugin filter.

 

[tourettes]

17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.265 [f5c]Pes header 0-0-1 fail

Usually that means you are using MDAPI filter (which is not supported) and the TS packets are encrypted when TsReader receives those.

 

[stoked]

17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.265 [f5c]Pes header 0-0-1 fail

Usually that means you are using MDAPI filter (which is not supported) and the TS packets are encrypted when TsReader receives those.

He's using DVB-C, don't think mdapi filter supports dvb-c though I may be mistaken. vlukinius would have to confirm.

 

[migube]

Not sure I have the error in the logs, will doublecheck, Im using DVb-T

I tried with One tuner (One stick with only one tuner), same slowness

Some Tvserver logs: from the time I zapped to Fr2.
Not sure when the image is actually shown, but it shows things like:
request received at 21:31:42.3 & possibly image at 21:31:47.9 => Which is >5 seconds.

MP logs:
2008-08-15 21:31:42.300696 [Debug][MPMain]: ChangeChannelNr()
2008-08-15 21:31:42.340753 [Debug][MPMain]: ChannelNavigator.ZapToChannel France 2 - zapdelay False
2008-08-15 21:31:42.340753 [Debug][MPMain]: UpdateOSD()
2008-08-15 21:31:42.350768 [Debug][MPMain]: Window: TvPlugin.TvZapOsd init
2008-08-15 21:31:42.350768 [Debug][MPMain]: zaposd pageload
2008-08-15 21:31:42.450912 [Debug][MPMain]: ZAP OSD:ON
2008-08-15 21:31:42.490969 [Info.][MPMain]: Channel change:France 2
2008-08-15 21:31:42.490969 [Info.][MPMain]: TVHome.ViewChannelAndCheck(): View channel=France 2
2008-08-15 21:31:42.711286 [Debug][3]: Planescene.InternalPresentSurface: timePassed = 0,1875 - dropped 1 frame(s)
2008-08-15 21:31:42.821444 [Info.][MPMain]: TSReaderPlayerause graph
2008-08-15 21:31:43.011718 [Info.][3]: planescene: PresentSurface() frame:26 enabled:False allowed:True 720x576
2008-08-15 21:31:45.315030 [Info.][MPMain]: tvhomeeektoEnd(True)
2008-08-15 21:31:45.325044 [Debug][MPMain]: g_Player.SeekAbsolute() - Preparing to seek to 0:0:35
2008-08-15 21:31:45.325044 [Info.][MPMain]: TsReaderPlayer:seekabs:350649984 start:0 end:350650000
2008-08-15 21:31:45.385131 [Info.][MPMain]: TsReaderPlayer seek done:0
2008-08-15 21:31:45.395145 [Info.][MPMain]: TSReaderPlayer: current pos:35,064998626709 dur:35,064998626709
2008-08-15 21:31:45.395145 [Info.][MPMain]: TSReaderPlayer:Continue graph
2008-08-15 21:31:45.395145 [Info.][MPMain]: succeededucceeded TvControl.VirtualCard
2008-08-15 21:31:45.785707 [Info.][MPMain]: Graph doesn't need a rebuild
2008-08-15 21:31:46.186283 [Info.][MPMain]: Graph stopped.
2008-08-15 21:31:46.186283 [Info.][MPMain]: Reconnecting audio pin of tsreader filter.
2008-08-15 21:31:46.216326 [Info.][MPMain]: Reconfigure graph done
2008-08-15 21:31:46.747089 [Debug][3]: Planescene.InternalPresentSurface: timePassed = 4,0625 - dropped 2 frame(s)
2008-08-15 21:31:47.438083 [Debug][MPMain]: VMR9Helper: Playing -> Repainting, Frames 1
2008-08-15 21:31:47.868702 [Info.][3]: planescene: PresentSurface() frame:0 enabled:True allowed:False 720x576
2008-08-15 21:31:47.918774 [Debug][MPMain]: zaposd pagedestroy
2008-08-15 21:31:47.918774 [Debug][MPMain]: Window: TvPlugin.TvZapOsd deinit
2008-08-15 21:31:47.918774 [Debug][MPMain]: TextureManager: CleanupThumbs()
2008-08-15 21:31:47.918774 [Debug][MPMain]: ZAP OSD:Off timeout
2008-08-15 21:31:47.928788 [Info.][3]: planescene: PresentSurface() frame:1 enabled:True allowed:False 720x576
2008-08-15 21:31:47.958832 [Info.][3]: planescene: PresentSurface() frame:2 enabled:True allowed:False 720x576
2008-08-15 21:31:47.968846 [Debug][MPMain]: VMR9: Repainting -> Playing, Frames: 3
2008-08-15 21:31:47.988875 [Debug][3]: Planescene.InternalPresentSurface: timePassed = 0,1875 - dropped 3 frame(s)

Tvserver logs:
2008-08-15 21:31:10.004256 [10]: Controller: StartTimeShifting started on card:1 to C:\Documents and Settings\All Users.WINDOWS\Application Data\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live1-0.ts.tsbuffer
2008-08-15 21:31:42.531027 [11]: Controller: channel #1 DVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:42.601128 [11]: Controller: card:2 typevbT channel not mapped
2008-08-15 21:31:42.601128 [11]: Controller: card:3 type:RadioWebStream cannot tune to channel
2008-08-15 21:31:42.601128 [11]: Controller: found 1 available
2008-08-15 21:31:42.741329 [11]: Controller: TimeShiftingWouldUseCard France 2 22
2008-08-15 21:31:42.741329 [11]: Controller: find free card for channel France 2
2008-08-15 21:31:42.751344 [11]: Controller: got 1 tuning details for France 2
2008-08-15 21:31:42.751344 [11]: Controller: channel #1 DVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:42.781387 [11]: Controller: card:1 typevbT is available priority:3 #users:0 same transponder:False
2008-08-15 21:31:42.821444 [11]: Controller: card:2 typevbT channel not mapped
2008-08-15 21:31:42.821444 [11]: Controller: card:3 type:RadioWebStream cannot tune to channel
2008-08-15 21:31:42.821444 [11]: Controller: found 1 available
2008-08-15 21:31:42.861502 [11]: Controller: StartTimeShifting France 2 22
2008-08-15 21:31:42.861502 [11]: Controller: find free card for channel France 2
2008-08-15 21:31:42.881531 [11]: Controller: got 1 tuning details for France 2
2008-08-15 21:31:42.881531 [11]: Controller: channel #1 DVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:42.921588 [11]: Controller: card:1 typevbT is available priority:3 #users:0 same transponder:False
2008-08-15 21:31:42.951632 [11]: Controller: card:2 typevbT channel not mapped
2008-08-15 21:31:42.961646 [11]: Controller: card:3 type:RadioWebStream cannot tune to channel
2008-08-15 21:31:42.971660 [11]: Controller: found 1 available
2008-08-15 21:31:43.372236 [11]: card: CardTune 1 France 2 N800C_3:1:-1
2008-08-15 21:31:43.392265 [11]: card: Tune 1 to France 2
2008-08-15 21:31:43.392265 [11]: card: user: N800C_3:1:0 tune DVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:43.572524 [11]: card: to different transponder
2008-08-15 21:31:43.582539 [11]: dvbt: TuneVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:43.582539 [11]: dvbt: tune: Assigning oldChannel
2008-08-15 21:31:43.582539 [11]: dvbt: tune: Current Channel != null DVBT:tvMR6 TF1 Freq:586000 ONID:8442 TSID:6 SID:1537 PMT:64 FTA:False LCN:1 BandWidth:8
2008-08-15 21:31:43.582539 [11]: dvbt: tune: Graph is tunning
2008-08-15 21:31:43.582539 [11]: dvbt: tune: Getting default locator
2008-08-15 21:31:43.582539 [11]: dvbt: tune: Putting bandwidth 8
2008-08-15 21:31:43.582539 [11]: dvbt: tune: put_ONID 8442
2008-08-15 21:31:43.582539 [11]: dvbt: tune: put_SID 257
2008-08-15 21:31:43.592553 [11]: dvbt: tune: put_TSID 1
2008-08-15 21:31:43.592553 [11]: dvbt: tune: Carrier frequency 490000
2008-08-15 21:31:43.592553 [11]: dvbt: tune: put_Locator
2008-08-15 21:31:43.592553 [11]: dvbt: tune: Submitting tune request: SubId 0, channel DVBT:tv:GR1 France 2 Freq:490000 ONID:8442 TSID:1 SID:257 PMT:6E FTA:True LCN:2 BandWidth:8
2008-08-15 21:31:43.592553 [11]: dvbt: tune: Submitting tune request: System.__ComObject
2008-08-15 21:31:43.592553 [11]: dvbubmiting tunerequest Channel:France 2 subChannel:0
2008-08-15 21:31:43.602568 [11]: dvbubmit tunerequest size:1 new:0
2008-08-15 21:31:43.602568 [11]: subch:0 OnBeforeTune
2008-08-15 21:31:43.602568 [11]: dvbubmit tunerequest calling put_TuneRequest
2008-08-15 21:31:44.904440 [11]: dvbubmit tunerequest done calling put_TuneRequest
2008-08-15 21:31:44.904440 [11]: subch:0 OnAfterTune
2008-08-15 21:31:44.904440 [11]: dvbt: tune: Running graph for channel TvLibrary.Implementations.DVB.TvDvbChannel
2008-08-15 21:31:44.904440 [11]: dvbt: tune: SubChannel 0
2008-08-15 21:31:44.914454 [11]: subch:0 OnGraphStart
2008-08-15 21:31:44.914454 [11]: subch:0 RunGraph: already running
2008-08-15 21:31:44.914454 [11]: subch:0 SetupPmtGrabberid 6E sid:101
2008-08-15 21:31:44.914454 [11]: subch:0 set pmt grabber pmt:6E sid:101
2008-08-15 21:31:44.914454 [11]: subch:0 wait for pmt 6E
2008-08-15 21:31:44.934483 [5]: subch:0 OnPMTReceived() True
2008-08-15 21:31:44.934483 [5]: subch:0 SendPmt:101 101 FFFFFFFF 0
2008-08-15 21:31:44.934483 [5]: Decode pmt
2008-08-15 21:31:44.934483 [5]: Set descriptor data with length 6
2008-08-15 21:31:44.934483 [5]: Set descriptor data with length 10
2008-08-15 21:31:44.934483 [5]: subch:0 SendPMT version:0 len:47 257
2008-08-15 21:31:44.934483 [5]: subch:0 cam flags:True
2008-08-15 21:31:44.934483 [5]: subch:0 SetMpegPidMapping
2008-08-15 21:31:44.944497 [5]: subch:0 pid:0 pcr
2008-08-15 21:31:44.944497 [5]: subch:0 pid:6E pmt
2008-08-15 21:31:44.944497 [5]: subch:0 pid:78 video type:MPEG-2
2008-08-15 21:31:44.944497 [5]: subch:0 map pid:78 video type:MPEG-2
2008-08-15 21:31:44.944497 [11]: dvbt: tune: Graph running. Returning TvLibrary.Implementations.DVB.TvDvbChannel
2008-08-15 21:31:44.944497 [11]: card: tuned user: N800C_3 subchannel: 0
2008-08-15 21:31:44.954512 [11]: user:N800C_3 add
2008-08-15 21:31:44.954512 [5]: subch:0 pid:82 audio lang:fra type:MPEG-1
2008-08-15 21:31:44.954512 [5]: subch:0 map pid:82 audio lang:fra type:MPEG-1
2008-08-15 21:31:44.954512 [5]: subch:0 pid:8C subtitle type:6
2008-08-15 21:31:44.964526 [5]: subch:0 stop tif
2008-08-15 21:31:44.964526 [5]: PID seen - type = Video
2008-08-15 21:31:44.964526 [5]: audioVideoEventHandler Video
2008-08-15 21:31:44.994569 [11]: card: Tuner locked: False
2008-08-15 21:31:44.994569 [11]: **************************************************
2008-08-15 21:31:45.004584 [11]: ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 0 *****
2008-08-15 21:31:45.004584 [11]: **************************************************
2008-08-15 21:31:45.014598 [5]: PID seen - type = Audio
2008-08-15 21:31:45.014598 [5]: audioVideoEventHandler Audio
2008-08-15 21:31:45.034627 [11]: card2:N800C_3 1 0
2008-08-15 21:31:45.034627 [11]: Controller: N800C_3 1 0
2008-08-15 21:31:45.044641 [11]: control2:N800C_3 1 0
2008-08-15 21:31:45.064670 [11]: card: StartTimeShifting 1 C:\Documents and Settings\All Users.WINDOWS\Application Data\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live1-0.ts
2008-08-15 21:31:45.074684 [11]: card: WaitForUnScrambledSignal
2008-08-15 21:31:45.074684 [11]: card: return not scrambled
2008-08-15 21:31:45.074684 [11]: card: WaitForTimeShiftFile
2008-08-15 21:31:45.084699 [11]: card: WaitForUnScrambledSignal
2008-08-15 21:31:45.084699 [11]: card: return not scrambled
2008-08-15 21:31:45.084699 [11]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo
2008-08-15 21:31:45.084699 [11]: card: WaitForTimeShiftFile - start of the video & audio is seen
2008-08-15 21:31:45.315030 [11]: TimeshiftingEPG: channel France 2 is not configured for grabbing epg
2008-08-15 21:31:45.315030 [11]: Controller: StartTimeShifting started on card:1 to C:\Documents and Settings\All Users.WINDOWS\Application Data\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live1-0.ts
2008-08-15 21:31:51.533972 [11]: Controller: channel #1 DVBT:tv:Reg France 3 Freq:490000 ONID:8442 TSID:1 SID:275 PMT2 FTA:True LCN:3 BandWidth:8

 

[infinite.loop]

everyone here should be aware that the used codecs have an HUGE impact on the channel switch times.
depending on codecs (and combination of audio/video codec) it can take 15 seconds or 2seconds to switch the channel, on the same PC!

the user jobiwan can confirm that.

 

[stax]

TV-Server Version: 1.0 RC2
MediaPortal Version: 1.0 RC2
MediaPortal Skin: xface
Windows Version: MCE 2005
CPU Type: AMD X2
Motherboard: AMD 770
1. TV Card: KNC-1 DVB-C
Codecs: Gabest
CableTV Provider: KabelBW
Remote: MCE v2
TV: 60cm 4:3 analog

I was estimating it takes 2-3 seconds to switch channels but after measuring it was actually twice, bottomline is you really have to measure.

I'm using Gabest's codecs, in other applications I've never noticed any performence problems with this codecs.

 

[infinite.loop]

I'm using Gabest's codecs, in other applications I've never noticed any performence problems with this codecs.

Other applications do not use the filters MediaPortal uses (i.e. TsReader). So that combination could cause issues in some cases.

As i have seen dvbviewer crashing when using i.e. the h.264 divx codec, MediaPortal does not crash.
Keep in mind that filters can behave differently in different applications.

 

[vlukinius]

17-08-2008 23:37:33.218 [6cc]Pes 0-0-1 fail
17-08-2008 23:37:33.265 [f5c]Pes header 0-0-1 fail

Usually that means you are using MDAPI filter (which is not supported) and the TS packets are encrypted when TsReader receives those.

He's using DVB-C, don't think mdapi filter supports dvb-c though I may be mistaken. vlukinius would have to confirm.

To be honest I have no clue about MDAPI filter. I have been using, the MPV and ffdshow and they both are slow. How ever I have to admit I do not know what I used during the test with the logs files I attached. But I think it was MPV.

infinityloop:

everyone here should be aware that the used codecs have an HUGE impact on the channel switch times.
depending on codecs (and combination of audio/video codec) it can take 15 seconds or 2seconds to switch the channel, on the same PC!

I understand that codecs may have a big impact. Is there any good information about this anywhere? Preferably related to media portal.
Even if people have different TV cards and video cards the results for the lag between when the tv card has tuned into the new channel and when the picture actually shows up should be about the same. If it is not a codec that uses gfx cpu or some computer in incredibly slow.

Thanks for any and all help. This is a big issue for many of us I think, even if the issue might not be Media Portal.