[mythtv] Streaming Prebuffering Pause
Blammo
blammo.doh at gmail.com
Thu Feb 17 00:00:03 UTC 2005
On Tue, 15 Feb 2005 22:21:46 -0700, Blammo <blammo.doh at gmail.com> wrote:
> On Tue, 15 Feb 2005 22:09:18 -0700, Blammo <blammo.doh at gmail.com> wrote:
> > on Tue, 15 Feb 2005 09:23:16 -0800, Ian Forde <ian at duckland.org> wrote:
> > > On Tue, 2005-02-15 at 10:19 -0700, Blammo wrote:
> > > > I'm working on doing backtraces myself, but so far it isn't working
> > > > like the document suggests. I've done the recompile, gdb mythfrontend,
> > > > and run, and it never starts the front end. If someone can tell me
> > > > what I'm doing wrong, I'll happily post any backtraces I can.
> > >
> > > You can also start up mythfrontend normally, then attach to the running
> > > process with gdb.
> >
> > Ok, figured out how to do backtraces on a running process ( gdb -q -p
> > PROCESSID ) There's more than (1) thing causing these lockups. I'm
> > seeing them (see different thread) without XvMC as well.
> >
> > Here's my notes on the XvMC pause-lockup issue
> >
> > How to recreate:
> >
> > Enable XvMC
> > go playback any recorded video
> > pause,
> > unpause
> > watch log fill with "prebuffering" messages
> >
> > Here's the backtrace:
> >
> > (gdb) thread apply all bt full
> >
> > Thread 8 (Thread -1224512592 (LWP 8355)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb7036378 in ?? ()
> > No symbol table info available.
> > #2 0x00000003 in ?? ()
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 7 (Thread -1233052752 (LWP 8356)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb6811378 in ?? ()
> > No symbol table info available.
> > #2 0x00000064 in ?? ()
> > No symbol table info available.
> > #3 0x082690c8 in ?? ()
> > No symbol table info available.
> > #4 0x00c9550b in __read_nocancel () from /lib/tls/libpthread.so.0
> > No symbol table info available.
> > #5 0xb72c599b in lirc_nextcode (code=0xb68113e8) at lirc_client.c:1493
> > new_buffer = 0xfffffe00 <Address 0xfffffe00 out of bounds>
> > packet_size = 100
> > end_len = 0
> > len = -512
> > end = 0x0
> > c = 8 '\b'
> > #6 0xb755ece0 in LircClient::Process (this=0x81b0340) at lirc.cpp:67
> > code = 0x0
> > ir = 0x0
> > ret = 0
> > #7 0xb74fea2c in SpawnLirc (param=0x81b56c8) at mythdialogs.cpp:52
> > main_window = (MythMainWindow *) 0x81b56c8
> > config_file = {static null = {static null = <same as static
> > member of an already seen type>,
> > d = 0x81570c0, static shared_null = 0x81570c0}, d = 0x81b05f0,
> > static shared_null = 0x81570c0}
> > program = {static null = {static null = <same as static member
> > of an already seen type>,
> > d = 0x81570c0, static shared_null = 0x81570c0}, d = 0x81b05d8,
> > static shared_null = 0x81570c0}
> > cl = (class LircClient *) 0x81b0340
> > #8 0x00c903ae in start_thread () from /lib/tls/libpthread.so.0
> > ---Type <return> to continue, or q <return> to quit---
> > No symbol table info available.
> > #9 0x00b0fb6e in clone () from /lib/tls/libc.so.6
> > No symbol table info available.
> >
> > Thread 6 (Thread -1268888656 (LWP 8357)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb45e4338 in ?? ()
> > No symbol table info available.
> > #2 0xb7f10b40 in ?? () from /usr/local/lib/libmythtv-0.17.so.0
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 5 (Thread -1277404240 (LWP 8358)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb3dc5238 in ?? ()
> > No symbol table info available.
> > #2 0x00000c8d in ?? ()
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 4 (Thread -1285796944 (LWP 8359)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb35c4348 in ?? ()
> > No symbol table info available.
> > #2 0xb7f10b40 in ?? () from /usr/local/lib/libmythtv-0.17.so.0
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 3 (Thread -1307448400 (LWP 8360)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb211c298 in ?? ()
> > No symbol table info available.
> > #2 0xb75fd250 in ?? () from /usr/local/lib/libmyth-0.17.so.0
> > No symbol table info available.
> > ---Type <return> to continue, or q <return> to quit---
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 2 (Thread -1329869904 (LWP 8361)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xb0bbc378 in ?? ()
> > No symbol table info available.
> > #2 0x00000b2b in ?? ()
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > Thread 1 (Thread -1221854304 (LWP 8354)):
> > #0 0xffffe410 in ?? ()
> > No symbol table info available.
> > #1 0xbfffded8 in ?? ()
> > No symbol table info available.
> > #2 0x05a2efb0 in ?? () from /usr/lib/qt-3.3/lib/libqt-mt.so.3
> > No symbol table info available.
> > #3 0x00000000 in ?? ()
> > No symbol table info available.
> >
> > strace of hung process:
> > Process 8354 attached - interrupt to quit
> > setup() = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530408, 727334}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530408, 727408}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530408, 727578}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530408, 829444}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530408, 829516}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530408, 829676}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530408, 931256}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530408, 931328}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530408, 931489}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530408, 931603}, NULL) = 0
> > gettimeofday({1108530408, 931628}, NULL) = 0
> >
> > --- start of repeated block ---
> >
> > write(3, ";\3\5\0\24\0\300\1\0\0\0\0\260\0020\1\261\0e\0\235\6\5"..., 76) = 76
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530408, 931858}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530408, 931997}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 33239}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530409, 33312}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530409, 33484}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 135222}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530409, 135295}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530409, 135454}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 237200}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530409, 237271}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530409, 237434}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 339192}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530409, 339263}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530409, 339421}, NULL) = 0
> > nanosleep({0, 100000000}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 441166}, NULL) = 0
> > ioctl(3, FIONREAD, [0]) = 0
> > gettimeofday({1108530409, 441237}, NULL) = 0
> > select(16, [3 4 5 11 12 15], [], [], {0, 0}) = 1 (in [5], left {0, 0})
> > read(5, "\0", 1) = 1
> > gettimeofday({1108530409, 441395}, NULL) = 0
> > ioctl(5, FIONREAD, [0]) = 0
> > write(6, "\0", 1) = 1
> > gettimeofday({1108530409, 441508}, NULL) = 0
> > gettimeofday({1108530409, 441573}, NULL) = 0
> >
> > --- end of repeated block ---
> >
>
> Ok, I ran mythfrontend -v all and here's the snip from where I hit
> PLAY again, till it starts repeating the same message. Hopefully this
> gives a little bit more info about what's happening:
>
> We pause:
>
> 2005-02-15 22:14:59.566 OutputAudioLoop: audio paused
> 2005-02-15 22:14:59.566 5824 bytes free on soundcard
> 2005-02-15 22:14:59.570 6592 bytes free on soundcard
>
> [etc.etc.etc]
>
> 2005-02-15 22:15:02.587 61472 bytes free on soundcard
> 2005-02-15 22:15:02.591 58144 bytes free on soundcard
> 2005-02-15 22:15:02.595 58912 bytes free on soundcard
> 2005-02-15 22:15:02.599 59680 bytes free on soundcard
>
> We play:
>
> 2005-02-15 22:15:02.603 OutputAudioLoop: Play Event
>
> 2005-02-15 22:15:02.603 Broadcasting free space avail
> 2005-02-15 22:15:02.607 Broadcasting free space avail
> 2005-02-15 22:15:02.611 Broadcasting free space avail
> 2005-02-15 22:15:02.615 Broadcasting free space avail
> 2005-02-15 22:15:02.619 Broadcasting free space avail
> 2005-02-15 22:15:02.623 Broadcasting free space avail
> 2005-02-15 22:15:02.627 Broadcasting free space avail
> 2005-02-15 22:15:02.632 Broadcasting free space avail
> 2005-02-15 22:15:02.633 _AddSamples bytes=4608, used=1, free=511999,
> timecode=1441
> 2005-02-15 22:15:02.633 _AddSamples bytes=4608, used=4609,
> free=507391, timecode=1465
> 2005-02-15 22:15:02.636 Broadcasting free space avail
> 2005-02-15 22:15:02.636 Broadcasting free space avail
> 2005-02-15 22:15:02.636 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.636 Broadcasting free space avail
> 2005-02-15 22:15:02.640 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.640 Broadcasting free space avail
> 2005-02-15 22:15:02.644 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.644 Broadcasting free space avail
> 2005-02-15 22:15:02.648 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.648 Broadcasting free space avail
> 2005-02-15 22:15:02.652 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.652 Broadcasting free space avail
> 2005-02-15 22:15:02.656 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.656 Broadcasting free space avail
> 2005-02-15 22:15:02.660 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.660 Broadcasting free space avail
> 2005-02-15 22:15:02.664 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.664 Broadcasting free space avail
> 2005-02-15 22:15:02.668 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.668 Broadcasting free space avail
> 2005-02-15 22:15:02.672 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.672 Broadcasting free space avail
> 2005-02-15 22:15:02.676 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.676 Broadcasting free space avail
> 2005-02-15 22:15:02.680 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.680 Broadcasting free space avail
> 2005-02-15 22:15:02.684 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.684 Broadcasting free space avail
> 2005-02-15 22:15:02.688 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.688 Broadcasting free space avail
> 2005-02-15 22:15:02.692 audio waiting for buffer to fill: have 1024 want 4096
> 2005-02-15 22:15:02.692 Broadcasting free space avail
> 2005-02-15 22:15:02.695 _AddSamples bytes=4608, used=1025,
> free=510975, timecode=1489
> 2005-02-15 22:15:02.696 Broadcasting free space avail
> 2005-02-15 22:15:02.696 audio waiting for buffer to fill: have 1536 want 4096
> 2005-02-15 22:15:02.696 Broadcasting free space avail
> 2005-02-15 22:15:02.700 audio waiting for buffer to fill: have 1536 want 4096
> 2005-02-15 22:15:02.700 Broadcasting free space avail
> 2005-02-15 22:15:02.704 audio waiting for buffer to fill: have 1536 want 4096
> 2005-02-15 22:15:02.704 Broadcasting free space avail
> 2005-02-15 22:15:02.708 audio waiting for buffer to fill: have 1536 want 4096
> 2005-02-15 22:15:02.708 Broadcasting free space avail
> 2005-02-15 22:15:02.711 A/V diverged by -3.62282 frames, dropping
> frame to keep audio in sync
> 2005-02-15 22:15:02.711 A/V diverged by -4.20815 frames, dropping
> frame to keep audio in sync
> 2005-02-15 22:15:02.711 A/V diverged by -4.39987 frames, dropping
> frame to keep audio in sync
> 2005-02-15 22:15:02.711 A/V diverged by -4.28892 frames, dropping
> frame to keep audio in sync
> 2005-02-15 22:15:02.711 prebuffering pause
> 2005-02-15 22:15:02.711 waiting for prebuffer...
> 2005-02-15 22:15:02.712 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.712 64704 bytes free on soundcard
> 2005-02-15 22:15:02.716 61280 bytes free on soundcard
> 2005-02-15 22:15:02.720 62048 bytes free on soundcard
> 2005-02-15 22:15:02.723 _AddSamples bytes=4608, used=1537,
> free=510463, timecode=1513
> 2005-02-15 22:15:02.724 OutputAudioLoop: Play Event
> 2005-02-15 22:15:02.724 Broadcasting free space avail
> 2005-02-15 22:15:02.724 audio waiting for buffer to fill: have 2048 want 4096
> 2005-02-15 22:15:02.724 Broadcasting free space avail
> 2005-02-15 22:15:02.724 A/V diverged by -3.95846 frames, dropping
> frame to keep audio in sync
> 2005-02-15 22:15:02.724 prebuffering pause
> 2005-02-15 22:15:02.724 waiting for prebuffer...
> 2005-02-15 22:15:02.728 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.728 55392 bytes free on soundcard
> 2005-02-15 22:15:02.732 56160 bytes free on soundcard
> 2005-02-15 22:15:02.735 prebuffering pause
> 2005-02-15 22:15:02.735 waiting for prebuffer...
> 2005-02-15 22:15:02.736 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.736 56928 bytes free on soundcard
> 2005-02-15 22:15:02.740 57696 bytes free on soundcard
> 2005-02-15 22:15:02.744 58464 bytes free on soundcard
> 2005-02-15 22:15:02.746 prebuffering pause
> 2005-02-15 22:15:02.746 waiting for prebuffer...
> 2005-02-15 22:15:02.748 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.748 59232 bytes free on soundcard
> 2005-02-15 22:15:02.752 60000 bytes free on soundcard
> 2005-02-15 22:15:02.756 60768 bytes free on soundcard
> 2005-02-15 22:15:02.757 prebuffering pause
> 2005-02-15 22:15:02.757 waiting for prebuffer...
> 2005-02-15 22:15:02.760 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.760 61536 bytes free on soundcard
> 2005-02-15 22:15:02.764 58208 bytes free on soundcard
> 2005-02-15 22:15:02.768 OutputAudioLoop: Play Event
> 2005-02-15 22:15:02.768 audio waiting for buffer to fill: have 2048 want 4096
>
> This seems to be the loop repeating:
>
> 2005-02-15 22:15:02.856 OutputAudioLoop: Play Event
> 2005-02-15 22:15:02.856 audio waiting for buffer to fill: have 2048 want 4096
> 2005-02-15 22:15:02.856 Broadcasting free space avail
> 2005-02-15 22:15:02.856 prebuffering pause
> 2005-02-15 22:15:02.856 waiting for prebuffer...
> 2005-02-15 22:15:02.859 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.860 60256 bytes free on soundcard
> 2005-02-15 22:15:02.863 61024 bytes free on soundcard
> 2005-02-15 22:15:02.867 prebuffering pause
> 2005-02-15 22:15:02.867 waiting for prebuffer...
> 2005-02-15 22:15:02.867 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.868 61792 bytes free on soundcard
> 2005-02-15 22:15:02.872 58464 bytes free on soundcard
> 2005-02-15 22:15:02.875 59232 bytes free on soundcard
> 2005-02-15 22:15:02.878 prebuffering pause
> 2005-02-15 22:15:02.878 waiting for prebuffer...
> 2005-02-15 22:15:02.879 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.880 60000 bytes free on soundcard
> 2005-02-15 22:15:02.883 60768 bytes free on soundcard
> 2005-02-15 22:15:02.887 61536 bytes free on soundcard
> 2005-02-15 22:15:02.889 prebuffering pause
> 2005-02-15 22:15:02.889 waiting for prebuffer...
> 2005-02-15 22:15:02.891 OutputAudioLoop: audio paused
> 2005-02-15 22:15:02.892 58208 bytes free on soundcard
> 2005-02-15 22:15:02.895 58976 bytes free on soundcard
>
> Appears like it's a sound problem. I've turned off and on agressive
> buffering, updated to the latest Alsa drivers, latest Nvidia drivers,
> all to no avail.
>
What additional information can I provide to the devs to help diagnose
and resolve this issue?
More information about the mythtv-dev
mailing list