How to cut down on 5 secs channel change? (1 Viewer)

thomas.p

Portal Member
February 10, 2009
9
0
Home Country
Denmark Denmark
TV-Server Version: 1.0.0.21149
MediaPortal Version: 1.0.0.21149
MediaPortal Skin: Blue3
Windows Version: Win XP MCE SP3
CPU Type: Intel P4 Nw 2.2 GHz
HDD: 1: Seagate 200 GB, 2: WD 250 GB, 3: WD 250 GB
Memory: 512 MB + 2x 256 MB PC-2700
Motherboard: Gigabyte 8PE667U
Video Card: ATI Radeon 9800 Pro w. 128 MB RAM
Video Card Driver: Catalyst v8.12
Sound Card: Creative Soundblaster Audigy 2 ZS
Sound Card AC3:
Sound Card Driver: 6.0.1.1361
1. TV Card: Hauppauge PVR 500 MCE
1. TV Card Type: Dual analogue tuners
1. TV Card Driver: 2.0.48.25037
2. TV Card:
2. TV Card Type:
2. TV Card Driver:
3. TV Card:
3. TV Card Type:
3. TV Card Driver:
4. TV Card:
4. TV Card Type:
4. TV Card Driver:
MPEG2 Video Codec: MPV Decoder Filter
MPEG2 Audio Codec: MPA Decoder Filter
h.264 Video Codec: ffdshow Video Decoder
Satelite/CableTV Provider:
HTPC Case: Old Piece of Trash™
Cooling: Zalman CNPS7000A-AlCu & VF1000 LED & NB47J
Power Supply: Nexus NX-3000 (300W)
Remote:
TV:
TV - HTPC Connection:


I am new to MediaPortal, so I need some help troubleshooting an issue that has annoyed me since I first tried out my new TV-watching-experience. I have come across several threads describing much the same problem, but most have been reduced to guesses without any reports of a real solution - I hope this will be different.

My channel change times are very long - usually in excess of 5 seconds. I have tried to break down the problem by looking at log files, but I have no idea what times are to be expected and what all the stuff that is going on in the log file is all about let alone how to resolve the problems that I have identified. It would be great if somebody could point to exactly which parts of the logs show excessive times and what I can do to counter the particular problems that they may represent.

To start things off I have grabbed an example from a log generated during one of my recent sessions - a generic channel switch. This can be found in attatched old_logs.zip. Another set of logs made with the MediaPortal Debug mode is also attatched for further elaboration.

mediaportal.log says button press was registered at 02:39:30.791438

vmr9.log says presentation started again at 02:39:36.025

This is a total of ~5.234 secs, which corresponds pretty well with the times i generally experience on changing channel. So I had an in-depth look at it:

