[mythtv-commits] Ticket #9511: [patch] avformat decoder buffer underrun (DVB livetv)
MythTV
noreply at mythtv.org
Thu Jan 27 08:22:48 UTC 2011
#9511: [patch] avformat decoder buffer underrun (DVB livetv)
-------------------------------------------------+-------------------------
Reporter: Jiri Fojtasek <jiri.fojtasek@…> | Owner: janne
Type: Bug Report | Status: new
Priority: critical | Milestone: unknown
Component: MythTV - Video Playback | Version: Trunk
Severity: high | Head
Keywords: | Resolution:
| Ticket locked: 0
-------------------------------------------------+-------------------------
Comment (by Jiri Fojtasek <jiri.fojtasek@…>):
The problem with decoder eof is cause by race condition between
ringbuffer,decoder,and player thread. Here is part of log showing this
race with my comments:
{{{
# Ringbuffer thread detecting end of file and invoking switchtoprogram
2011-01-20 23:50:01.484
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
safe_read(... at 2549768, 1048576) -> 0
2011-01-20 23:50:01.485
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg): @ end of read
ahead loop
2011-01-20 23:50:01.485
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
ReadPriv(..32768, normal) -- copying data
2011-01-20 23:50:01.485
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
ReadPriv(..32768, normal) -- checksum 38247
# Decoder thread reading remained portion of data in ringbuffer and
waiting in RingBuffer::WaitForAvail(). The race condition begin ...
2011-01-20 23:50:01.491
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
ReadPriv(..6136, normal) @2549768 -- begin
# Player thread jumping in to switch to program (sz=0KB so buffer is
drained)
2011-01-20 23:50:01.509
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
IsReallyNearEnd() br(468KB) sz(0KB) vfl(28) frh(0) ne:1
2011-01-20 23:50:01.509 Player(0): SwitchToProgram - start
# Player thread stopping ringbuffer reading, and decoder thread still
waiting in RingBuffer::WaitForAvail()
2011-01-20 23:50:01.618 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:01.718 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:01.818 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:01.918 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.022 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.122 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.222 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.322 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.423 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.490
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg): @ end of read
ahead loop
2011-01-20 23:50:02.523 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.623 Player(0), Warning: Waited 100ms for decoder to
pause
2011-01-20 23:50:02.723 Player(0), Warning: Waited 100ms for decoder to
pause
# Decoder thread waiting in RingBuffer::WaitForAvail() timeouted and
entered eof state, decoder thread was finally stopped
# After this the decoder will not decode anything anymore ...
2011-01-20 23:50:02.740
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
ReadPriv(..6136, normal): ReadBufAvail() == 0
2011-01-20 23:50:02.748
RingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg): @ end of read
ahead loop
#Player thread opening next file, but decoder is dead
2011-01-20 23:50:02.778
FileRingBuf(/var/spool/mythtv/livetv/9008_20110120234837.mpg):
OpenFile(/var/spool/mythtv/livetv/9008_20110120235000.mpg, 2000 ms)
2011-01-20 23:50:02.801
FileRingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg): OpenFile()
made 1 attempts in 23 ms
2011-01-20 23:50:02.801 Player(0): SwitchToProgram(void) discont: 0
newtype: 0 newid: 2 eof: 0
2011-01-20 23:50:02.801
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 2549768, 1048576) -- begin
2011-01-20 23:50:02.923
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 2549768, 1048576) -> 549336
2011-01-20 23:50:02.924 Player(0): SwitchToProgram - end
2011-01-20 23:50:02.928
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg): @ end of read
ahead loop
2011-01-20 23:50:02.934
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 3099104, 1048576) -- begin
2011-01-20 23:50:02.971 Player(0): LiveTV forcing JumpTo 1
#Decoder thread has been set eof, so jumtoprogram trying switch file, but
it will not work because decoder is dead
2011-01-20 23:50:02.982 Player(0): JumpToProgram - start
2011-01-20 23:50:03.044 Waiting on select..
2011-01-20 23:50:03.047 Waiting on select..
2011-01-20 23:50:03.054
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 3099104, 1048576) -> 72944
2011-01-20 23:50:03.054
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg): @ end of read
ahead loop
2011-01-20 23:50:03.081 Waiting on select..
2011-01-20 23:50:03.083
FileRingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
OpenFile(/var/spool/mythtv/livetv/9008_20110120235000.mpg, 2000 ms)
2011-01-20 23:50:03.086
FileRingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg): OpenFile()
made 1 attempts in 3 ms
2011-01-20 23:50:03.086
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 0, 1048576) -- begin
2011-01-20 23:50:03.127 Waiting on select..
2011-01-20 23:50:03.148
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 0, 1048576) -> 622280
2011-01-20 23:50:03.148
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg): @ end of read
ahead loop
2011-01-20 23:50:03.153
RingBuf(/var/spool/mythtv/livetv/9008_20110120235000.mpg):
safe_read(... at 622280, 1048576) -- begin
2011-01-20 23:50:03.166 Player(0): JumpToProgram - end
2011-01-20 23:50:03.166 Player(0): Waiting for video buffers...
# Player start spaming that waiting for buffers but will not got em. This
will do until playback die and
# error message "Buffers failed ..." show
2011-01-20 23:50:03.269 Player(0): Waited 100ms for video buffers
AAAAAAAAAAAAAAAAAAAAAAAAAAAaAaL
}}}
This is the most worse scenario, but sometimes decoder set eof before
player stop decoder to drain ringbuffer. Then stopping decoder timeout
messages will not popup, but the rest is the same.
The attached v2 patch changes:
- Open file is called before player thread try stop decoder thread to
ensure decoder will finish reading from ringbuffer and/or new playback
file during trying to pause.
- Ringbuffer logic has been adjusted to deal with this change, some dead
code that trying to hide (not solve) this problem has been removed. Most
notable change is than decoder will wait in RingBuffer::WaitForAvail()
until ringbuffer thread fill requested data.
- This patch not changing other pause/unpause logic whish can be removed
in future.
After this change remaining portion of the dead code can be removed, but
its not mandatory in current state. After this issue will be fixed in
trunk ill post batch of fixes targeting other major playback issues i have
found during this investigation.
Also i will be pleasured if Mark Kendal will include in his commits
references to ticket from where he picked code changes.
Jiri
--
Ticket URL: <http://code.mythtv.org/trac/ticket/9511#comment:8>
MythTV <http://code.mythtv.org/trac>
MythTV Media Center
More information about the mythtv-commits
mailing list