Channel switching times increased with 1.4.0 (1 Viewer)

[mm1352000]

Hello again Razorblade

The second log entry you posted is from 2013-08-11. This is already with server 1.4. I updated the server on 2013-08-07.

It really feels "much" longer now...

On the 12th I see:

2013-08-12 19:15:28.926072 [Info.][MPMain(1)]: TvPlugin and TvServer don't have the same version.
TvServer Version: 1.4.0.0
TvPlugin Version: 1.3.0.0

I don't see that entry on the 11th so either the server is still v1.3 at that stage, or something funky is going on if that is really the case.

Do you need some older Logfiles?

Sure. I mean, if you're convinced that you updated on the 7th and you have some 1.3 client + server logs around then by all means I'd be happy to take a look. That way I can cross-compare and see where the extra time is taken.

What exactly is a "full channel change"?

It is when the TV Server has to actually send a tune request to the hardware and the client has to build or rebuild the player graph. You could consider it like a "worst case" channel change time (though it is not actually the absolute worst case).
On the server side, it is the difference between an 800 ms change and a 200 ms change.
On the client side it is harder to quantify, but you can compare for yourself.

Here is the full tune for SAT.1:
[collapse]2013-08-12 19:16:20.010114 [Info.][MPMain(1)]: TVHome.ViewChannelAndCheck(): View channel=SAT.1
2013-08-12 19:16:20.652204 [Info.][MPMain(1)]: succeededucceeded TvControl.VirtualCard
2013-08-12 19:16:20.656211 [Info.][MPMain(1)]: tvhome:startplay
2013-08-12 19:16:20.659216 [Info.][MPMain(1)]: tvhome:file:\TV_Timeshift\live9-0.ts.tsbuffer
2013-08-12 19:16:20.663223 [Warn.][MPMain(1)]: tvhome:startplay. Phase 1 - 9 ms - Done method initialization
2013-08-12 19:16:20.665226 [Info.][MPMain(1)]: tvhome:startplay:rtsp://WHS-Box:554/stream9.0 - using rtsp mode:True
2013-08-12 19:16:20.669233 [Info.][MPMain(1)]: g_Player.Play(rtsp://WHS-Box:554/stream9.0 TV)
2013-08-12 19:16:20.881593 [Info.][MPMain(1)]: TSReaderPlayer play:rtsp://WHS-Box:554/stream9.0 radio:False
2013-08-12 19:16:20.882595 [Info.][MPMain(1)]: TSReaderPlayer: live tv
2013-08-12 19:16:20.883597 [Info.][MPMain(1)]: TSReaderPlayer: Enabling DX9 exclusive mode
2013-08-12 19:16:20.883597 [Info.][MPMain(1)]: TSReaderPlayerlay rtsp://WHS-Box:554/stream9.0
2013-08-12 19:16:20.890609 [Info.][MPMain(1)]: TSReaderPlayer: GetInterfaces()
2013-08-12 19:16:20.907638 [Info.][MPMain(1)]: DirectShowUtils: First try to insert new audio renderer Default DirectSound Device
2013-08-12 19:16:20.993784 [Info.][MPMain(1)]: DirectShowUtils: Found audio renderer
2013-08-12 19:16:21.070915 [Info.][MPMain(1)]: TSReaderPlayer: Add TsReader to graph
2013-08-12 19:16:21.071916 [Info.][MPMain(1)]: TSReaderPlayer: Open file: rtsp://WHS-Box:554/stream9.0
2013-08-12 19:16:21.100966 [Info.][MPMain(1)]: TSReaderPlayer:OnRequestAudioChange()
2013-08-12 19:16:21.112986 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:16:21.113988 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:16:21.113988 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:16:21.114990 [Info.][MPMain(1)]: Audio stream: switching to preferred AC3 audio stream 1, based on LANG deu
2013-08-12 19:16:21.115991 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:16:21.819185 [Info.][MPMain(1)]: TsReaderPlayer: OnVideoFormatChanged - streamtype=MPEG2 resolution=720x576 aspect ratio=16:9 bitrate=15000000 isInterlaced=True
2013-08-12 19:16:21.827198 [Info.][MPMain(1)]: TSReaderPlayer: Add codecs
2013-08-12 19:16:22.085637 [Info.][MPMain(1)]: VMR9: added EVR Renderer to graph
2013-08-12 19:16:22.167776 [Info.][MPMain(1)]: Added filter: CyberLink Video Decoder (PDVD12) to graph
2013-08-12 19:16:22.176792 [Info.][MPMain(1)]: Added filter: MediaPortal DVBSub3 to graph
2013-08-12 19:16:22.322038 [Info.][MPMain(1)]: Added filter: LAV Audio Decoder to graph
2013-08-12 19:16:22.325043 [Info.][MPMain(1)]: TSReaderPlayer: Render TsReader outputs
2013-08-12 19:16:22.433227 [Info.][MPMain(1)]: TSReaderPlayer: Cleanup Captions
2013-08-12 19:16:22.485315 [Info.][MPMain(1)]: TSReaderPlayer: OnInitialized
2013-08-12 19:16:22.485315 [Info.][MPMain(1)]: TSReaderPlayer: position:0, duration:1,1
2013-08-12 19:16:22.486317 [Info.][MPMain(1)]: g_Player.OnStarted() rtsp://WHS-Box:554/stream9.0 media:TV
2013-08-12 19:16:22.538405 [Warn.][MPMain(1)]: tvhome:startplay. Phase 2 - 1872 ms - Done starting g_Player.Play()
2013-08-12 19:16:22.547421 [Info.][MPMain(1)]: tv home initAT.1 done[/collapse]

Note we can see it took roughly 650 ms to tune on the server side so we can guess the hardware had to tune. Then we use a bunch of time adding renderers, codecs and TsReader. All up, it is 2.5 seconds.

Compare that with a change like this to VOX:
[collapse]2013-08-12 19:17:51.460316 [Info.][MPMain(1)]: TVHome.ViewChannelAndCheck(): View channel=VOX
2013-08-12 19:17:51.474340 [Info.][MPMain(1)]: TSReaderPlayerause graph
2013-08-12 19:17:51.499382 [Info.][MPMain(1)]: TSReaderPlayer: OnZapping :128
2013-08-12 19:17:51.681692 [Info.][MPMain(1)]: TSReaderPlayer: OnZapping :3
2013-08-12 19:17:51.682693 [Info.][MPMain(1)]: succeededucceeded TvControl.VirtualCard
2013-08-12 19:17:51.682693 [Info.][MPMain(1)]: tvhomeeektoEnd(89,4697709/89,537),True,rtsp=True
2013-08-12 19:17:51.683695 [Info.][MPMain(1)]: TsReaderPlayer:seekabs:895370000 start:0 end:895370000
2013-08-12 19:17:51.839960 [Info.][MPMain(1)]: TsReaderPlayer: pos: 895370000 start:0 end:895370000
2013-08-12 19:17:51.839960 [Info.][MPMain(1)]: TsReaderPlayer seek done:0
2013-08-12 19:17:51.840962 [Info.][MPMain(1)]: TSReaderPlayer: current pos:89,537 dur:89,537
2013-08-12 19:17:51.840962 [Info.][MPMain(1)]: TSReaderPlayer:Continue graph
2013-08-12 19:17:52.049316 [Info.][MPMain(1)]: TSReaderPlayer:OnRequestAudioChange()
2013-08-12 19:17:52.053322 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:17:52.054324 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:17:52.054324 [Info.][MPMain(1)]: Audio stream: switching to preferred AC3/MPEG audio stream 0 (only 1 track avail.)
2013-08-12 19:17:52.056327 [Info.][MPMain(1)]: TsReaderPlayer: AudioDualMonoMode switching not available. Audioswitcher filter not loaded
2013-08-12 19:17:52.451999 [Info.][MPMain(1)]: Rerendering audio pin of tsreader filter.
2013-08-12 19:17:52.453001 [Info.][MPMain(1)]: Disconnecting all pins from filter LAV Audio Decoder
2013-08-12 19:17:52.454002 [Info.][MPMain(1)]: Disconnecting pin Output
2013-08-12 19:17:52.454002 [Info.][MPMain(1)]: Disconnecting all pins from filter Default DirectSound Device
2013-08-12 19:17:52.456006 [Info.][MPMain(1)]: Added filter: LAV Audio Decoder to graph
2013-08-12 19:17:52.695412 [Info.][MPMain(1)]: Reconfigure graph done[/collapse]

It took approximately 200 ms for the server to do its thing, so we can tell the hardware did not have to tune.
Then the audio codec had to be reconfigured... but that is much faster than rebuilding the graph. All up, change time of 1.2 seconds or so.

So, not all channel changes can be directly compared because the work required for MP to change the channel varies.

mm

 

[aat]

This was a really good answer, should've been edited as a FAQ-note.

 

[Razorblade]

Thank you very much for that detailed explanation.

Which log-files do you need? I could not find your quotes in any of the log files So I don't know which files you need.

Attached you'll find the log of the server update to 1.4

Edit:
There's no improvement with a RAMdisk on the server.

 

[mm1352000]

Thank you very much for that detailed explanation.

No problem.

Which log-files do you need?

Basically I need MediaPortal 1.3 log files like you've supplied for MP 1.4. I start looking at timings in the MediaPortal.log (and MediaPortal.x.log), and depending on what I see I may need to look at the TVService.log (and TVService.x.log) and TsReader logs.

Unless you have old log files somewhere that were from before you upgraded the server then unfortunately the only way to produce such log files would be to downgrade the server (which would require uninstall and reinstall) and TV plugin on the client.

 

[Razorblade]

Unfortunately I don't have MediaPortal.log files from before the update, only TsReader.log files.

I think downgrading won't be worth the effort.
I'll update all my clients to the latest version within the next few days and then check the timings again.

Thank you very much for your help and your patience mm

 

[mm1352000]

Thank you very much for your help and your patience mm

No problem.
I'm sorry we haven't been able to get to the bottom of the problem, but I hope some of the info was at least helpful... and do let us know how you get on once the clients have been updated. I note that MP 1.5 PR is on the horizon...