[vlc-devel] [PATCH] pulse: calculate the start time from the last date played

[Thomas Guillem]

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.videolan.org/pipermail/vlc-devel/attachments/20180703/5e4b911f/attachment-0001.html>