[mythtv] [mythtv-commits] Ticket #2603: Prebuffering pause while realtime commflagging

[Chris Pinkham]

* On Wed Oct 25, 2006 at 06:39:23AM -0000, MythTV wrote:
> Changes (by thomas at boerkel.de):

>  Reopening and attaching more examples, where it can be seen better, that
>  it really seems to be related to the commflag update.
>  Also, in the first example, there is also something about "new
>  commBreakIter" and "AutoCommercialSkip()" around the prebuffering pause.
>  It really is a fact, that this happens only when watching with realtime
>  commflagging. I can watch a prerecorded show (from a day earlier) with no
>  problems, while the backend records and commflags 2 other shows.

What you left out is the fact that the show being watched while realtime
flagging is being run is being watched while it is being recorded.  The
prerecorded shows are... (pause for effect) prerecorded.  The 'live'
program will require the seektable to be loaded from the encoder while
the prerecorded program will have the whole seektable already in memory.

It looks like it's taking almost 2.5 seconds to update the seektable
from the encoder.

2006-10-19 22:04:52.582 Setting New Commercial Break List, old size 4, new 6
2006-10-19 22:04:52.582 NVP: new commBreakIter = 4 @ frame 53349
2006-10-19 22:04:52.589 Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(1)
2006-10-19 22:04:52.590 write -> 23 39      QUERY_RECORDER 4[]:[]GET_FRAMES_WRITTEN
2006-10-19 22:04:52.591 read  <- 23 11      0[]:[]89610
2006-10-19 22:04:52.592 Filling position map from 64117 to 89610
2006-10-19 22:04:52.592 write -> 23 58      QUERY_RECORDER 4[]:[]FILL_POSITION_MAP[]:[]64117[]:[]89610
2006-10-19 22:04:53.069 read  <- 23 78546   0[]:[]64128[]:[]0[]:[]1391785996[]:[]0[]:[]64140[]:[]0[]:[]139209...
2006-10-19 22:04:53.420 NVP: 37200 interlaced frames seen.
2006-10-19 22:04:53.740 NVP: prebuffering pause
2006-10-19 22:04:53.740 NVP: Waiting for prebuffer.. 0 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:53.919 NVP: Waiting for prebuffer.. 1 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.099 NVP: Waiting for prebuffer.. 2 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.279 NVP: Waiting for prebuffer.. 3 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.459 NVP: Waiting for prebuffer.. 4 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.639 NVP: Waiting for prebuffer.. 5 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.819 NVP: Waiting for prebuffer.. 6 AAAAAAAAAAAAAuaAALAAAAAAAAAAAAA
2006-10-19 22:04:54.964 Position map filled from Encoder to: 89610
2006-10-19 22:04:54.965 SyncPositionMap watchingrecording total: 7466 entries
2006-10-19 22:04:54.965 SyncPositionMap, new totframes: 89610, new length: 3584, posMap size: 7466

There was only one half second between the FILL_POSITION_MAP write and the
response from the encoder.  Then almost 2 full seconds between that and
the end of DecoderBase::PosMapFromEnc when it prints the "new totframes" line.

Can you sprinkle some VERBOSE calls inside various places in the
DecoderBase::PosMapFromEnc() method in libs/libmythtv/decoderbase.cpp and
try to reproduce the issue?  Something like the following VERBOSE is good
enough if you're running stock code and let me know what version you're
using.

VERBOSE(VB_PLAYBACK, QString("PosMapFromEnc: Line %1").arg(__LINE__));

Put those before and after the call to nvr_enc->FillPositionMap(start, end, posMap);
and then put a bunch more around the bottom of that method before and after
the m_positionMap.reserve() line and inside the for loop.

That should help see where the delay is and if it can be optimized.

--
Chris