summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorNeels Hofmeyr <nhofmeyr@sysmocom.de>2016-09-22 04:50:13 +0200
committerNeels Hofmeyr <nhofmeyr@sysmocom.de>2016-09-22 07:18:39 +0200
commitd0858c2ae9cdd065d09c3a58e60409b7af50111e (patch)
treeb81c505382af2281f0de298a8a5a168997eca10e
parent255dac16a4a69e29be62bcc692dabf9cd1a586b5 (diff)
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
-rw-r--r--tests/timer/timer_test.c21
-rw-r--r--tests/timer/timer_test.ok99
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