[mythtv-users] 'Wakeup' Delay on Idle Frontend

Wed Dec 23 01:02:15 UTC 2009

On Thu, Dec 10, 2009 at 2:59 PM, Jim Stichnoth <stichnot at gmail.com> wrote:
> On Thu, Dec 10, 2009 at 2:12 PM, Mark Garland
> <mythtvusers at markgarland.co.uk> wrote:
>> Hi all,
>>
>> I've been running 0.22-fixes out of the (K)Ubuntu repos for about a month
>> now and really like it.
>>
>> One thing I've noticed is that when my combined frontend/backend has been
>> left idle at the menu for some time (say overnight, or all day), when you
>> press a button on the remote (or keyboard) there is a 4-5 second delay
>> before the frontend responds.  Normally, things like up and down work
>> instantly, but changing between menu screens, especially going into "Watch
>> Recordings", gives the delay.
>>
>> I don't think it is a resource issue - the machine has plenty of RAM, has an
>> idle CPU, I can't hear any extensive harddisk accesses during the delay, and
>> the database is optimised nightly and was blank 4 weeks ago (compressed back
>> up size is <15mb).
>> I also don't remember this happening in 0.21-fixes.
>>
>> I'll have to do some more investigation (i.e. monitoring the disk/cpu)
>> before that first remote button push, but for the time being I wanted to ask
>> if anyone else was experiecing this, or whether it was a known bug?
>
> Try running this:
>
> strace -p<pid_of_mythfrontend> -tt -T -e trace=file > strace_out.txt 2>&1
>
> after the system has "cooled off" to capture the file system accesses
> and their timestamps while the system warms up again.  Repeat this
> (outputting to a different file) for a warmed-up system.  See if there
> are any big jumps in the timestamps versus a fairly smooth transition.
>
> I see the same behavior on my frontends.  They are diskless ION boxes,
> so I was assuming it was an NFS issue and I have been slowly trying to
> migrate the relevant files (theme graphics, image caches) into a
> ramdisk, but the delays are still there.  Interesting to hear that the
> same behavior shows up with a hard disk.  My strace output shows that
> with the Blue Abstract theme, there are over 2000 file accesses to
> draw the Watch Recordings page, with many of the files being queried
> lots of times (200 in at least one case).

I think I found the source of this delay.  I caught one of these
delays while running strace:

strace -p<pid_of_mythfrontend> -tt -T

Here is the relevant section of the strace output:

14:50:09.650126 ioctl(55, FIONREAD, [18]) = 0 <0.000026>
14:50:09.650256 read(55, "jump playbackbox\r\n"..., 4114) = 18 <0.000029>
14:50:09.650530 futex(0xb009870c, FUTEX_WAKE_OP_PRIVATE, 1, 1,
0xb0098708, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000032>
14:50:09.650654 futex(0xb00986f0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000027>
14:50:09.650752 futex(0xb00db0ec, FUTEX_WAKE_OP_PRIVATE, 1, 1,
0xb00db0e8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000027>
14:50:09.650852 futex(0xb00db0d0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000027>
14:50:09.650987 clock_gettime(CLOCK_MONOTONIC, {404822, 149927091}) =
0 <0.000027>
14:50:09.651139 read(8, 0x8d2fb4c, 4096) = -1 EAGAIN (Resource
temporarily unavailable) <0.000024>
14:50:09.651253 read(17, 0x8d5e224, 4096) = -1 EAGAIN (Resource
temporarily unavailable) <0.000022>
14:50:09.651351 poll([{fd=4, events=POLLIN}, {fd=12,
events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=15,
events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17,
events=POLLIN}, {fd=8, events=POLLIN}, {fd=20, events=POLLIN}, {fd=43,
events=POLLIN}, {fd=55, events=POLLIN}], 10, 6) = 1 ([{fd=4,
revents=POLLIN}]) <0.000031>
14:50:09.651612 read(4, "A"..., 1)      = 1 <0.000025>
14:50:09.651713 clock_gettime(CLOCK_MONOTONIC, {404822, 150639705}) =
0 <0.000020>
14:50:09.651808 read(8, 0x8d2fb4c, 4096) = -1 EAGAIN (Resource
temporarily unavailable) <0.000022>
14:50:09.652165 gettimeofday({1261522209, 652205}, NULL) = 0 <0.000022>
14:50:09.652319 poll([{fd=29, events=POLLIN|POLLPRI}], 1, 0) = 0
(Timeout) <0.000024>
14:50:09.652424 write(29, "\1\0\0\0\1"..., 5) = 5 <0.000104>
14:50:09.652692 shutdown(29, 2 /* send and receive */) = 0 <0.000048>
14:50:09.652847 close(29)               = 0 <0.000045>
14:50:09.653006 gettimeofday({1261522209, 653035}, NULL) = 0 <0.000020>
14:50:09.653099 clock_gettime(CLOCK_REALTIME, {1261522209, 653147555})
= 0 <0.000021>
14:50:09.653211 futex(0xb36fd724, FUTEX_WAIT_PRIVATE, 1, {4,
999887445}) = -1 ETIMEDOUT (Connection timed out) <4.999998>
14:50:14.653353 write(2, "Error in my_thread_global_end(): "..., 55) =
55 <0.000035>
14:50:14.653499 futex(0xb36fd768, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000020>
14:50:14.653685 clone(child_stack=0xa74ff3e4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0xa74ffbd8, {entry_number:6, base_addr:0xa74ffb90,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
limit_in_pages:1, seg_not_present:0, useable:1},
child_tidptr=0xa74ffbd8) = 26877 <0.000058>
14:50:14.653883 rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTART}, {0x1,
[PIPE], SA_RESTART}, 8) = 0 <0.000025>
14:50:14.654052 gettimeofday({1261522214, 654081}, NULL) = 0 <0.000020>
14:50:14.654206 gettimeofday({1261522214, 654236}, NULL) = 0 <0.000025>
14:50:14.654388 write(1, "2009-12-22 14:50:14.654 New DB co"..., 52) =
52 <0.000030>
14:50:14.654584 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 29 <0.000042>
14:50:14.654727 fcntl64(29, F_SETFL, O_RDONLY) = 0 <0.000021>
14:50:14.654823 fcntl64(29, F_GETFL)    = 0x2 (flags O_RDWR) <0.000019>
14:50:14.654930 connect(29, {sa_family=AF_INET, sin_port=htons(3306),
sin_addr=inet_addr("192.168.0.205")}, 16) = 0 <0.000515>

Note the 5 second delay waiting on a lock while nothing else happens,
after which this message is written to the log:

Error in my_thread_global_end(): 3 threads didn't exit

and then a new connection to the database is initiated.

A web search on this error message suggests that it is an application
problem related to Qt, MySQL, and thread creation/destruction.  My
frontend system has mysql 5.0.67 and qt 4.5.2 installed, for what it's
worth.

Any ideas on this, before I give up and open a ticket?

Jim