Progress bar "lost" after skipping about 3 times

[hondansx]

@ hondansx
it is unlikely that the demuxerts code is making something.
I suspect, that at the endit will hang at putting it to the stream.

I am sorry but I am afraid, that you have to do the same inside demuxerts (I suspect submitpacket and  then in the end putting it to the stream).

Marten

What I can tell is, that in the end it jumps to DemuxerTS::processTS into the payload section (while olders do not) to parseTSPacketDetails and it looks like it will hang in

Code Select Expand


   ULLONG pts_expected = me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
      while (pts_expected > (1LL<<33)) pts_expected -= (1LL<<33);


And no I am stuck and do not know what I can do..

@Marten
Would it be okay for you, to send you this file?

[davep]

First impression is that the latest git fixes my hanging problem. Maybe there are some other quirks but we can fix those later.

Many thanks, and well done.

Dave

[laz]

I've not had that much time to do my own debugging on this but I've been following this closely. I've just checked out from git and rebuilt.

My first impressions was that skipping forward and back by a minute was now working all the time. However, I still have some problems with it.

It seems to work properly a lot more of the time than it did before. The sequence I see is:
- press remote button:
a. screen goes black
b. blank progress bar appears with "-:-- -:--" for the position and length
c. video starts
d. yellow progress bar and position and length appear
e. OSD times out and status bar disappears

Normally this happens pretty quickly. A few times (and this has happened as the first time I skip on starting playback or after several skips) "d" never happens and the OSD disappears before the times or yellow progress bar appear. If I press "OK" to show the progress bar, it remains blank with the dashes instead of times.

If I try to skip again after this has happened, only steps "b" and "e" seem to happen, i.e. it displays the blank progress bar (with the >>| icon) which then times out and no skipping occurs. If I pause, the blanks status bar is shown.

If I skip a few more times, it becomes unresponsive and I eventually need to use "kill -KILL" to kill vompclient. If I stop playback after the failed skip and then resume, the resume position is a minute forwards.

This behaviour seems worse with some recordings than others. I had a feeling it might be where I'm skipping from "within programme" to "within advert" or vice versa and there is a change in audio format, bitrate, or something that is tripping up the audio or video decoder. I think I've just disproved that theory, though!

I have found one of my recordings that seems to cause a blank status bar and not skip after skipping 4-5 times. I'll produce some debug output and see if there's anything obvious.

Laz

[MartenR]

@hondansx

@Marten
Would it be okay for you, to send you this file?

Depends, how big is it?

Can you please make a log of pts_expected?
I have the feeling, that if I now the number I can fix it.
(Btw. if it really hangs there, the bug should be there also on mvp).

@laz
The -:-- thing is probably related to a bug in obtaining the time from the videoomx object, which empties the database of pts entries. (Anyway it recovers after a while)
For the hang I need to have information where the hang occurs, because it can be really anywhere in the code. (and it does not hang on my machine)


Marten

[hondansx]

Can you please make a log of pts_expected?
I have the feeling, that if I now the number I can fix it.
(Btw. if it really hangs there, the bug should be there also on mvp).

Yes, this happens on my mvp.
This is the output, which runs since 30 min. ;-).

Code Select Expand


demuxerts.cc:
while (pts_expected > (1LL<<33)) {
    Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu 1LL: %llu", pts_expected, (1LL<<33));
    pts_expected -= (1LL<<33);
}


Code Select Expand


10:03:52.898206 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961601221124321 1LL: 8589934592
10:03:52.898461 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961592631189729 1LL: 8589934592
10:03:52.898717 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961584041255137 1LL: 8589934592
10:03:52.898973 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961575451320545 1LL: 8589934592
10:03:52.899229 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961566861385953 1LL: 8589934592
10:03:52.899483 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961558271451361 1LL: 8589934592
10:03:52.899739 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961549681516769 1LL: 8589934592
10:03:52.899994 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961541091582177 1LL: 8589934592
10:03:52.900249 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961532501647585 1LL: 8589934592
10:03:52.900505 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961523911712993 1LL: 8589934592
10:03:52.900761 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961515321778401 1LL: 8589934592
10:03:52.901016 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961506731843809 1LL: 8589934592
10:03:52.901272 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961498141909217 1LL: 8589934592
10:03:52.901527 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961489551974625 1LL: 8589934592
10:03:52.901782 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961480962040033 1LL: 8589934592
10:03:52.902149 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961472372105441 1LL: 8589934592
10:03:52.902425 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961463782170849 1LL: 8589934592
10:03:52.902680 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961455192236257 1LL: 8589934592
10:03:52.902935 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961446602301665 1LL: 8589934592
10:03:52.903190 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961438012367073 1LL: 8589934592
10:03:52.903492 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961429422432481 1LL: 8589934592
10:03:52.903755 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961420832497889 1LL: 8589934592
10:03:52.904011 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961412242563297 1LL: 8589934592
10:03:52.904267 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961403652628705 1LL: 8589934592
10:03:52.904524 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961395062694113 1LL: 8589934592
10:03:52.904779 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961386472759521 1LL: 8589934592
10:03:52.905035 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961377882824929 1LL: 8589934592
10:03:52.905291 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961369292890337 1LL: 8589934592
10:03:52.905547 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961360702955745 1LL: 8589934592
10:03:52.905803 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961352113021153 1LL: 8589934592
10:03:52.906059 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961343523086561 1LL: 8589934592
10:03:52.906315 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961334933151969 1LL: 8589934592
10:03:52.906571 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961326343217377 1LL: 8589934592
10:03:52.906827 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961317753282785 1LL: 8589934592
10:03:52.907084 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961309163348193 1LL: 8589934592
10:03:52.907342 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961300573413601 1LL: 8589934592
10:03:52.907599 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961291983479009 1LL: 8589934592
10:03:52.907855 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961283393544417 1LL: 8589934592
10:03:52.908112 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961274803609825 1LL: 8589934592
10:03:52.908369 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961266213675233 1LL: 8589934592
10:03:52.908625 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961257623740641 1LL: 8589934592
10:03:52.908881 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961249033806049 1LL: 8589934592
10:03:52.909137 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961240443871457 1LL: 8589934592
10:03:52.909394 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961231853936865 1LL: 8589934592
10:03:52.909649 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961223264002273 1LL: 8589934592
10:03:52.909906 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961214674067681 1LL: 8589934592
10:03:52.910163 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961206084133089 1LL: 8589934592
10:03:52.910420 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961197494198497 1LL: 8589934592
10:03:52.910675 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961188904263905 1LL: 8589934592
10:03:52.910932 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961180314329313 1LL: 8589934592
10:03:52.911187 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961171724394721 1LL: 8589934592
10:03:52.911443 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961163134460129 1LL: 8589934592
10:03:52.911700 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961154544525537 1LL: 8589934592
10:03:52.911956 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961145954590945 1LL: 8589934592
10:03:52.912316 [debug]  170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961137364656353 1LL: 8589934592


