commit 3f64dc1f60040ec3263499bb414cb69aefe967d9
from: Sven M. Hallberg <pesco@khjk.org>
date: Thu Nov 09 19:09:18 2023 UTC

fix timing calculation

Measure and take into account the "return latency" of cwstop(), i.e. the time
it took between playback stopping ang cwstop() returning, usually negative.

commit - b232461a63350252e93337c1c0c30e53f2a8cb0a
commit + 3f64dc1f60040ec3263499bb414cb69aefe967d9
blob - 0d4c17d99a4faa43760f441d3787183fa9d67c9e
blob + 712a5322e29e362f25debe505976c5e3f1b5c376
--- cw.c
+++ cw.c
@@ -9,6 +9,7 @@
 #include <limits.h>	/* CHAR_BIT */
 #include <math.h>
 #include <sndio.h>
+#include <sys/time.h>	/* getclocktime, timespecsub */
 #include <assert.h>
 #include <err.h>
 #include "cw.h"
@@ -23,6 +24,7 @@ static struct sio_par par;
 static size_t framesz, bufsz;
 static sample_t *buf;
 static int writ, pos;			/* total frames and current play pos. */
+static struct timespec tplay;		/* time when playback started */
 
 /* envelope parameters */
 static int rise = 4;			/* ramp up (attack) time [ms] */
@@ -189,7 +191,6 @@ sample_out(int f, int x, int n, int total, int nramp)
 
 #ifdef DEBUGTIME
 #include <stdio.h>
-#include <sys/time.h>
 
 static struct timespec t0;
 
@@ -209,7 +210,7 @@ timestamp(const char *str)
 #endif
 
 /* play a beep of the desired frequency and length */
-int
+void
 beep(int f, int len)
 {
 	int n;		/* samples left to play */
@@ -239,11 +240,10 @@ beep(int f, int len)
 	timestamp("beep(): done writing\n");
 
 	inbeep = 1;
-	return (writ - pos) * 1000 / par.rate;	/* remaining play time [ms] */
 }
 
 /* play a pause of the desired length */
-int
+void
 silence(int len)
 {
 	int n, total;
@@ -270,12 +270,13 @@ silence(int len)
 	timestamp("silence(): done writing\n");
 
 	inbeep = 0;
-	return (writ - pos) * 1000 / par.rate;	/* remaining play time [ms] */
 }
 
 static void
 cb_onmove(void *arg, int delta)
 {
+	if (delta == 0)				/* start of playback */
+		clock_gettime(CLOCK_MONOTONIC, &tplay);
 	pos += delta;
 #ifdef DEBUGTIME
 	timestamp("onmove: ");
@@ -378,7 +379,7 @@ cwstart()
 #endif
 }
 
-void
+int
 cwstop(void)
 {
 #ifdef DEBUGTIME
@@ -397,4 +398,26 @@ cwstop(void)
 	timestamp("sio_stop() ");
 	fprintf(stderr, "took %f ms\n", ms);
 #endif
+
+	/*
+	 * Calculate and report our "return latency", i.e. the time it took
+	 * between playback finishing and the return of the function. This
+	 * value can be negative, meaning that we actually returned earlier
+	 * than playback will finish.
+	 */
+	struct timespec tnow, dt;
+	int playms, nowms;
+
+	clock_gettime(CLOCK_MONOTONIC, &tnow);
+	timespecsub(&tnow, &tplay, &dt);
+	nowms = dt.tv_sec * 1000 + dt.tv_nsec / 1000000;
+	playms = writ * 1000 / par.rate;
+
+#ifdef DEBUGTIME
+	timestamp("playback started ");
+	fprintf(stderr, "%d ms ago, playback time %d ms\n", nowms, playms);
+	timestamp("cwstop: ");
+	fprintf(stderr, "return latency %d ms\n", nowms - playms);
+#endif
+	return nowms - playms;
 }
blob - 613e77647e70605af48b71e73f79cb6e6cb6fcf1
blob + 6b69c80fa1f7e5c03a73d03c71af983e28dcda85
--- cw.h
+++ cw.h
@@ -7,9 +7,9 @@ rampfun_t ramp_lin, ramp_sqr, ramp_sin, ramp_cos, ramp
 
 void cwinit(void);
 void cwstart(void);
-void cwstop(void);
-int beep(int, int);
-int silence(int);
+void beep(int, int);
+void silence(int);
+int cwstop(void);		/* returns time since playback finished [ms] */
 
 /* getenv helpers */
 int getenvnum(const char *, const char *, int *);
blob - 748852b89b60b9fe5bfaf97e7e733f96d617b36e
blob + 2bc6ceac549a2af6034f2c940cf25a20c328e11c
--- morse.c
+++ morse.c
@@ -379,7 +379,7 @@ show(char *s)
 int
 play(char *s)
 {
-	int pause, rem = 0;
+	int pause;
 
 	if (*s == '\0')
 		pause = 7 * pditlen - ditlen;	/* inter-word pause */
@@ -387,18 +387,16 @@ play(char *s)
 		pause = 3 * pditlen - ditlen;	/* intra-word pause */
 
 	cwstart();
-	rem = silence(pause);
+	silence(pause);
 	while (*s) {
 		if (*s == '.')
 			beep(freq, ditlen);
 		else if (*s == '-')
 			beep(freq, 3 * ditlen);
 		s++;
-		rem = silence(ditlen);
+		silence(ditlen);
 	}
-	cwstop();
-
-	return rem;				/* remaining play time [ms] */
+	return cwstop();			/* return latency [ms] */
 }
 
 /* the audio hook for teacher mode */
blob - c135883985cb742fd1e51598dafc674b826609ab
blob + c8aa0f8c51695f3a093a54f420cf896c927387d7
--- teach.c
+++ teach.c
@@ -173,7 +173,6 @@ trial(int i, int ch)
 	if (failprob[i] > 0.9)
 		sound(' ');			/* inter-word pause */
 	latency = sound(ch);
-	//assert(latency == 0);		// XXX
 	clock_gettime(CLOCK_MONOTONIC, &t0);
 	if (failprob[i] > 0.9)
 		printf("%c\b", ch);
@@ -191,7 +190,7 @@ trial(int i, int ch)
 		clock_gettime(CLOCK_MONOTONIC, &t1);
 		timespecsub(&t1, &t0, &delta);
 		taken = delta.tv_sec + delta.tv_nsec / 1000000000.0;	/* s */
-		//taken += latency / 1000.0;
+		taken += latency / 1000.0;
 		sigma = sqrt(vartime);
 
 		/* if return pressed, pause and show scores */