foo.diff

diff --git a/audio_alsa.c b/audio_alsa.c
index 62db843f..39671812 100644
--- a/audio_alsa.c
+++ b/audio_alsa.c
@@ -75,7 +75,7 @@ static void *alsa_buffer_monitor_thread_code(void *arg);
 static void volume(double vol);
 static void do_volume(double vol);
 static int prepare(void);
-static int do_play(void *buf, int samples);
+static int do_play(void *buf, int samples, int sample_type, uint32_t timestamp, uint64_t playtime);
 
 static void parameters(audio_parameters *info);
 static int mute(int do_mute); // returns true if it actually is allowed to use the mute
@@ -218,7 +218,7 @@ static int precision_delay_available() {
           generate_zero_frames(silence, frames_of_silence, config.output_format,
                                use_dither, // i.e. with dither
                                dither_random_number_store);
-      do_play(silence, frames_of_silence);
+      do_play(silence, frames_of_silence, play_samples_are_untimed, 0, 0);
       pthread_cleanup_pop(1);
       // now we can get the delay, and we'll note if it uses update timestamps
       yndk_type uses_update_timestamps;
@@ -1726,7 +1726,16 @@ static int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played)
 }
 */
 
-static int do_play(void *buf, int samples) {
+static size_t hash_c_string(const char* p, size_t s) {
+    size_t result = 0;
+    const size_t prime = 31;
+    for (size_t i = 0; i < s; ++i) {
+        result = p[i] + (result * prime);
+    }
+    return result;
+}
+
+static int do_play(void *buf, int samples, int sample_type, uint32_t timestamp, uint64_t playtime) {
   // assuming the alsa_mutex has been acquired
   // debug(3,"audio_alsa play called.");
   int oldState;
@@ -1749,7 +1758,21 @@ static int do_play(void *buf, int samples) {
 
       snd_pcm_state_t prior_state = state; // keep this for afterwards....
       // debug(3, "alsa: write %d frames.", samples);
+
+      int64_t lead_time = 0;
+      if (sample_type == play_samples_are_timed) {
+        size_t buffer_hash = hash_c_string(buf, samples);
+        lead_time = playtime - get_absolute_time_in_ns();
+        debug(2, "starting alsa_pcm_write for frame: %u, delay: %ld frames, leadtime: %f ms, deviation from requested playtime: %f ms, real time: %f ms, buff hash: %u, samples: %d",
+          timestamp, my_delay, 0.000001 * lead_time, ((0.000001 * lead_time) - (1000.0 * my_delay / 44100)), 0.000001 * get_realtime_in_ns(), buffer_hash, samples);
+      }
       ret = alsa_pcm_write(alsa_handle, buf, samples);
+      if (sample_type == play_samples_are_timed) {
+        lead_time = playtime - get_absolute_time_in_ns();
+        debug(2, "finished alsa_pcm_write for frame: %u, delay: %ld frames, leadtime: %f ms, deviation from requested playtime: %f ms, real time: %f ms, ret: %d",
+          timestamp, my_delay, 0.000001 * lead_time, ((0.000001 * lead_time) - (1000.0 * my_delay / 44100)), 0.000001 * get_realtime_in_ns(), ret);
+      }
+
       if (ret > 0)
         frames_sent_for_playing += ret; // this is the number of frames accepted
       if (ret == samples) {
@@ -1916,7 +1939,7 @@ static int play(void *buf, int samples, __attribute__((unused)) int sample_type,
       // set_mute_state(); // try to action the request and return a status
       // do_mute(0); // unmute for backend's reason
     }
-    ret = do_play(buf, samples);
+    ret = do_play(buf, samples, sample_type, timestamp, playtime);
   }
 
   debug_mutex_unlock(&alsa_mutex, 0);
@@ -2135,7 +2158,7 @@ static void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg)
               generate_zero_frames(silence, frames_of_silence, config.output_format,
                                    use_dither, // i.e. with dither
                                    dither_random_number_store);
-          ret = do_play(silence, frames_of_silence);
+          ret = do_play(silence, frames_of_silence, play_samples_are_untimed, 0, 0);
           frame_count++;
           pthread_cleanup_pop(1); // free malloced buffer
           if (ret < 0) {