Opened 9 years ago

Closed 9 years ago

Last modified 9 years ago

#8875 closed defect (fixed)

av-sync lost

Reported by: Markus Schulz <msc@…> Owned by: tralph
Priority: minor Milestone: 0.24
Component: MythTV - Video Playback Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

i have several files where the a/v-sync is lost after a specific time. first it plays fine at 25fps, but after a while it plays at ~ 24fps.

problem is repeatable and looks like the following:

2010-09-06 20:18:13.545 Player(1): 3200 progressive frames seen. 'video_output' mean = '39993.97', std. dev. = '8350.67', fps = '25.00' .... 2010-09-06 20:19:17.760 Player(1): 4800 progressive frames seen. 'video_output' mean = '39993.67', std. dev. = '8353.26', fps = '25.00' 'video_output' mean = '39794.86', std. dev. = '8087.57', fps = '25.13' 'video_output' mean = '40193.94', std. dev. = '8132.71', fps = '24.88' 'video_output' mean = '39794.50', std. dev. = '8565.80', fps = '25.13' 2010-09-06 20:19:33.758 Player(1): 5200 progressive frames seen. 'video_output' mean = '39993.93', std. dev. = '8341.60', fps = '25.00' 'video_output' mean = '40394.90', std. dev. = '7948.29', fps = '24.76' 'video_output' mean = '40994.26', std. dev. = '7113.72', fps = '24.39' 'video_output' mean = '41027.35', std. dev. = '7165.15', fps = '24.37' .... 2010-09-06 20:20:06.495 Player(1): 6000 progressive frames seen. 'video_output' mean = '40994.79', std. dev. = '7191.47', fps = '24.39' 'video_output' mean = '40993.81', std. dev. = '6995.66', fps = '24.39' 'video_output' mean = '40994.08', std. dev. = '7175.92', fps = '24.39' 'video_output' mean = '40995.28', std. dev. = '7108.31', fps = '24.39'

after a seek it works for a short while again but lost sync again. with mplayer the files are working.

i've attached a log where i played it twice and after lost sync the second time i do a short forward seek.

