timer_test: print more details to stdout to check

The test is now fully deterministic, so include all detail in stdout, to check
for.

Change-Id: Iecf6387f1d25253fcf1260777673853030c1d326

2 files changed, 116 insertions, 4 deletions

diff --git a/tests/timer/timer_test.c b/tests/timer/timer_test.c
index 12caecfd..ec85c048 100644
--- a/tests/timer/timer_test.c
+++ b/tests/timer/timer_test.c
@@ -73,6 +73,7 @@ static void main_timer_fired(void *data)
 	unsigned int *step = data;
 	unsigned int add_in_this_step;
 	int i;
+	printf("main_timer_fired()\n");
 
 	if (*step == timer_nsteps) {
 		printf("Main timer has finished, please, "
@@ -98,6 +99,8 @@ static void main_timer_fired(void *data)
 		v->stop.tv_usec = v->start.tv_usec;
 		osmo_timer_schedule(&v->timer, seconds, 0);
 		llist_add(&v->head, &timer_test_list);
+		printf("scheduled timer at %d.%06d\n",
+		       (int)v->stop.tv_sec, (int)v->stop.tv_usec);
 	}
 	printf("added %d timers in step %u (expired=%u)\n",
 		add_in_this_step, *step, expired_timers);
@@ -111,7 +114,7 @@ static void secondary_timer_fired(void *data)
 	struct test_timer *v = data, *this, *tmp;
 	struct timeval current, res;
 	struct timeval precision = { 0, TIME_BETWEEN_TIMER_CHECKS + 1};
-	int i;
+	int i, deleted;
 
 	osmo_gettimeofday(&current, NULL);
 
@@ -132,6 +135,10 @@ static void secondary_timer_fired(void *data)
 		       (int)res.tv_sec, (int)res.tv_usec);
 		too_soon++;
 	}
+	else
+		printf("timer fired on time: %d.%06d (+ %d.%06d)\n",
+		       (int)v->stop.tv_sec, (int)v->stop.tv_usec,
+		       (int)res.tv_sec, (int)res.tv_usec);
 
 	llist_del(&v->head);
 	talloc_free(data);
@@ -144,15 +151,19 @@ static void secondary_timer_fired(void *data)
 
 	/* "random" deletion of timers. */
 	i = 0;
+	deleted = 0;
 	llist_for_each_entry_safe(this, tmp, &timer_test_list, head) {
 		i ++;
 		if (!(i & 0x3)) {
 			osmo_timer_del(&this->timer);
 			llist_del(&this->head);
 			talloc_free(this);
-			expired_timers++;
+			deleted++;
 		}
 	}
+	expired_timers += deleted;
+	printf("early deleted %d timers, %d still active\n", deleted,
+	       total_timers - expired_timers);
 }
 
 int main(int argc, char *argv[])
@@ -180,12 +191,16 @@ int main(int argc, char *argv[])
 	steps = ((MAIN_TIMER_NSTEPS * TIME_BETWEEN_STEPS + 20) * 1e6)
 		/ TIME_BETWEEN_TIMER_CHECKS;
 
-	printf("Running timer test for %u steps\n", timer_nsteps);
+	printf("Running timer test for %d iterations,"
+	       " %d steps of %d msecs each\n",
+	       timer_nsteps, steps, TIME_BETWEEN_TIMER_CHECKS / 1000);
 
 	osmo_timer_schedule(&main_timer, 1, 0);
 
 #ifdef HAVE_SYS_SELECT_H
 	while (steps--) {
+		printf("%d.%06d\n", (int)osmo_gettimeofday_override_time.tv_sec,
+		       (int)osmo_gettimeofday_override_time.tv_usec);
 		osmo_timers_prepare();
 		osmo_timers_update();
 		osmo_gettimeofday_override_add(0, TIME_BETWEEN_TIMER_CHECKS);
diff --git a/tests/timer/timer_test.ok b/tests/timer/timer_test.ok
index 7617bc33..109d0393 100644
--- a/tests/timer/timer_test.ok
+++ b/tests/timer/timer_test.ok
@@ -1,8 +1,105 @@
-Running timer test for 5 steps
+Running timer test for 5 iterations, 85 steps of 423 msecs each
+23.424242
+23.847452
+24.270662
+24.693872
+main_timer_fired()
+scheduled timer at 25.693872
 added 1 timers in step 0 (expired=0)
+25.117082
+25.540292
+25.963502
+main_timer_fired()
+scheduled timer at 26.963502
+scheduled timer at 27.963502
 added 2 timers in step 1 (expired=0)
+timer fired on time: 25.693872 (+ 0.269630)
+early deleted 0 timers, 2 still active
+26.386712
+26.809922
+27.233132
+main_timer_fired()
+scheduled timer at 28.233132
+scheduled timer at 29.233132
+scheduled timer at 30.233132
+scheduled timer at 31.233132
 added 4 timers in step 2 (expired=1)
+timer fired on time: 26.963502 (+ 0.269630)
+early deleted 1 timers, 4 still active
+27.656342
+28.079552
+timer fired on time: 27.963502 (+ 0.116050)
+early deleted 0 timers, 3 still active
+28.502762
+main_timer_fired()
+scheduled timer at 29.502762
+scheduled timer at 30.502762
+scheduled timer at 31.502762
+scheduled timer at 32.502762
+scheduled timer at 33.502762
+scheduled timer at 34.502762
+scheduled timer at 35.502762
+scheduled timer at 36.502762
 added 8 timers in step 3 (expired=4)
+28.925972
+29.349182
+timer fired on time: 29.233132 (+ 0.116050)
+early deleted 2 timers, 8 still active
+29.772392
+main_timer_fired()
+scheduled timer at 30.772392
+scheduled timer at 31.772392
+scheduled timer at 32.772392
+scheduled timer at 33.772392
+scheduled timer at 34.772392
+scheduled timer at 35.772392
+scheduled timer at 36.772392
+scheduled timer at 37.772392
+scheduled timer at 30.772392
+scheduled timer at 31.772392
+scheduled timer at 32.772392
+scheduled timer at 33.772392
+scheduled timer at 34.772392
+scheduled timer at 35.772392
+scheduled timer at 36.772392
+scheduled timer at 37.772392
 added 16 timers in step 4 (expired=7)
+30.195602
+30.618812
+timer fired on time: 30.502762 (+ 0.116050)
+early deleted 5 timers, 18 still active
+timer fired on time: 30.233132 (+ 0.385680)
+early deleted 4 timers, 13 still active
+31.042022
+main_timer_fired()
 Main timer has finished, please, wait a bit for the final report.
+31.465232
+timer fired on time: 31.233132 (+ 0.232100)
+early deleted 3 timers, 9 still active
+31.888442
+timer fired on time: 31.772392 (+ 0.116050)
+early deleted 2 timers, 6 still active
+32.311652
+32.734862
+33.158072
+timer fired on time: 32.772392 (+ 0.385680)
+early deleted 1 timers, 4 still active
+33.581282
+34.004492
+34.427702
+34.850912
+35.274122
+35.697332
+36.120542
+timer fired on time: 35.772392 (+ 0.348150)
+early deleted 0 timers, 3 still active
+36.543752
+timer fired on time: 36.502762 (+ 0.040990)
+early deleted 0 timers, 2 still active
+36.966962
+timer fired on time: 36.772392 (+ 0.194570)
+early deleted 0 timers, 1 still active
+37.390172
+37.813382
+timer fired on time: 37.772392 (+ 0.040990)
 test over: added=31 expired=31 too_soon=0 too_late=0