[mythtv] Streaming Prebuffering Pause

Blammo blammo.doh at gmail.com
Wed Feb 16 05:21:46 UTC 2005


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.


More information about the mythtv-dev mailing list