GNOME Bugzilla – Bug 785937
alsasrc timestamps is sensitive to context switches.
Last modified: 2018-05-07 15:59:23 UTC
Created attachment 357097 [details] Instrumentation The alsasrc time stamps is sensitive to context switches. If I instrument code in pcm_lib.c ( core ) and alsasrc.c as in attached file
Created attachment 357099 [details] [review] Using audio stamp instead of tstamp (gst-plugins-base patch)
If I run Ftrace with attached Instrumentation I got. ... irq/79-SSI-RX-3150 [003] .... 568.856203: snd_pcm_period_elapsed: Hello 1 irq/79-SSI-RX-3150 [003] d..2 568.856251: update_audio_tstamp: Hello 2 1 irq/79-SSI-RX-3150 [003] d..2 568.856261: update_audio_tstamp: Hello 3 568.829260520 irq/79-SSI-RX-3150 [003] d..2 568.856266: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.856464: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856475: update_audio_tstamp: Hello 3 568.829483940 alsasrc7:src-3151 [002] d..2 568.856480: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.856637: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856642: update_audio_tstamp: Hello 3 568.829662690 alsasrc7:src-3151 [002] d..2 568.856653: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.856675: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856680: update_audio_tstamp: Hello 3 568.829700740 alsasrc7:src-3151 [002] d..2 568.856685: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.856743: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856749: update_audio_tstamp: Hello 3 568.829768200 alsasrc7:src-3151 [002] d..2 568.856754: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] ...1 568.856818: tracing_mark_write: USER_SPACE Hello 2 alsasrc7:src-3151 [002] ...1 568.856858: tracing_mark_write: USER_SPACE Hello 3 alsasrc7:src-3151 [002] d..2 568.856886: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856892: update_audio_tstamp: Hello 3 568.829910820 alsasrc7:src-3151 [002] d..2 568.856897: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.856919: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.856924: update_audio_tstamp: Hello 3 568.829944705 alsasrc7:src-3151 [002] d..2 568.856928: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] ...1 568.856950: tracing_mark_write: USER_SPACE Hello 4 alsasrc7:src-3151 [002] ...1 568.857632: tracing_mark_write: USER_SPACE Hello 1 alsasrc7:src-3151 [002] d..2 568.857812: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.857829: update_audio_tstamp: Hello 3 568.830811315 alsasrc7:src-3151 [002] d..2 568.857836: update_audio_tstamp: Hello 3.1 9.088000000 alsasrc7:src-3151 [002] d..2 568.857878: update_audio_tstamp: Hello 2 1 alsasrc7:src-3151 [002] d..2 568.857885: update_audio_tstamp: Hello 3 568.830901195 alsasrc7:src-3151 [002] d..2 568.857890: update_audio_tstamp: Hello 3.1 9.088000000 ... With this trace we can see that the IRQ is updating the tstamp and audio stamp. We can also se that snd_pcm_readi and snd_pcm_status_get_state also updating the tstamp . So if a context switch occur the time stamp will not be as when the interrupt occur . Also notice this is not true for audio timestamp. Please find attached patch that uses audio stamp instead of tstamp.
Created attachment 357103 [details] Ftrace Attach Ftrace for better readability.
Review of attachment 357099 [details] [review]: ::: ext/alsa/gstalsasrc.c @@ +105,3 @@ +static gint number_of_alsasrc = 0; +static GMutex number_of_alsasrc_lock; +static snd_htimestamp_t alsa_start_time; This is really ugly, why do you need that exactly ?
Hi , I need it in use cases with more than one alsasrc. There are just one audio time ( in core) but the trigger time stamp is for each instance of alsasrc. So if the time stamps should be synchronized I need a common "alsa_start_time". To know when to set and reset alsa_start_time I need to know how many alsasrc instances there are, that is the purpose of "number_of_alsasrc" . To be able to trust "number_of_alsasrc" I need the "number_of_alsasrc_lock". This in use cases when alsasrss are started and stopped pretty much at the same time.
I think this is quite error prone, do you have references of other userspace doing the same thing elsewhere ? Have you verified you haven't in fact found a kernel bug here ? I'd like to see this changed base more documentation then a single ftrace analyses.
Created attachment 357259 [details] log with timestamps
Hi, When you write "I think this is quite error prone" , I assume you mean my analyze and fix. I also aware that the code I complain about is around 5 years old according to git blame. So I am understanding your concerns. So I suggest we take first thing first and I will try to convince you, that the current implementation have problems. Then after that I am more then willing to discuss another solutions. Previously I showed with my Ftrace that snd_pcm_readi and snd_pcm_status_get_state is updating the tstamp . If you now with that knowlage take a look at the code in gstalsasrc.c functions gst_alsasrc_read and gst_alsasrc_get_timestamp and imagine that a context-switch occur as in example below. Let say the thread don't execute for 10 ms . gst_alsasrc_get_timestamp (GstAlsaSrc * asrc) { snd_pcm_status_t *status; snd_htimestamp_t audiostamp; GstClockTime timestamp; snd_pcm_uframes_t avail; gint err = -EPIPE; if (G_UNLIKELY (!asrc)) { GST_ERROR_OBJECT (asrc, "No alsa handle created yet !"); return GST_CLOCK_TIME_NONE; } if (G_UNLIKELY (snd_pcm_status_malloc (&status) != 0)) { GST_ERROR_OBJECT (asrc, "snd_pcm_status_malloc failed"); return GST_CLOCK_TIME_NONE; } <---- context switch -------> if (G_UNLIKELY (snd_pcm_status (asrc->handle, status) != 0)) { GST_ERROR_OBJECT (asrc, "snd_pcm_status failed"); return GST_CLOCK_TIME_NONE; } Will the timestamp be affected by the context switch ? Answer: Yes and that is the problem . This part is also worth looking at. /* max available frames sets the depth of the buffer */ avail = snd_pcm_status_get_avail (status); /* calculate the timestamp of the next sample to be read */ timestamp -= gst_util_uint64_scale_int (avail, GST_SECOND, asrc->rate); Hier there are some handling that are compensate for long time context switch. avail will be zero if the context switch is smaller than the time between two IRQs . In the case I am investigate we have configured is so each packet represent 64ms audio. This mean that the timestamp can be 63.999,,, ms wrong in worst case . I have also done some more instrumentation to simulate context-switchar static gint test = 0; gst_alsasrc_get_timestamp (GstAlsaSrc * asrc) { snd_pcm_status_t *status; snd_htimestamp_t audiostamp; GstClockTime timestamp; snd_pcm_uframes_t avail; gint err = -EPIPE; if (G_UNLIKELY (!asrc)) { GST_ERROR_OBJECT (asrc, "No alsa handle created yet !"); return GST_CLOCK_TIME_NONE; } if (G_UNLIKELY (snd_pcm_status_malloc (&status) != 0)) { GST_ERROR_OBJECT (asrc, "snd_pcm_status_malloc failed"); return GST_CLOCK_TIME_NONE; } /* Simulate contex-switch */ test++; if ((test%5) == 0) { GST_ERROR("Hello Simulated context-switch"); g_usleep(50000); } if (G_UNLIKELY (snd_pcm_status (asrc->handle, status) != 0)) { GST_ERROR_OBJECT (asrc, "snd_pcm_status failed"); return GST_CLOCK_TIME_NONE; } ,,,, avail = snd_pcm_status_get_avail (status); GST_ERROR("Hello avail %d",avail); ,,,, GST_ERROR_OBJECT (asrc, "ALSA timestamp : %" GST_TIME_FORMAT ", delay %lu", GST_TIME_ARGS (timestamp), avail); Please find part of log attached timestamps.txt In this log you can see that the timestamps after the "Hello Simulated context-switch" print are affected . Normallt there are around 64ms between timestamps but after that simulated contex-switch the delta is much higher. Do you agree on that current implementation have problems ?
Seams to be some kind of kernel problem. I will try to come back when I know more.
Closing this bug report as no further information has been provided. Please feel free to reopen this bug report if you can provide the information that was asked for in a previous comment. Thanks!