[MartenR]

I need the first line that occurs of parseTSpacketsdetails.
It seems that it is out of bounds.
The question is why...

Marten

[hondansx]

Good:

Code Select Expand


10:14:50.710182 [debug]  241 Demuxer - Entering audio sync: Video PTS = 120954145
10:14:50.710429 [debug]  241 Demuxer - Entering audio sync: Audio PTS = 120887173
10:14:50.713508 [debug]  241 DemuxerTS - parseTSPacketDetails pts_expected: 8710867137 1LL: 8589934592
10:14:50.714225 [debug]  241 Demux - START packet_type à 224
10:14:50.715185 [debug]  241 Demux - END sent: 34852 packet.getSize: 34852



Bad:

Code Select Expand


10:14:56.801418 [debug]  264 Demuxer - Entering audio sync: Video PTS = 8548456737
10:14:56.801668 [debug]  264 Demuxer - Entering audio sync: Audio PTS = 0
10:14:56.805154 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744073668019761 1LL: 8589934592
10:14:56.805411 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744065078085169 1LL: 8589934592
10:14:56.805664 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744056488150577 1LL: 8589934592
10:14:56.805917 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744047898215985 1LL: 8589934592
10:14:56.806171 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744039308281393 1LL: 8589934592
10:14:56.806426 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744030718346801 1LL: 8589934592
10:14:56.806680 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744022128412209 1LL: 8589934592
10:14:56.806933 [debug]  264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744013538477617 1LL: 8589934592
/code]

[MartenR]

Sorry to bother you again, I need the values of all variables in the expression:

Code Select Expand

me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
It seems like an signed unsigned mismatch.

[hondansx]

Sorry to bother you again, I need the values of all variables in the expression:

Code Select Expand

me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
It seems like an signed unsigned mismatch.

Doesn't matter.
Is this the right thing?

Code Select Expand


ULLONG pts_expected = me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %i frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu tfps: %f", pts_expected, tfps);
while (pts_expected > (1LL<<33)) {
        Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu 1LL: %llu", pts_expected, (1LL<<33))
        pts_expected -= (1LL<<33);
}   


[MartenR]

Yes this is the right thing one log line of the first occurence should show me, what is happening.

Marten

P.S: @laz the -:-- issue should be solved by latest git

[hondansx]

Next try.

[MartenR]

@hondansx
We coming close, the frame number is a problem. It is too big.
Please print before

Code Select Expand

if (frameCounting && numpicts &&
      packet.getPacketType() >= PESTYPE_VID0 &&
      packet.getPacketType() <= PESTYPE_VIDMAX)
the content of frameNumber and  numpicts.
Either frameNumber or numpicts are making trouble.

Marten

[laz]

Your recent git update (Fix invalid time) does seem at first sight to have fixed the problem I had with skipping. I've only had a quick test so far, skipping minute-wise (or 10-s wise) back and forth about half an hour into a film and it seems pretty resilient. Even repeatedly pressing skip as fast as I could didn't cause it to hang. This recording is one that always caused a hang after a 4-5 skips before this.



I'll stop being careful with how rapidly I skip and test some more...

Laz

[hondansx]

@hondansx
We coming close, the frame number is a problem. It is too big.
Please print before

Code Select Expand

if (frameCounting && numpicts &&
      packet.getPacketType() >= PESTYPE_VID0 &&
      packet.getPacketType() <= PESTYPE_VIDMAX)
the content of frameNumber and  numpicts.
Either frameNumber or numpicts are making trouble.

Marten

New log

[MartenR]

@hondansx
Thanks for being patient.

I just recognized that part of your debug code is wrong.
Can you please change

Code Select Expand

Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %i frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
to

Code Select Expand

Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %ulld frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
Note, that frame num is long long.
Sorry, I should have spotted that earlier.

Marten

Marten