Very sluggish UI during reschedules especially

[Mike Rice <mikerice1969@…>]

I am experiencing very sluggish UI on my frontend (backend on another machine). It happens frequently but I usually notice a problem when a reschedule is happening. For example if I am watching something at 2 minutes past the hour it may just pause playback for several seconds. After I delete a recording and am looking for the next in the playback box the UI may become unresponsive for several seconds. A fairly reliable way to reproduce it is as follows:

1. Start watching a recording on frontend
   
2. On backend do: mythbackend --resched
   
3. Pause/UnPause? a few times. Usually there is no response from an unpause for several seconds.
   

Here are log snippets from frontend and backend for one of these cases:

Annotated front end log snippets:

2011-01-22 15:39:02.065 Player(0): 2000 progressive frames seen.
'video_output' mean = '16664.54', std. dev. = '54.88', fps = '60.01'
'video_output' mean = '16665.06', std. dev. = '47.04', fps = '60.01'
'video_output' mean = '16664.17', std. dev. = '32.60', fps = '60.01'
2011-01-22 15:39:06.181 ScreenSaverX11Private: Calling xscreensaver-command -deactivate
2011-01-22 15:39:06.191 MythSocket(ffffffffb2214ed0:44): write -> 44 122     MESSAGE[]:[]SYSTEM_EVENT PLAY_PAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
2011-01-22 15:39:06.282 MythSocket(ffffffffb2214ed0:44): read  <- 44 2       OK
2011-01-22 15:39:06.283 UpdateOSDSeekMessage(Paused, 0)
2011-01-22 15:39:06.284 Player(0): Play speed: rate: 59.9401 speed: 0 skip: 0 => new interval 16683
2011-01-22 15:39:06.300 VideoOutputXv: UpdatePauseFrame() UUUUUUuUUuUUULUUUUUUUUUUUUUUUUU
2011-01-22 15:39:06.305 ScreenSaverX11Private: StopTimer
<<<>>>
<<<Unpaused after about 3 sec pause>>>
<<<>>>
2011-01-22 15:39:09.148 MythSocket(ffffffffb2214ed0:44): write -> 44 124     MESSAGE[]:[]SYSTEM_EVENT PLAY_UNPAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
<<<<>>>
<<<No response for 28 seconds>>
<<<>>>
2011-01-22 15:39:37.884 MythSocket(ffffffffb2214ed0:44): read  <- 44 2       OK
2011-01-22 15:39:37.884 Player(0): Play(  1.0, normal 1, unpause audio 1)
2011-01-22 15:39:37.884 UpdateOSDSeekMessage(Play, 2)
2011-01-22 15:39:37.885 Player(0): Play speed: rate: 59.9401 speed: 1 skip: 1 => new interval 16683
2011-01-22 15:39:37.885 Player(0): Stretch Factor 1, allow passthru

Annotated backend log snippets:

<<< OFirst pause >>>
<<<>>>
2011-01-22 15:39:06.189 MythSocket(99b24e0:47): read  <- 47 122     MESSAGE[]:[]SYSTEM_EVENT PLAY_PAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
2011-01-22 15:39:06.228 MythEvent: SYSTEM_EVENT PLAY_PAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
2011-01-22 15:39:06.254 MythSocket(99b24e0:47): write -> 47 2       OK
2011-01-22 15:39:06.254 MythSocket(9993d30:46): write -> 46 140     BACKEND_MESSAGE[]:[]SYSTEM_EVENT PLAY_PAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2[]:[]empty

<<<Unpaused after 3 seconds>>>
2011-01-22 15:39:09.145 MythSocket(99b24e0:47): read  <- 47 124     MESSAGE[]:[]SYSTEM_EVENT PLAY_UNPAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
<<< 12 seconds >>>
2011-01-22 15:39:22.256 MythEvent: SYSTEM_EVENT PLAY_UNPAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2
<<< 15 seconds >>>
2011-01-22 15:39:37.826 MythSocket(99b24e0:47): write -> 47 2       OK
2011-01-22 15:39:37.826 MythSocket(9993d30:46): write -> 46 142     BACKEND_MESSAGE[]:[]SYSTEM_EVENT PLAY_UNPAUSED HOSTNAME mythfrontend2 CHANID 5736 STARTTIME 2011-01-22T04:29:00 SENDER mythfrontend2[]:[]empty
2011-01-22 15:39:40.941 scheduler: Scheduled items: Scheduled 3550 items in 45.4 = 4.64 match + 40.78 place
2011-01-22 15:39:40.965 MythEvent: SYSTEM_EVENT SCHEDULER_RAN SENDER masterbackend

It seems the reschedule blocks processing and since my reschedule takes around 45 seconds it is really noticeable. I was ok though in 0.22 and I didn't see this problem until upgrading to 0.24.

I'll attach more complete logs to the ticket. I'd be happy to provide any other logs and assist in any means possible. The WAF is really taking a hit due to this.

[Mike Rice <mikerice1969@…>]

frontend log

[Mike Rice <mikerice1969@…>]

backend log