Re: Kaffeine problem with CFS

Christoph Pfister
2007-04-18T08:57:56Z

Hi,

2007/4/18, Ingo Molnar <mingo@elte.hu>:
>
> [ i've Cc:-ed Ulrich Drepper, this CFS-triggered hang seems to have some
> futex and pthread_cond_wait() relevance. ]
>
> * Christoph Pfister <christophpfister@gmail.com> wrote:
>
> > >> > [1] http://cekirdek.pardus.org.tr/~caglar/strace.kaffeine
> >
> > Could you try xine-ui or gxine? Because I suspect rather xine-lib for
> > freezing issues. In any way I think a gdb backtrace would be much
> > nicer - but if you can't reproduce the freeze issue with other xine
> > based players and want to run kaffeine in gdb, you need to execute
> > "gdb --args kaffeine --nofork".
>
> update: i've reproduced one kind of a hang but i'm not sure it's the
> same hang Ismail is seeing. It was quite hard to trigger it under CFS, i
> had to do wild forward/backward button seeks on a real DVD and i mixed
> it with CPU-intense workloads on the same box. Here are the straces and
> gdb backtraces:
>
> kaffeine thread PID 9303, waiting for other threads to do something,
> stuck in pthread_mutex_lock():
>
> futex(0xb07409e0, FUTEX_WAIT, 2, NULL <unfinished ...>
>
> backtrace:
>
> #0 0xffffe410 in __kernel_vsyscall ()
> #1 0x4a2538ce in __lll_mutex_lock_wait () from /lib/libpthread.so.0
> #2 0x4a24f71c in _L_mutex_lock_79 () from /lib/libpthread.so.0
> #3 0x4a24f24d in pthread_mutex_lock () from /lib/libpthread.so.0
> #4 0xb79f64f9 in xine_play () from /usr/lib/libxine.so.1
> #5 0xb7a9b0fb in KXineWidget::slotSeekToPosition () from /usr/lib/kde3/libxinepart.so
> #6 0xb7a9b3bc in KXineWidget::wheelEvent () from /usr/lib/kde3/libxinepart.so
> #7 0x4b5f9150 in QWidget::event () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #8 0x4b55353b in QApplication::internalNotify () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #9 0x4b55526e in QApplication::notify () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #10 0x4a72065e in KApplication::notify () from /usr/lib/libkdecore.so.4
> #11 0x4b4dd5de in QETWidget::translateWheelEvent () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #12 0x4b4eb41d in QETWidget::translateMouseEvent () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #13 0x4b4e9766 in QApplication::x11ProcessEvent () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #14 0x4b4fb38b in QEventLoop::processEvents () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #15 0x4b56ce30 in QEventLoop::enterLoop () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #16 0x4b56cce6 in QEventLoop::exec () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #17 0x4b55317f in QApplication::exec () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> #18 0x0806fc1a in QWidget::setUpdatesEnabled ()
> #19 0x49f9df10 in __libc_start_main () from /lib/libc.so.6
> #20 0x0806f7e1 in QWidget::setUpdatesEnabled ()
>
> Kaffeine thread 9324, seems to be in an infinite pthread_cond_wait()
> loop that does:
>
> futex(0xb0740b78, FUTEX_WAIT, 3559, NULL) = 0
> futex(0xb0740b5c, FUTEX_WAKE, 1) = 0
> munmap(0xaacb1000, 1662976) = 0
> mmap2(NULL, 1662976, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xaacb1000
> gettimeofday({1176891363, 347259}, NULL) = 0
> munmap(0xab309000, 1662976) = 0
>
> backtrace:
>
> #0 0xffffe410 in __kernel_vsyscall ()
> #1 0x4a2510c6 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
> #2 0xb79fd1a8 in QWidget::setUpdatesEnabled () from /usr/lib/libxine.so.1
> #3 0xb7a030ab in QWidget::setUpdatesEnabled () from /usr/lib/libxine.so.1
> #4 0x4a24d2db in start_thread () from /lib/libpthread.so.0
> #5 0x4a05820e in clone () from /lib/libc.so.6

This backtrace is useless - QWidget::setUpdatesEnabled() is certainly
_not_ defined in libxine. So the function names in #2 and #3 are wrong
because the addresses seem to belong to libxine.

> Kaffine thread 9325 does a loop of short pthread_cond_wait() futex
> sleeps:
>
> 1176891721.419314 futex(0xb07527e8, FUTEX_WAIT, 8537, NULL) = 0 <0.011710>
> 1176891721.431068 futex(0xb07527cc, FUTEX_WAKE, 1) = 0 <0.000006>
> 1176891721.431429 futex(0xb0740c04, 0x5 /* FUTEX_??? */, 1) = 1 <0.000008>
> 1176891721.431458 futex(0xb0740be8, FUTEX_WAKE, 1) = 1 <0.000012>
> 1176891721.431489 futex(0xb07527e8, FUTEX_WAIT, 8539, NULL) = 0 <0.007339>
> 1176891721.439008 futex(0xb07527cc, FUTEX_WAKE, 1) = 0 <0.000052>
> 1176891721.439510 futex(0xb0740c04, 0x5 /* FUTEX_??? */, 1) = 1 <0.000055>
> 1176891721.439636 futex(0xb0740be8, FUTEX_WAKE, 1) = 1 <0.000089>
> 1176891721.439789 futex(0xb07527e8, FUTEX_WAIT, 8541, NULL) = 0 <0.007045>
> 1176891721.447017 futex(0xb07527cc, FUTEX_WAKE, 1) = 0 <0.000054>
> 1176891721.447682 futex(0xb0740c04, 0x5 /* FUTEX_??? */, 1) = 1 <0.000065>
>
> backtrace:
>
> #0 0xffffe410 in __kernel_vsyscall ()
> #1 0x4a2510c6 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
> #2 0xb79fd1a8 in QWidget::setUpdatesEnabled () from /usr/lib/libxine.so.1
> #3 0xb7a04079 in QWidget::setUpdatesEnabled () from /usr/lib/libxine.so.1
> #4 0x4a24d2db in start_thread () from /lib/libpthread.so.0
> #5 0x4a05820e in clone () from /lib/libc.so.6

Dito.

> library versions:
>
> xine-lib-1.1.5-1.fc7
> xine-plugin-1.0-3.fc7
> glibc-headers-2.5.90-21
> glibc-common-2.5.90-21
> glibc-2.5.90-21
> glibc-devel-2.5.90-21
> gxine-0.5.11-3.fc7
> kaffeine-0.8.3-4.fc7
> xine-0.99.4-11.lvn7
> xine-lib-extras-1.1.5-1.fc7
> gxine-mozplugin-0.5.11-3.fc7
>
> what's weird is that all threads are in a pthread op and seem to be kind
> of busy-looping. Maybe xine-lib has some buggy use of pthread condvars
> that CFS happens to trigger? (If CFS broke futexes in general i think
> we'd be seeing far more widespread breakage.)
>
> Ingo

Christoph