Some recordings put MythPlayer in a bad state where timestamp is wrong

[ggervasio]

I have been using master and starting a few months ago, some recordings seem to have a few bad frames(?) that cause MythPlayer? to get into a state where, among other things:

• video constantly stutters as if frames are skipped (audio is fine and in sync)
• player timestamp runs at half the correct rate (ie. timestamp OSD increments 1 second for every 2 seconds played). This causes seeks and bookmarks to behave incorrectly. Saving a bookmark at 10 minutes after the bad frame places it at 5 minutes after (which is what the timestamp shows).

It doesn't recover from this state. Exiting and restarting the player works fine until it hits another "bad frame".

So far, I have only noticed this behavior on some (not all) recordings of the local NBC affiliate (KNTV in the SF Bay Area) which broadcasts in 1080i MPEG-2.

I was able to find a recording where the problem happens almost from the start. The first 500MB and a log of "mythavtest -v playback,libav,timestamp" (based on git: 3d6f3e2e475322b462ac14cf9f0ca14a8e52aab8) have been uploaded here:

​https://filebin.net/tzd83eg4fj5xrc99

I'm guessing this is where it goes wrong -- MythPlayer::SetFrameRate/SetFrameInterval? is called to double the frame rate when there's a frame interval that's only 16ms (5381872 -> 5381888):

2018-10-10 23:30:37.673077 I  AFD: video timecode 484368500 5381872 5381872 5381838

2018-10-10 23:30:37.699914 I  Player(0): A/V timecodes audio 5380994 video 5380904 frameinterval 33367 avdel -7 avg -1113 tcoffset 0 avp 0 avpen 0 avdc -84334 diverge -0.0333563

2018-10-10 23:30:37.708173 I  Player(0): SetFrameInterval ps:1 scan:3
2018-10-10 23:30:37.708181 I  AFD: video timecode 484370001 5381888 5381888 5381872

2018-10-10 23:30:37.732172 I  Player(0): A/V timecodes audio 5381027 video 5380937 frameinterval 16683 avdel -8 avg -2251 tcoffset 0 avp 0 avpen 1 avdc -83240 diverge -0.0674619

I think this is the relevant section of AvFormatDecoder::ProcessVideoFrame?:

    // Calculate actual fps from the pts values.
    long long ptsdiff = temppts - lastvpts;
    double calcfps = 1000.0 / ptsdiff;
    if (calcfps < 121.0 && calcfps > 3.0)
    {
        // If fps has doubled due to frame-doubling deinterlace
        // Set fps to double value.
        double fpschange = calcfps / fps;
        int prior = fpsMultiplier;
        if (fpschange > 1.9 && fpschange < 2.1)
            fpsMultiplier = 2;
        if (fpschange > 0.4 && fpschange < 0.6)
            fpsMultiplier = 1;
        if (fpsMultiplier != prior)
            m_parent->SetFrameRate(fps);
    }

If I comment out this section, the problem goes away.

[ggervasio]

Sorry, I think I have a bad local edit. Please close this ticket.

[ggervasio]

(Ver sorry for the churn.) I have now reproduced the issue without my local edits. I have replaced the log in the filebin (​​https://filebin.net/tzd83eg4fj5xrc99) with one generated from git: 3d6f3e2e475322b462ac14cf9f0ca14a8e52aab8.

The original description is valid except the relevant lines in the log are now:

2018-10-11 03:03:44.345283 I  AFD: video timecode 484368500 5381872 5381872 5381838

2018-10-11 03:03:44.371258 I  Player(0): A/V timecodes audio 5380991 video 5380904 frameinterval 33367 avdel -12 avg -4879 tcoffset 0 avp 0 avpen 0 avdc -76424 diverge -0.146222

2018-10-11 03:03:44.380499 I  Player(0): SetFrameInterval ps:1 scan:3
2018-10-11 03:03:44.380505 I  AFD: video timecode 484370001 5381888 5381888 5381872

2018-10-11 03:03:44.405853 I  Player(0): A/V timecodes audio 5381025 video 5380937 frameinterval 16683 avdel -11 avg -6303 tcoffset 0 avp 0 avpen 1 avdc -77656 diverge -0.188899

[Peter Bennett]

Thank you for your excellent work in finding the place where the problem occurs. The bug is in the second test if (fpschange > 0.4 && fpschange < 0.6). It should be checking for a value near 1.0 (i.e. between 0.9 and 1.1). That is the code that should set the frame rate back to normal, which is not happening. I will commit the fix.

[Peter Bennett]

commit 1f66a73939819cf8de9bc3fb1428ad1fe18bdcc5 (HEAD -> master, origin/master) Author: Peter Bennett Date: Thu Oct 11 14:06:07 2018 -0400

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332

[Peter Bennett <pbennett@…>]

In 1f66a73939/mythtv:

Video playback: fix error in frame doubling check

An error in the check for doubled frame rate meant that it was not
resetting when doubling ends.

Fixes #13332