2009-05-18, 16:36
After compiling XBMC, both release tags, and latest out of SVN several times I have noticed the likely reason XBMC consumes 100%+ of one core when displaying it's GUI. This is also ruining the downstream project Boxee.
After these few calls, then sched_yield() as fast as the processor will run them (thousands of times a second) then another block like the above is executed.
I am rather sure this is the culprit. I suspect either a kernel change or a key library (libc?) change may be the reason. Eg, a call is made expecting it to block on something but instead results in sched_yield() being called repeatedly.
This is Ubunti 9.04, 64 bit system. Ubuntu server kernel installed.
I know you guys think that 32 bit targets are the main focus, however, 64 bit cpus are becoming pretty much cheap as snot and not all HTPC systems are low power.
Code:
[ 7f56a5677742] select(12, [11], [11], NULL, NULL) = 1 (out [11])
[ 7f56a567722c] writev(11, [{"\2\0\4\0\25\0\200\3\0@\0\0\23\0\200\3+\0\1\0"..., 20}, {NULL, 0}, {""..., 0}], 3) = 20
[ 7f56a5677742] select(12, [11], [], NULL, NULL) = 1 (in [11])
[ 7f56a5670f4b] read(11, "\1\1*\7\0\0\0\0\3\0\200\3\0\0\0\0000\372\240\1\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
[ 7f56a5670f4b] read(11, 0x1c85e44, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[ 7f56a5670f4b] read(11, 0x1c85e44, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[ 7f56a5677742] select(12, [11], NULL, NULL, {0, 0}) = 0 (Timeout)
[ 7f56a5670f4b] read(15, 0x7f569db5c000, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64234, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64236, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64238, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64240, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64242, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64244, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64246, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64248, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64250, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64252, ru_nivcsw=19063}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64254, ru_nivcsw=19063}) = 0
[ 7f56a5640d21] nanosleep({0, 0}, {0, 0}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34110, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64259, ru_nivcsw=19063}) = 0
[ 7f56a60f3c89] getpid() = 10468
[ 7f56a60f3c89] getpid() = 10468
[ 7f56a60f3c89] getpid() = 10468
[ 7f56a5670b5b] open("/proc/meminfo", O_RDONLY) = 22
[ 7f56a5670284] fstat(22, {st_dev=makedev(0, 3), st_ino=4026531984, st_mode=S_IFREG|0444, st_nlink=1, st_uid=0, st_gid=0, st_blksize=1024, st_blocks=0, st_size=0, st_atime=2009/05/17-16:28:24, st_mtime=2009/05/17-16:28:24, st_ctime=2009/05/17-16:28:24}) = 0
[ 7f56a567b8da] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f56ab95d000
[ 7f56a5670f4b] read(22, "MemTotal: 978628 kB\nMemFr"..., 1024) = 1024
[ 7f56a5670f4b] read(22, "12 kB\nDirectMap2M: 57344 kB"..., 1024) = 34
[ 7f56a5670f4b] read(22, ""..., 1024) = 0
[ 7f56a5670f4b] read(22, ""..., 1024) = 0
[ 7f56a5670ea0] close(22) = 0
[ 7f56a567b907] munmap(0x7f56ab95d000, 4096) = 0
[ 7f56a60f3c89] getpid() = 10468
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34111, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64288, ru_nivcsw=19064}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34111, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64290, ru_nivcsw=19064}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34111, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64292, ru_nivcsw=19064}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34111, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64294, ru_nivcsw=19064}) = 0
[ 7f56a5676687] getrusage(RUSAGE_SELF, {ru_utime={11, 40000}, ru_stime={28, 700000}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=34111, ru_majflt=66, ru_nswap=0, ru_inblock=11296, ru_oublock=3672, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=64296, ru_nivcsw=19064}) = 0
[ 7f56a60f3c89] getpid() = 10468
[ 7f56a5664c57] sched_yield() = 0After these few calls, then sched_yield() as fast as the processor will run them (thousands of times a second) then another block like the above is executed.
I am rather sure this is the culprit. I suspect either a kernel change or a key library (libc?) change may be the reason. Eg, a call is made expecting it to block on something but instead results in sched_yield() being called repeatedly.
This is Ubunti 9.04, 64 bit system. Ubuntu server kernel installed.
I know you guys think that 32 bit targets are the main focus, however, 64 bit cpus are becoming pretty much cheap as snot and not all HTPC systems are low power.
