Opened 9 years ago

Closed 9 years ago

#9503 closed Bug Report (Invalid)

Very sluggish UI during reschedules especially

Reported by: Mike Rice <mikerice1969@…> Owned by:
Priority: minor Milestone: unknown
Component: MythTV - General Version: 0.24-fixes
Severity: medium Keywords:
Cc: Ticket locked: no

Description (last modified by Raymond Wagner)

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.

Attachments (3)

felog.txt.gz (81.9 KB) - added by Mike Rice <mikerice1969@…> 9 years ago.
frontend log
belog.txt.gz (2.6 KB) - added by Mike Rice <mikerice1969@…> 9 years ago.
backend log
version_info (675 bytes) - added by Raymond Wagner 9 years ago.

Download all attachments as: .zip

Change History (7)

Changed 9 years ago by Mike Rice <mikerice1969@…>

Attachment: felog.txt.gz added

frontend log

Changed 9 years ago by Mike Rice <mikerice1969@…>

Attachment: belog.txt.gz added

backend log

comment:1 Changed 9 years ago by Raymond Wagner

Description: modified (diff)

Changed 9 years ago by Raymond Wagner

Attachment: version_info added

comment:2 Changed 9 years ago by stuartm

Status: newinfoneeded_new

I cannot reproduce this at all and I wonder if this wasn't the same issue I recently fixed in master/0.24-fixes.

Mike are you able to reproduce this with the latest 0.24-fixes?

comment:3 Changed 9 years ago by mikerice1969@…

You can close this. I posted this on the dev-list awhile back when I resolved the issue:

Checking my old logs (before updating to Fedora 14/MythTV 0.24) I found that the schedule was taking 20-25 seconds. After the update it is taking 40-45 seconds.

So I swapped out the 667MHz 1G with the 800MHz 2G DIMMs from the bedroom frontend and that cut the query down to 20 seconds again.

I also moved the database off the system drive but that didn't seem to affect the query time much.

Not sure if the memory usage of MythTV increased or something else in Fedora14 but the problem seems to be gone with the added memory.

comment:4 Changed 9 years ago by stuartm

Resolution: Invalid
Status: infoneeded_newclosed

Reschedules shouldn't be affecting the frontend unless as you suggest it was an outside factor like disk I/O, but since you can't reproduce it anymore we can't debug any further. FWIW, 20 seconds is still pretty long for a reschedule, I'm going to assume that it's a slow CPU.

Note: See TracTickets for help on using tickets.