Code:
** MediaPortal.log snippet begin **
2009-02-10 02:39:30.791438 [Info.][MPMain]: TVHome:OnPreviousChannel()
[COLOR="Red"]2009-02-10 02:39:30.978938 [Info.][MPMain]: Navigator:ZapPrevious TV 2 Zulu->TV 2[/COLOR]
2009-02-10 02:39:33.572688 [Info.][MPMain]: Channel change:TV 2
2009-02-10 02:39:33.572688 [Info.][MPMain]: TVHome.ViewChannelAndCheck(): View channel=TV 2
[COLOR="Red"]2009-02-10 02:39:33.838313 [Info.][MPMain]: TSReaderPlayer:Pause graph[/COLOR]
2009-02-10 02:39:35.385188 [Info.][MPMain]: tvhome:SeektoEnd(True, rtsp=False
2009-02-10 02:39:35.400813 [Info.][MPMain]: TsReaderPlayer:seekabs:648070000 start:2980000 end:648070000
2009-02-10 02:39:35.478938 [Info.][MPMain]: TsReaderPlayer seek done:0
2009-02-10 02:39:35.478938 [Info.][MPMain]: TSReaderPlayer: current pos:64,509 dur:64,509
2009-02-10 02:39:35.478938 [Info.][MPMain]: TSReaderPlayer:Continue graph
2009-02-10 02:39:35.478938 [Info.][MPMain]: succeeded:Succeeded TvControl.VirtualCard
** MediaPortal.log snippet end **

Two things especially bother me about this: The events at 02:39:30.978938 and 02:39:33.838313. Each last 2.59375 secs and 1.546875 - without them the total change time would be ~1.093 secs which, to me, would be better than the expected total of 1-2 secs. So I am really interested in what is hiding behind those events and times.

For greater detail I took a look at the tv.log file - it held no record for the initial "Navigator:ZapPrevious" time consumption, so I am guessing that is client-side and registered in a log I could not find. However it did give a better idea of what was going on with the "TSReaderPlayer:pause graph".

(I refrained from pasting my tv.log snippet here - would take up too much room ;)

The tv.log represents a time frame of 1.671875 - only some 30% of the total channel change time. However there are also a few times that seem out of the ordinary. In particular the following three lines seemed to use up a lot of time. However I have no clue whether this is normal and what can be done to improve those times.

02:39:33.994563 0.171875 card: user: mediaportal:1:0 tune tv:confused:portsNyhederne Freq:0 Channel:89 Country:Denmark Tuner:Cable Video:Tuner
02:39:34.713313 0.40625 card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo
02:39:35.150813 0.21875 card: WaitForTimeShiftFile - video and audio are seen after 0,421875 seconds

The three together make up 0.796875 secs which is just short of half of the total time represented in the tv.log

Code:
** vmr9.log snippet begin **
10-02-2009 02:39:33.869 [a74]vmr9:StopPresenting()
10-02-2009 02:39:36.025 [69c]vmr9:StartPresenting()
** vmr9.log snippet end **

I am guessing that the vmr9.log shows that the MediaPortal client shuts down the display of the video stream while the server is changing the channel. When

compared to the other log files it seems the presentation is stopped while the MediaPlayer.log reports the "TSReaderPlayer:pause graph" and the tv.log reports

that it is happening just before the "Controller: StartTimeShifting TV 2 15" is happening, which does not seem to coincide with any of the big time consumers in

the tv.log. It is difficult for me to assess whether this means something without a bit more insight into how this works :)

tv.log end 02:39:35.400813
MediaPortal.log end 02:39:35.478938 +0.078125
vmr9.log end 02:39:36.025 +0.546062

I am wondering what is going on during the time that passes while the tv.log and MediaPortal.log is done reporting and I am waiting to see the picture on my

screen as I am guessing the vmr9.log reports more than half a second later

Codecs does not seem to be a problem - I have changed between several different sets and channel change times doesn't really get lower.

I have also experimented with placement and setup of timeshift files, which also seemed to have no direct effect on the problem.

Can anybody explain to me what is going on?
 

thomas.p

Portal Member
February 10, 2009
9
0
Home Country
Denmark Denmark
By sheer dumb luck I discovered that the log entries containing Navigator:Zap is closely connected to GUI functionality. When playing around with the configuration of MediaPortal I stumbled over the Zap-OSD settings. Those turned out to be tightly connected with channel changing times - especially the value of "Zap delay".

After setting this to 0 the time of a "Navigator:Zap" entry dropped from an average of 2.594 secs to an average of 0.320 secs - effectively shaving off more than 2 secs which makes a huge difference in zapping! This means that my average channel change time has dropped to 2.496 secs which is less than half of what I started out with.

However I am still stuck with the "TSReaderPlayer:pause graph" entry and the relatively huge time span it consumes during my channel changes. In the TsReader.log I get the impression that the "CTsReaderFilter::pause()" and the "vid:set discontinuity" make up most of this. Any of you guys have ideas for which parts of MediaPortal these entries are referring to and how I might configure them to take less time?

Any help would be appreciated! :D
 

Users who are viewing this thread

Top Bottom