perhaps it has something todo with the following log-output (haven't checked all other async files for these message) a short time before it goes async the first time:

2010-09-06 20:18:45.522 Player(1): 4000 progressive frames seen. 'video_output' mean = '39994.54', std. dev. = '8318.48', fps = '25.00' 2010-09-06 20:18:45.923 [mpeg4 @ 0xb6701fa0]frame skip 8 2010-09-06 20:18:45.923 [mpeg4 @ 0xb6701fa0]frame skip 8 2010-09-06 20:18:46.522 [mpeg4 @ 0xb6701fa0]frame skip 8 2010-09-06 20:18:46.523 [mpeg4 @ 0xb6701fa0]frame skip 8

with mplayer there was a similar message but no av-sync loss: VO: [xv] 624x352 => 624x352 Planar YV12 [ASPECT] Warning: No suitable new res found! [mpeg4 @ 0x8a1e100]frame skip 8t: -0.056 4044/4044 10% 0% 2.2% 9 0 [mpeg4 @ 0x8a1e100]frame skip 8t: -0.056 4060/4060 10% 0% 2.2% 9 0 [mpeg4 @ 0x8a1e100]frame skip 8t: -0.056 28460/28460 10% 0% 2.3% 13 0 [mpeg4 @ 0x8a1e100]frame skip 8t: -0.056 28461/28461 10% 0% 2.3% 13 0 A:1240.5 V:1240.6 A-V: -0.136 ct: -0.074 31016/31016 10% 0% 2.3% 13 0

Attachments (2)

sync_problem.log (53.5 KB) - added by Markus Schulz <msc@…> 9 years ago.
frontend_avi_problem.log.gz (221.3 KB) - added by Markus Schulz <msc@…> 9 years ago.

Download all attachments as: .zip

Change History (12)

Changed 9 years ago by Markus Schulz <msc@…>

Attachment: sync_problem.log added

comment:1 Changed 9 years ago by robertm

Status: newassigned

comment:2 Changed 9 years ago by Markus Schulz <msc@…>

It hast nothing todo with the frame skip message, i've many other files which go async without these message:

2010-09-14 23:20:18.573 TV: StartPlayer?(0, WatchingVideo?, main) -- end ok 2010-09-14 23:20:18.573 TV: Changing from None to WatchingVideo? 2010-09-14 23:20:18.576 TV: HandleStateChange?(0) -- end 2010-09-14 23:20:18.597 Player(h): progressive frame seen after 2 interlaced frames 2010-09-14 23:20:18.599 VDPAU: Added 2 output surfaces (total 4, max 4) 2010-09-14 23:20:18.648 Player(h): Video is 3.62692 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.649 Player(h): Disabled deinterlacing 2010-09-14 23:20:18.649 Player(h): Video is 6.2392 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.649 Player(h): Video is 7.9706 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.669 Player(h): Video is 9.02336 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.670 Player(h): Video is 9.69903 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.670 Player(h): Video is 9.95998 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.690 Player(h): Video is 9.90991 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.690 Player(h): Video is 9.77044 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.690 Player(h): Video is 9.42005 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.710 Player(h): Video is 8.91147 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.710 Player(h): Video is 8.39813 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.711 Player(h): Video is 7.77334 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.731 Player(h): Video is 7.05897 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.731 Player(h): Video is 6.39727 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.731 Player(h): Video is 5.65522 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.751 Player(h): Video is 4.85888 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.751 Player(h): Video is 4.13573 frames behind audio (too slow), dropping frame to catch up. 2010-09-14 23:20:18.751 Player(h): Video is 3.34759 frames behind audio (too slow), dropping frame to catch up. 'video_output' mean = '34648.11', std. dev. = '15311.98', fps = '28.86' 'video_output' mean = '39993.95', std. dev. = '8270.09', fps = '25.00' 'video_output' mean = '39794.81', std. dev. = '8083.95', fps = '25.13' 2010-09-14 23:20:33.992 Player(h): 400 progressive frames seen. 'video_output' mean = '39995.39', std. dev. = '8379.53', fps = '25.00' 'video_output' mean = '39993.31', std. dev. = '8435.88', fps = '25.00' 'video_output' mean = '39994.72', std. dev. = '8238.50', fps = '25.00' 'video_output' mean = '39994.10', std. dev. = '8351.13', fps = '25.00' 2010-09-14 23:20:50.050 Player(h): 800 progressive frames seen. 'video_output' mean = '40394.53', std. dev. = '7860.88', fps = '24.76' 'video_output' mean = '40995.50', std. dev. = '7177.95', fps = '24.39' 'video_output' mean = '40991.74', std. dev. = '6878.64', fps = '24.40' 'video_output' mean = '40994.65', std. dev. = '7178.36', fps = '24.39' 2010-09-14 23:21:06.408 Player(h): 1200 progressive frames seen. 'video_output' mean = '40994.23', std. dev. = '6943.68', fps = '24.39' 'video_output' mean = '40995.07', std. dev. = '6478.08', fps = '24.39' 'video_output' mean = '40994.72', std. dev. = '7054.22', fps = '24.39' 'video_output' mean = '40993.80', std. dev. = '7165.05', fps = '24.39' 2010-09-14 23:21:22.828 Player(h): 1600 progressive frames seen. 'video_output' mean = '40994.65', std. dev. = '6883.18', fps = '24.39' 'video_output' mean = '40994.09', std. dev. = '7022.50', fps = '24.39' 'video_output' mean = '40994.65', std. dev. = '6980.53', fps = '24.39' 'video_output' mean = '40793.75', std. dev. = '6916.29', fps = '24.51' 2010-09-14 23:21:39.226 Player(h): 2000 progressive frames seen. 'video_output' mean = '40994.93', std. dev. = '6981.94', fps = '24.39' 'video_output' mean = '41193.96', std. dev. = '6746.13', fps = '24.28' 'video_output' mean = '40994.51', std. dev. = '7097.36', fps = '24.39' 'video_output' mean = '40994.84', std. dev. = '6946.66', fps = '24.39'

it always sync to 24.39 fps, this can't be by accident.

comment:3 Changed 9 years ago by tralph

Markus, please provide a sample for analysis. I'd guess that the frame rate being used to display the video isn't correct.

comment:4 Changed 9 years ago by Markus Schulz <msc@…>

ok, i've put a sample online: http://0zero.de/~nias/sample.mkv

comment:5 Changed 9 years ago by tralph

Milestone: unknown0.24
Owner: changed from Janne Grunau to tralph

The problem with this video is that it incorrectly determines the frame rate as 23.9791 fps when it is actually 25 fps. For Matroska we should use the tracks default_duration to determine the fps as some encoders do not set the stream and container fps correctly.

comment:6 Changed 9 years ago by tralph

Resolution: fixed
Status: assignedclosed

(In [26581]) Use stream->avg_frame_rate for Matroska which is the track's default_duration. Also, refactor fps calculation and selection and add some logging.

Fixes #8875.

comment:7 Changed 9 years ago by Markus Schulz <msc@…>

sorry, but that's not only a mkv problem. The file was originally an avi and the avi has the same problem...

comment:8 Changed 9 years ago by tralph

Markus, you can playback the .avi with -v playback,timestamp,extra and post the log and I'll look at it.

Changed 9 years ago by Markus Schulz <msc@…>

Attachment: frontend_avi_problem.log.gz added

comment:9 Changed 9 years ago by Markus Schulz <msc@…>

i've attached the log. same file except in an avi container.

why the fps was calculated? Sounds stupid to me, cause you don't know if the audio was long enough for all video frames?!? Only the container knows the right choice (written by encoder).

the new code results in 25fps for the matroska:

AFD: Selected FPS is 25 (matroska 25 stream 23.9791 container 1000 estimated 23.9791)
Player(0): Display Refresh Rate: 59.952 Video Frame Rate: 25.000

but still wrong for avi (cause: new code only affects mkv files):

Selected FPS is 23.9791 (matroska 0 stream 23.9791 container 25 estimated 23.9791)
Player(1): Display Refresh Rate: 59.952 Video Frame Rate: 23.980

but really strange was for me, that some avi files with perfect av-sync:

AFD: Selected FPS is 23.976 (matroska 0 stream 23.976 container 25 estimated 23.976)
Player(2): Display Refresh Rate: 59.952 Video Frame Rate: 23.976

results too in "Selected FPS" of 23,976 and was played perfectly synced at 25fps:

'video_output' mean = '40009,83', std. dev. = '11201,69', fps = '24,99'
'video_output' mean = '40010,56', std. dev. = '10616,94', fps = '24,99'
'video_output' mean = '40010,63', std. dev. = '10573,37', fps = '24,99'
'video_output' mean = '40010,51', std. dev. = '10190,71', fps = '24,99'

i think for an avi file only the container can know the right choice for the fps.

comment:10 Changed 9 years ago by Markus Schulz <msc@…>

Ok, i think i know the problem, i've debugged the time_base values (and changed the code to prefer the container fps instead of stream-fps):

2010-10-03 14:49:18.158 AFD: Selected FPS is 25 (matroska 0 stream 25 container 25 estimated 25 tick_per_frame 1 time base_ 1 / 25)
2010-10-03 14:49:26.635 AFD: Selected FPS is 23.9761 (matroska 0 stream 23.9791 container 23.9761 estimated 23.9761 tick_per_frame 1 time base_ 2733 / 65535)
2010-10-03 14:49:34.762 AFD: Selected FPS is 25 (matroska 0 stream 25 container 25 estimated 25 tick_per_frame 1 time base_ 1 / 25)
2010-10-03 14:49:46.142 AFD: Selected FPS is 25 (matroska 0 stream 29.97 container 25 estimated 25 tick_per_frame 1 time base_ 1001 / 30000)
2010-10-03 14:49:57.305 AFD: Selected FPS is 25 (matroska 0 stream 25 container 25 estimated 25 tick_per_frame 1 time base_ 1 / 25)
2010-10-03 14:50:21.843 AFD: Selected FPS is 25 (matroska 0 stream 23.9791 container 25 estimated 23.9791 tick_per_frame 1 time base_ 2733 / 65535)
2010-10-03 14:50:34.256 AFD: Selected FPS is 25 (matroska 0 stream 23.9791 container 25 estimated 23.9791 tick_per_frame 1 time base_ 2733 / 65535)
2010-10-03 14:50:52.498 AFD: Selected FPS is 25 (matroska 0 stream 23.976 container 25 estimated 23.976 tick_per_frame 1 time base_ 1001 / 24000)
2010-10-03 14:51:06.641 AFD: Selected FPS is 23.976 (matroska 0 stream 23.9791 container 23.976 estimated 23.976 tick_per_frame 1 time base_ 2733 / 65535)
2010-10-03 14:51:17.008 AFD: Selected FPS is 25 (matroska 0 stream 23.9791 container 25 estimated 23.9791 tick_per_frame 1 time base_ 2733 / 65535)
2010-10-03 14:51:26.977 AFD: Selected FPS is 25 (matroska 0 stream 25 container 25 estimated 25 tick_per_frame 1 time base_ 1 / 25)
2010-10-03 14:51:37.031 AFD: Selected FPS is 25 (matroska 0 stream 25 container 25 estimated 25 tick_per_frame 1 time base_ 1 / 25)
2010-10-03 14:51:51.846 AFD: Selected FPS is 25 (matroska 0 stream 23.9791 container 25 estimated 23.9791 tick_per_frame 1 time base_ 2733 / 65535)

The async files are "PAL-Speedup" files (like most PAL-DVDs) were the video stream was taken from Cinema/NTSC-Source combined with PAL-Audio-Stream. Therefore the video stream must be played faster at 25fps to be sync with audio. MPlayer seems to do this always (take container value), but myth prefers the stream-fps which seems to be wrong.

I will now try to prefer the container-fps for a while instead of stream fps and see if it works (no async files anymore)

What i still don't understand was: why files with time_base = 1001 / 24000 and selected fps = 23.976 are played with:

'video_output' mean = '40010,51', std. dev. = '10190,71', fps = '24,99'

and are perfect in sync. At a first look only files with time_base = 2733 / 65535 are async if the stream-fps was chosen.

Note: See TracTickets for help on using tickets.