Opened 13 years ago
Closed 13 years ago
#9503 closed Bug Report (Invalid)
Very sluggish UI during reschedules especially
Reported by: | Owned by: | ||
---|---|---|---|
Priority: | minor | Milestone: | unknown |
Component: | MythTV - General | Version: | 0.24-fixes |
Severity: | medium | Keywords: | |
Cc: | Ticket locked: | no |
Description (last modified by )
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:
- Start watching a recording on frontend
- On backend do: mythbackend --resched
- 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)
Change History (7)
Changed 13 years ago by
Attachment: | felog.txt.gz added |
---|
Changed 13 years ago by
Attachment: | version_info added |
---|
comment:2 Changed 13 years ago by
Status: | new → infoneeded_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 13 years ago by
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 13 years ago by
Resolution: | → Invalid |
---|---|
Status: | infoneeded_new → closed |
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.
frontend log