[vlc-devel] [PATCH] pulse: calculate the start time from the last date played
Rémi Denis-Courmont
remi at remlab.net
Tue Jul 3 11:24:16 CEST 2018
1) PTS and date must be matched.
2) The first only values that have any meaning are first PTS (buffer start) and last PTS + last length (buffer end). Last PTS is just some random value in the middle of the buffer.
Which one of those two should be used... I think that depends how PTS and length are adjusted (or not) with non-1 playback rate. Other than that, first PTS is the easiest one.
Le 3 juillet 2018 10:35:13 GMT+03:00, Thomas Guillem <thomas at gllm.fr> a écrit :
>
>On Mon, Jul 2, 2018, at 18:05, Rémi Denis-Courmont wrote:
>> You need to start with the PTS of the first block in queue, not the
>> last block. This does not look right.
>So I really don't understand what this latency callback is doing.
>
>I'll try to explain what I understand. Here a log of pulse audio
>starting on the clock branch with a first played system date that is
>more than 200ms in the future (on current master, it's only 33ms).
>Play: pts: 23220 length: 23219 date: 27747186134
>[0000555823192b90] pulse audio output debug: cannot synchronize start
>stream_start: date: 27747186134 pa_latency: 0
>[0000555823192b90] pulse audio output debug: deferring start (222587
>us)
>Play: pts: 46440 length: 23219 date: 27747209354
>stream_start: date: 27747209354 pa_latency: 23219
>[0000555823192b90] pulse audio output debug: deferring start (222476
>us)
>Play: pts: 69660 length: 23219 date: 27747232574
>stream_start: date: 27747232574 pa_latency: 46439
>[0000555823192b90] pulse audio output debug: deferring start (222429
>us)
>Play: pts: 92880 length: 23219 date: 27747255794
>stream_start: date: 27747255794 pa_latency: 69659
>[0000555823192b90] pulse audio output debug: deferring start (222385
>us)
>Play: pts: 116100 length: 23219 date: 27747279014
>stream_start: date: 27747279014 pa_latency: 92879
>[0000555823192b90] pulse audio output debug: deferring start (222343
>us)
>Play: pts: 139320 length: 23219 date: 27747302234
>stream_start: date: 27747302234 pa_latency: 116099
>[0000555823192b90] pulse audio output debug: deferring start (222296
>us)
>Play: pts: 162540 length: 23219 date: 27747325454
>stream_start: date: 27747325454 pa_latency: 139319
>[0000555823192b90] pulse audio output debug: deferring start (222253
>us)
>Play: pts: 185760 length: 23219 date: 27747348674
>stream_start: date: 27747348674 pa_latency: 162539
>[0000555823192b90] pulse audio output debug: deferring start (222208
>us)
>Play: pts: 208980 length: 23219 date: 27747371894
>stream_start: date: 27747371894 pa_latency: 185759
>[0000555823192b90] pulse audio output debug: deferring start (222156
>us)
>Play: pts: 232200 length: 23219 date: 27747395114
>stream_start: date: 27747395114 pa_latency: 208979
>[0000555823192b90] pulse audio output debug: deferring start (222092
>us)
>Play: pts: 255420 length: 23219 date: 27747418334
>stream_start: date: 27747418334 pa_latency: 232199
>[0000555823192b90] pulse audio output debug: deferring start (222026
>us)
>Play: pts: 278640 length: 23219 date: 27747441554
>stream_start: date: 27747441554 pa_latency: 255419
>[0000555823192b90] pulse audio output debug: deferring start (221962
>us)
>Play: pts: 301860 length: 23219 date: 27747464774
>stream_start: date: 27747464774 pa_latency: 278639
>[0000555823192b90] pulse audio output debug: deferring start (221916
>us)
>Play: pts: 325080 length: 23219 date: 27747487994
>stream_start: date: 27747487994 pa_latency: 301859
>[0000555823192b90] pulse audio output debug: deferring start (221848
>us)
>Play: pts: 348300 length: 23219 date: 27747511214
>stream_start: date: 27747511214 pa_latency: 325079
>[0000555823192b90] pulse audio output debug: deferring start (221802
>us)
>Play: pts: 371520 length: 23219 date: 27747534434
>stream_start: date: 27747534434 pa_latency: 348299
>[0000555823192b90] pulse audio output debug: deferring start (221756
>us)
>Play: pts: 394740 length: 23219 date: 27747557654
>stream_start: date: 27747557654 pa_latency: 371519
>[0000555823192b90] pulse audio output debug: deferring start (221713
>us)
>Play: pts: 417960 length: 23219 date: 27747580874
>stream_start: date: 27747580874 pa_latency: 394739
>[0000555823192b90] pulse audio output debug: deferring start (221667
>us)
>Play: pts: 441180 length: 23219 date: 27747604094
>stream_start: date: 27747604094 pa_latency: 417959
>[0000555823192b90] pulse audio output debug: deferring start (221623
>us)
>Play: pts: 464400 length: 23219 date: 27747627314
>stream_start: date: 27747627314 pa_latency: 441179
>[0000555823192b90] pulse audio output debug: deferring start (221558
>us)
>Play: pts: 487620 length: 23219 date: 27747650534
>stream_start: date: 27747650534 pa_latency: 464399
>[0000555823192b90] pulse audio output debug: deferring start (221510
>us)
>stream_latency_cb: first_date: 27747186134
>stream_start: date: 27747186134 pa_latency: 487619
>[0000555823192b90] pulse audio output warning: starting late (-
>293433 us)
>
>When the callback is received, the pa_latency value is changed from
>464399 to 487619 (without any new buffer played) because PulseAudio
>notify us of a new hw latency. stream_start() will redo the delta
>calculation with this new pa_latency value but will compare it to the
>first_date (27747186134), therefore the result will be inevitably late.
>This new delta calculation should be done with the last date played
>(27747650534) since the pa_latency take into account the hw latency and
>all buffers already played.
>
>>
>> Le 2 juillet 2018 17:31:59 GMT+03:00, Thomas Guillem <thomas at gllm.fr>
>> a écrit :>> If I understand correctly, stream_latency_cb() is needed
>to re-
>>> calculate the
>>>>>
>>>
>>>
>>> new derrered time (or start late in the worst case scenario) when
>>> the audio
>>>>>
>>>
>>>
>>> device latency changes.
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> This callback called stream_start() with the first played system
>>> date. The
>>>>>
>>>
>>>
>>> problem is that the delta calculated from stream_start was always
>>> late. Using
>>>>>
>>>
>>>
>>> the last system date seems more logical. Indeed, the delta need to
>be
>>>>>
>>>
>>>
>>> calculated from values using the same reference point (and
>>> vlc_pa_get_latency()
>>>>>
>>>
>>>
>>> is calculated from the amount of buffers played).
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> This issue can be reproduced when the first played date is more than
>>> 100ms in
>>>>>
>>>
>>>
>>> the future.
>>>
>>>
>>>
>>>
>>> ---
>>>
>>>
>>>
>>>
>>> modules/audio_output/pulse.c | 22 +++++++++-------------
>>>
>>>
>>>
>>>
>>> 1 file changed, 9 insertions(+), 13 deletions(-)
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> diff --git a/modules/audio_output/pulse.c
>>> b/modules/audio_output/pulse.c
>>>>>
>>>
>>>
>>> index f999eb534b..a275c9f5e6 100644
>>>
>>>
>>>
>>>
>>> --- a/modules/audio_output/pulse.c
>>>
>>>
>>>
>>>
>>> +++ b/modules/audio_output/pulse.c
>>>
>>>
>>>
>>>
>>> @@ -68,8 +68,7 @@ typedef struct
>>>
>>>
>>>
>>>
>>> pa_threaded_mainloop *mainloop; /**< PulseAudio thread */
>>>
>>>
>>>
>>>
>>> pa_time_event *trigger; /**< Deferred stream trigger */
>>>
>>>
>>>
>>>
>>> pa_cvolume cvolume; /**< actual sink input volume */
>>>
>>>
>>>
>>>
>>> - vlc_tick_t first_pts; /**< Play stream timestamp of buffer
>start
>>> */
>>>>>
>>>
>>>
>>> - vlc_tick_t first_date; /**< Play system timestamp of buffer
>>> start */
>>>>>
>>>
>>>
>>> + vlc_tick_t last_date; /**< Play system timestamp of last buffer
>>> */
>>>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> pa_volume_t volume_force; /**< Forced volume (stream must be
>>> NULL) */
>>>>>
>>>
>>>
>>> pa_stream_flags_t flags_force; /**< Forced flags (stream must
>be
>>> NULL) */
>>>>>
>>>
>>>
>>> @@ -227,7 +226,7 @@ static void stream_start(pa_stream *s,
>>> audio_output_t *aout, vlc_tick_t date)
>>>>>
>>>
>>>
>>> aout_sys_t *sys = aout->sys;
>>>
>>>
>>>
>>>
>>> vlc_tick_t delta;
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> - assert (sys->first_pts != VLC_TS_INVALID);
>>>
>>>
>>>
>>>
>>> + assert (sys->last_date != VLC_TS_INVALID);
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> if (sys->trigger != NULL) {
>>>
>>>
>>>
>>>
>>> vlc_pa_rttime_free(sys->mainloop, sys->trigger);
>>>
>>>
>>>
>>>
>>> @@ -258,10 +257,10 @@ static void stream_latency_cb(pa_stream *s,
>>> void *userdata)
>>>>>
>>>
>>>
>>> aout_sys_t *sys = aout->sys;
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> /* This callback is _never_ called while paused. */
>>>
>>>
>>>
>>>
>>> - if (sys->first_pts == VLC_TS_INVALID)
>>>
>>>
>>>
>>>
>>> + if (sys->last_date == VLC_TS_INVALID)
>>>
>>>
>>>
>>>
>>> return; /* nothing to do if buffers are (still) empty */
>>>>>
>>>
>>>
>>> if (pa_stream_is_corked(s) > 0)
>>>
>>>
>>>
>>>
>>> - stream_start(s, aout, sys->first_date);
>>>
>>>
>>>
>>>
>>> + stream_start(s, aout, sys->last_date);
>>>
>>>
>>>
>>>
>>> }
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> @@ -331,7 +330,7 @@ static void stream_overflow_cb(pa_stream *s,
>void
>>> *userdata)
>>>>>
>>>
>>>
>>> if (unlikely(op == NULL))
>>>
>>>
>>>
>>>
>>> return;
>>>
>>>
>>>
>>>
>>> pa_operation_unref(op);
>>>
>>>
>>>
>>>
>>> - sys->first_pts = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>> + sys->last_date = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>> }
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> static void stream_started_cb(pa_stream *s, void *userdata)
>>>
>>>
>>>
>>>
>>> @@ -504,10 +503,7 @@ static void Play(audio_output_t *aout, block_t
>>> *block, vlc_tick_t date)
>>>>>
>>>
>>>
>>> * will take place, and sooner or later a deadlock. */
>>>
>>>
>>>
>>>
>>> pa_threaded_mainloop_lock(sys->mainloop);
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> - if (sys->first_pts == VLC_TS_INVALID) {
>>>
>>>
>>>
>>>
>>> - sys->first_pts = block->i_pts;
>>>
>>>
>>>
>>>
>>> - sys->first_date = date;
>>>
>>>
>>>
>>>
>>> - }
>>>
>>>
>>>
>>>
>>> + sys->last_date = date;
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> if (pa_stream_is_corked(s) > 0)
>>>
>>>
>>>
>>>
>>> stream_start(s, aout, date);
>>>
>>>
>>>
>>>
>>> @@ -543,7 +539,7 @@ static void Pause(audio_output_t *aout, bool
>>> paused, vlc_tick_t date)
>>>>>
>>>
>>>
>>> stream_stop(s, aout);
>>>
>>>
>>>
>>>
>>> } else {
>>>
>>>
>>>
>>>
>>> pa_stream_set_latency_update_callback(s, stream_latency_cb,
>>> aout);
>>>>>
>>>
>>>
>>> - if (likely(sys->first_pts != VLC_TS_INVALID))
>>>
>>>
>>>
>>>
>>> + if (likely(sys->last_date != VLC_TS_INVALID))
>>>
>>>
>>>
>>>
>>> stream_start_now(s, aout);
>>>
>>>
>>>
>>>
>>> }
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> @@ -576,7 +572,7 @@ static void Flush(audio_output_t *aout,
>>> bool wait)
>>>>>
>>>
>>>
>>> op = pa_stream_flush(s, NULL, NULL);
>>>
>>>
>>>
>>>
>>> if (op != NULL)
>>>
>>>
>>>
>>>
>>> pa_operation_unref(op);
>>>
>>>
>>>
>>>
>>> - sys->first_pts = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>> + sys->last_date = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>> stream_stop(s, aout);
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> pa_threaded_mainloop_unlock(sys->mainloop);
>>>
>>>
>>>
>>>
>>> @@ -807,7 +803,7 @@ static int Start(audio_output_t *aout,
>>> audio_sample_format_t *restrict fmt)
>>>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> sys->trigger = NULL;
>>>
>>>
>>>
>>>
>>> pa_cvolume_init(&sys->cvolume);
>>>
>>>
>>>
>>>
>>> - sys->first_pts = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>> + sys->last_date = VLC_TS_INVALID;
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> pa_format_info *formatv = pa_format_info_new();
>>>
>>>
>>>
>>>
>>> formatv->encoding = encoding;
>>>
>>>
>>>
>>>
>>
>> --
>> Envoyé de mon appareil Android avec Courriel K-9 Mail. Veuillez
>> excuser ma brièveté.>
>_________________________________________________
>> vlc-devel mailing list
>> To unsubscribe or modify your subscription options:
>> https://mailman.videolan.org/listinfo/vlc-devel
--
Envoyé de mon appareil Android avec Courriel K-9 Mail. Veuillez excuser ma brièveté.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.videolan.org/pipermail/vlc-devel/attachments/20180703/86916aeb/attachment.html>
More information about the vlc-devel
mailing list