xref: /dpdk/app/test/test_timer.c (revision f8dbaebbf1c9efcbb2e2354b341ed62175466a57)
1 /* SPDX-License-Identifier: BSD-3-Clause
2  * Copyright(c) 2010-2014 Intel Corporation
3  */
4 
5 #include "test.h"
6 
7 /*
8  * Timer
9  * =====
10  *
11  * #. Stress test 1.
12  *
13  *    The objective of the timer stress tests is to check that there are no
14  *    race conditions in list and status management. This test launches,
15  *    resets and stops the timer very often on many cores at the same
16  *    time.
17  *
18  *    - Only one timer is used for this test.
19  *    - On each core, the rte_timer_manage() function is called from the main
20  *      loop every 3 microseconds.
21  *    - In the main loop, the timer may be reset (randomly, with a
22  *      probability of 0.5 %) 100 microseconds later on a random core, or
23  *      stopped (with a probability of 0.5 % also).
24  *    - In callback, the timer is can be reset (randomly, with a
25  *      probability of 0.5 %) 100 microseconds later on the same core or
26  *      on another core (same probability), or stopped (same
27  *      probability).
28  *
29  * # Stress test 2.
30  *
31  *    The objective of this test is similar to the first in that it attempts
32  *    to find if there are any race conditions in the timer library. However,
33  *    it is less complex in terms of operations performed and duration, as it
34  *    is designed to have a predictable outcome that can be tested.
35  *
36  *    - A set of timers is initialized for use by the test
37  *    - All cores then simultaneously are set to schedule all the timers at
38  *      the same time, so conflicts should occur.
39  *    - Then there is a delay while we wait for the timers to expire
40  *    - Then the main lcore calls timer_manage() and we check that all
41  *      timers have had their callbacks called exactly once - no more no less.
42  *    - Then we repeat the process, except after setting up the timers, we have
43  *      all cores randomly reschedule them.
44  *    - Again we check that the expected number of callbacks has occurred when
45  *      we call timer-manage.
46  *
47  * #. Basic test.
48  *
49  *    This test performs basic functional checks of the timers. The test
50  *    uses four different timers that are loaded and stopped under
51  *    specific conditions in specific contexts.
52  *
53  *    - Four timers are used for this test.
54  *    - On each core, the rte_timer_manage() function is called from main loop
55  *      every 3 microseconds.
56  *
57  *    The autotest python script checks that the behavior is correct:
58  *
59  *    - timer0
60  *
61  *      - At initialization, timer0 is loaded by the main core, on main core
62  *        in "single" mode (time = 1 second).
63  *      - In the first 19 callbacks, timer0 is reloaded on the same core,
64  *        then, it is explicitly stopped at the 20th call.
65  *      - At t=25s, timer0 is reloaded once by timer2.
66  *
67  *    - timer1
68  *
69  *      - At initialization, timer1 is loaded by the main core, on the
70  *        main core in "single" mode (time = 2 seconds).
71  *      - In the first 9 callbacks, timer1 is reloaded on another
72  *        core. After the 10th callback, timer1 is not reloaded anymore.
73  *
74  *    - timer2
75  *
76  *      - At initialization, timer2 is loaded by the main core, on the
77  *        main core in "periodical" mode (time = 1 second).
78  *      - In the callback, when t=25s, it stops timer3 and reloads timer0
79  *        on the current core.
80  *
81  *    - timer3
82  *
83  *      - At initialization, timer3 is loaded by the main core, on
84  *        another core in "periodical" mode (time = 1 second).
85  *      - It is stopped at t=25s by timer2.
86  */
87 
88 #include <stdio.h>
89 #include <stdarg.h>
90 #include <string.h>
91 #include <stdlib.h>
92 #include <stdint.h>
93 #include <inttypes.h>
94 #include <sys/queue.h>
95 #include <math.h>
96 
97 #include <rte_common.h>
98 #include <rte_log.h>
99 #include <rte_memory.h>
100 #include <rte_launch.h>
101 #include <rte_cycles.h>
102 #include <rte_eal.h>
103 #include <rte_per_lcore.h>
104 #include <rte_lcore.h>
105 #include <rte_timer.h>
106 #include <rte_random.h>
107 #include <rte_malloc.h>
108 #include <rte_pause.h>
109 
110 #define TEST_DURATION_S 1 /* in seconds */
111 #define NB_TIMER 4
112 
113 #define RTE_LOGTYPE_TESTTIMER RTE_LOGTYPE_USER3
114 
115 static volatile uint64_t end_time;
116 static volatile int test_failed;
117 
118 struct mytimerinfo {
119 	struct rte_timer tim;
120 	unsigned id;
121 	unsigned count;
122 };
123 
124 static struct mytimerinfo mytiminfo[NB_TIMER];
125 
126 static void timer_basic_cb(struct rte_timer *tim, void *arg);
127 
128 static void
129 mytimer_reset(struct mytimerinfo *timinfo, uint64_t ticks,
130 	      enum rte_timer_type type, unsigned tim_lcore,
131 	      rte_timer_cb_t fct)
132 {
133 	rte_timer_reset_sync(&timinfo->tim, ticks, type, tim_lcore,
134 			     fct, timinfo);
135 }
136 
137 /* timer callback for stress tests */
138 static void
139 timer_stress_cb(__rte_unused struct rte_timer *tim,
140 		__rte_unused void *arg)
141 {
142 	long r;
143 	unsigned lcore_id = rte_lcore_id();
144 	uint64_t hz = rte_get_timer_hz();
145 
146 	if (rte_timer_pending(tim))
147 		return;
148 
149 	r = rte_rand();
150 	if ((r & 0xff) == 0) {
151 		mytimer_reset(&mytiminfo[0], hz, SINGLE, lcore_id,
152 			      timer_stress_cb);
153 	}
154 	else if ((r & 0xff) == 1) {
155 		mytimer_reset(&mytiminfo[0], hz, SINGLE,
156 			      rte_get_next_lcore(lcore_id, 0, 1),
157 			      timer_stress_cb);
158 	}
159 	else if ((r & 0xff) == 2) {
160 		rte_timer_stop(&mytiminfo[0].tim);
161 	}
162 }
163 
164 static int
165 timer_stress_main_loop(__rte_unused void *arg)
166 {
167 	uint64_t hz = rte_get_timer_hz();
168 	unsigned lcore_id = rte_lcore_id();
169 	uint64_t cur_time;
170 	int64_t diff = 0;
171 	long r;
172 
173 	while (diff >= 0) {
174 
175 		/* call the timer handler on each core */
176 		rte_timer_manage();
177 
178 		/* simulate the processing of a packet
179 		 * (1 us = 2000 cycles at 2 Ghz) */
180 		rte_delay_us(1);
181 
182 		/* randomly stop or reset timer */
183 		r = rte_rand();
184 		lcore_id = rte_get_next_lcore(lcore_id, 0, 1);
185 		if ((r & 0xff) == 0) {
186 			/* 100 us */
187 			mytimer_reset(&mytiminfo[0], hz/10000, SINGLE, lcore_id,
188 				      timer_stress_cb);
189 		}
190 		else if ((r & 0xff) == 1) {
191 			rte_timer_stop_sync(&mytiminfo[0].tim);
192 		}
193 		cur_time = rte_get_timer_cycles();
194 		diff = end_time - cur_time;
195 	}
196 
197 	lcore_id = rte_lcore_id();
198 	RTE_LOG(INFO, TESTTIMER, "core %u finished\n", lcore_id);
199 
200 	return 0;
201 }
202 
203 /* Need to synchronize worker lcores through multiple steps. */
204 enum { WORKER_WAITING = 1, WORKER_RUN_SIGNAL, WORKER_RUNNING, WORKER_FINISHED };
205 static uint16_t lcore_state[RTE_MAX_LCORE];
206 
207 static void
208 main_init_workers(void)
209 {
210 	unsigned i;
211 
212 	RTE_LCORE_FOREACH_WORKER(i) {
213 		__atomic_store_n(&lcore_state[i], WORKER_WAITING, __ATOMIC_RELAXED);
214 	}
215 }
216 
217 static void
218 main_start_workers(void)
219 {
220 	unsigned i;
221 
222 	RTE_LCORE_FOREACH_WORKER(i) {
223 		__atomic_store_n(&lcore_state[i], WORKER_RUN_SIGNAL, __ATOMIC_RELEASE);
224 	}
225 	RTE_LCORE_FOREACH_WORKER(i) {
226 		rte_wait_until_equal_16(&lcore_state[i], WORKER_RUNNING, __ATOMIC_ACQUIRE);
227 	}
228 }
229 
230 static void
231 main_wait_for_workers(void)
232 {
233 	unsigned i;
234 
235 	RTE_LCORE_FOREACH_WORKER(i) {
236 		rte_wait_until_equal_16(&lcore_state[i], WORKER_FINISHED, __ATOMIC_ACQUIRE);
237 	}
238 }
239 
240 static void
241 worker_wait_to_start(void)
242 {
243 	unsigned lcore_id = rte_lcore_id();
244 
245 	rte_wait_until_equal_16(&lcore_state[lcore_id], WORKER_RUN_SIGNAL, __ATOMIC_ACQUIRE);
246 	__atomic_store_n(&lcore_state[lcore_id], WORKER_RUNNING, __ATOMIC_RELEASE);
247 }
248 
249 static void
250 worker_finish(void)
251 {
252 	unsigned lcore_id = rte_lcore_id();
253 
254 	__atomic_store_n(&lcore_state[lcore_id], WORKER_FINISHED, __ATOMIC_RELEASE);
255 }
256 
257 
258 static volatile int cb_count = 0;
259 
260 /* callback for second stress test. will only be called
261  * on main lcore
262  */
263 static void
264 timer_stress2_cb(struct rte_timer *tim __rte_unused, void *arg __rte_unused)
265 {
266 	cb_count++;
267 }
268 
269 #define NB_STRESS2_TIMERS 8192
270 
271 static int
272 timer_stress2_main_loop(__rte_unused void *arg)
273 {
274 	static struct rte_timer *timers;
275 	int i, ret;
276 	uint64_t delay = rte_get_timer_hz() / 20;
277 	unsigned int lcore_id = rte_lcore_id();
278 	unsigned int main_lcore = rte_get_main_lcore();
279 	int32_t my_collisions = 0;
280 	static uint32_t collisions;
281 
282 	if (lcore_id == main_lcore) {
283 		cb_count = 0;
284 		test_failed = 0;
285 		__atomic_store_n(&collisions, 0, __ATOMIC_RELAXED);
286 		timers = rte_malloc(NULL, sizeof(*timers) * NB_STRESS2_TIMERS, 0);
287 		if (timers == NULL) {
288 			printf("Test Failed\n");
289 			printf("- Cannot allocate memory for timers\n" );
290 			test_failed = 1;
291 			main_start_workers();
292 			goto cleanup;
293 		}
294 		for (i = 0; i < NB_STRESS2_TIMERS; i++)
295 			rte_timer_init(&timers[i]);
296 		main_start_workers();
297 	} else {
298 		worker_wait_to_start();
299 		if (test_failed)
300 			goto cleanup;
301 	}
302 
303 	/* have all cores schedule all timers on main lcore */
304 	for (i = 0; i < NB_STRESS2_TIMERS; i++) {
305 		ret = rte_timer_reset(&timers[i], delay, SINGLE, main_lcore,
306 				timer_stress2_cb, NULL);
307 		/* there will be collisions when multiple cores simultaneously
308 		 * configure the same timers */
309 		if (ret != 0)
310 			my_collisions++;
311 	}
312 	if (my_collisions != 0)
313 		__atomic_fetch_add(&collisions, my_collisions, __ATOMIC_RELAXED);
314 
315 	/* wait long enough for timers to expire */
316 	rte_delay_ms(100);
317 
318 	/* all cores rendezvous */
319 	if (lcore_id == main_lcore) {
320 		main_wait_for_workers();
321 	} else {
322 		worker_finish();
323 	}
324 
325 	/* now check that we get the right number of callbacks */
326 	if (lcore_id == main_lcore) {
327 		my_collisions = __atomic_load_n(&collisions, __ATOMIC_RELAXED);
328 		if (my_collisions != 0)
329 			printf("- %d timer reset collisions (OK)\n", my_collisions);
330 		rte_timer_manage();
331 		if (cb_count != NB_STRESS2_TIMERS) {
332 			printf("Test Failed\n");
333 			printf("- Stress test 2, part 1 failed\n");
334 			printf("- Expected %d callbacks, got %d\n", NB_STRESS2_TIMERS,
335 					cb_count);
336 			test_failed = 1;
337 			main_start_workers();
338 			goto cleanup;
339 		}
340 		cb_count = 0;
341 
342 		/* proceed */
343 		main_start_workers();
344 	} else {
345 		/* proceed */
346 		worker_wait_to_start();
347 		if (test_failed)
348 			goto cleanup;
349 	}
350 
351 	/* now test again, just stop and restart timers at random after init*/
352 	for (i = 0; i < NB_STRESS2_TIMERS; i++)
353 		rte_timer_reset(&timers[i], delay, SINGLE, main_lcore,
354 				timer_stress2_cb, NULL);
355 
356 	/* pick random timer to reset, stopping them first half the time */
357 	for (i = 0; i < 100000; i++) {
358 		int r = rand() % NB_STRESS2_TIMERS;
359 		if (i % 2)
360 			rte_timer_stop(&timers[r]);
361 		rte_timer_reset(&timers[r], delay, SINGLE, main_lcore,
362 				timer_stress2_cb, NULL);
363 	}
364 
365 	/* wait long enough for timers to expire */
366 	rte_delay_ms(100);
367 
368 	/* now check that we get the right number of callbacks */
369 	if (lcore_id == main_lcore) {
370 		main_wait_for_workers();
371 
372 		rte_timer_manage();
373 		if (cb_count != NB_STRESS2_TIMERS) {
374 			printf("Test Failed\n");
375 			printf("- Stress test 2, part 2 failed\n");
376 			printf("- Expected %d callbacks, got %d\n", NB_STRESS2_TIMERS,
377 					cb_count);
378 			test_failed = 1;
379 		} else {
380 			printf("Test OK\n");
381 		}
382 	}
383 
384 cleanup:
385 	if (lcore_id == main_lcore) {
386 		main_wait_for_workers();
387 		if (timers != NULL) {
388 			rte_free(timers);
389 			timers = NULL;
390 		}
391 	} else {
392 		worker_finish();
393 	}
394 
395 	return 0;
396 }
397 
398 /* timer callback for basic tests */
399 static void
400 timer_basic_cb(struct rte_timer *tim, void *arg)
401 {
402 	struct mytimerinfo *timinfo = arg;
403 	uint64_t hz = rte_get_timer_hz();
404 	unsigned lcore_id = rte_lcore_id();
405 	uint64_t cur_time = rte_get_timer_cycles();
406 
407 	if (rte_timer_pending(tim))
408 		return;
409 
410 	timinfo->count ++;
411 
412 	RTE_LOG(INFO, TESTTIMER,
413 		"%"PRIu64": callback id=%u count=%u on core %u\n",
414 		cur_time, timinfo->id, timinfo->count, lcore_id);
415 
416 	/* reload timer 0 on same core */
417 	if (timinfo->id == 0 && timinfo->count < 20) {
418 		mytimer_reset(timinfo, hz, SINGLE, lcore_id, timer_basic_cb);
419 		return;
420 	}
421 
422 	/* reload timer 1 on next core */
423 	if (timinfo->id == 1 && timinfo->count < 10) {
424 		mytimer_reset(timinfo, hz*2, SINGLE,
425 			      rte_get_next_lcore(lcore_id, 0, 1),
426 			      timer_basic_cb);
427 		return;
428 	}
429 
430 	/* Explicitly stop timer 0. Once stop() called, we can even
431 	 * erase the content of the structure: it is not referenced
432 	 * anymore by any code (in case of dynamic structure, it can
433 	 * be freed) */
434 	if (timinfo->id == 0 && timinfo->count == 20) {
435 
436 		/* stop_sync() is not needed, because we know that the
437 		 * status of timer is only modified by this core */
438 		rte_timer_stop(tim);
439 		memset(tim, 0xAA, sizeof(struct rte_timer));
440 		return;
441 	}
442 
443 	/* stop timer3, and restart a new timer0 (it was removed 5
444 	 * seconds ago) for a single shot */
445 	if (timinfo->id == 2 && timinfo->count == 25) {
446 		rte_timer_stop_sync(&mytiminfo[3].tim);
447 
448 		/* need to reinit because structure was erased with 0xAA */
449 		rte_timer_init(&mytiminfo[0].tim);
450 		mytimer_reset(&mytiminfo[0], hz, SINGLE, lcore_id,
451 			      timer_basic_cb);
452 	}
453 }
454 
455 static int
456 timer_basic_main_loop(__rte_unused void *arg)
457 {
458 	uint64_t hz = rte_get_timer_hz();
459 	unsigned lcore_id = rte_lcore_id();
460 	uint64_t cur_time;
461 	int64_t diff = 0;
462 
463 	/* launch all timers on core 0 */
464 	if (lcore_id == rte_get_main_lcore()) {
465 		mytimer_reset(&mytiminfo[0], hz/4, SINGLE, lcore_id,
466 			      timer_basic_cb);
467 		mytimer_reset(&mytiminfo[1], hz/2, SINGLE, lcore_id,
468 			      timer_basic_cb);
469 		mytimer_reset(&mytiminfo[2], hz/4, PERIODICAL, lcore_id,
470 			      timer_basic_cb);
471 		mytimer_reset(&mytiminfo[3], hz/4, PERIODICAL,
472 			      rte_get_next_lcore(lcore_id, 0, 1),
473 			      timer_basic_cb);
474 	}
475 
476 	while (diff >= 0) {
477 
478 		/* call the timer handler on each core */
479 		rte_timer_manage();
480 
481 		/* simulate the processing of a packet
482 		 * (3 us = 6000 cycles at 2 Ghz) */
483 		rte_delay_us(3);
484 
485 		cur_time = rte_get_timer_cycles();
486 		diff = end_time - cur_time;
487 	}
488 	RTE_LOG(INFO, TESTTIMER, "core %u finished\n", lcore_id);
489 
490 	return 0;
491 }
492 
493 static int
494 timer_sanity_check(void)
495 {
496 #ifdef RTE_LIBEAL_USE_HPET
497 	if (eal_timer_source != EAL_TIMER_HPET) {
498 		printf("Not using HPET, can't sanity check timer sources\n");
499 		return 0;
500 	}
501 
502 	const uint64_t t_hz = rte_get_tsc_hz();
503 	const uint64_t h_hz = rte_get_hpet_hz();
504 	printf("Hertz values: TSC = %"PRIu64", HPET = %"PRIu64"\n", t_hz, h_hz);
505 
506 	const uint64_t tsc_start = rte_get_tsc_cycles();
507 	const uint64_t hpet_start = rte_get_hpet_cycles();
508 	rte_delay_ms(100); /* delay 1/10 second */
509 	const uint64_t tsc_end = rte_get_tsc_cycles();
510 	const uint64_t hpet_end = rte_get_hpet_cycles();
511 	printf("Measured cycles: TSC = %"PRIu64", HPET = %"PRIu64"\n",
512 			tsc_end-tsc_start, hpet_end-hpet_start);
513 
514 	const double tsc_time = (double)(tsc_end - tsc_start)/t_hz;
515 	const double hpet_time = (double)(hpet_end - hpet_start)/h_hz;
516 	/* get the percentage that the times differ by */
517 	const double time_diff = fabs(tsc_time - hpet_time)*100/tsc_time;
518 	printf("Measured time: TSC = %.4f, HPET = %.4f\n", tsc_time, hpet_time);
519 
520 	printf("Elapsed time measured by TSC and HPET differ by %f%%\n",
521 			time_diff);
522 	if (time_diff > 0.1) {
523 		printf("Error times differ by >0.1%%");
524 		return -1;
525 	}
526 #endif
527 	return 0;
528 }
529 
530 static int
531 test_timer(void)
532 {
533 	unsigned i;
534 	uint64_t cur_time;
535 	uint64_t hz;
536 
537 	if (rte_lcore_count() < 2) {
538 		printf("Not enough cores for timer_autotest, expecting at least 2\n");
539 		return TEST_SKIPPED;
540 	}
541 
542 	/* sanity check our timer sources and timer config values */
543 	if (timer_sanity_check() < 0) {
544 		printf("Timer sanity checks failed\n");
545 		return TEST_FAILED;
546 	}
547 
548 	/* init timer */
549 	for (i=0; i<NB_TIMER; i++) {
550 		memset(&mytiminfo[i], 0, sizeof(struct mytimerinfo));
551 		mytiminfo[i].id = i;
552 		rte_timer_init(&mytiminfo[i].tim);
553 	}
554 
555 	/* calculate the "end of test" time */
556 	cur_time = rte_get_timer_cycles();
557 	hz = rte_get_timer_hz();
558 	end_time = cur_time + (hz * TEST_DURATION_S);
559 
560 	/* start other cores */
561 	printf("Start timer stress tests\n");
562 	rte_eal_mp_remote_launch(timer_stress_main_loop, NULL, CALL_MAIN);
563 	rte_eal_mp_wait_lcore();
564 
565 	/* stop timer 0 used for stress test */
566 	rte_timer_stop_sync(&mytiminfo[0].tim);
567 
568 	/* run a second, slightly different set of stress tests */
569 	printf("\nStart timer stress tests 2\n");
570 	test_failed = 0;
571 	main_init_workers();
572 	rte_eal_mp_remote_launch(timer_stress2_main_loop, NULL, CALL_MAIN);
573 	rte_eal_mp_wait_lcore();
574 	if (test_failed)
575 		return TEST_FAILED;
576 
577 	/* calculate the "end of test" time */
578 	cur_time = rte_get_timer_cycles();
579 	hz = rte_get_timer_hz();
580 	end_time = cur_time + (hz * TEST_DURATION_S);
581 
582 	/* start other cores */
583 	printf("\nStart timer basic tests\n");
584 	rte_eal_mp_remote_launch(timer_basic_main_loop, NULL, CALL_MAIN);
585 	rte_eal_mp_wait_lcore();
586 
587 	/* stop all timers */
588 	for (i=0; i<NB_TIMER; i++) {
589 		rte_timer_stop_sync(&mytiminfo[i].tim);
590 	}
591 
592 	rte_timer_dump_stats(stdout);
593 
594 	return TEST_SUCCESS;
595 }
596 
597 REGISTER_TEST_COMMAND(timer_autotest, test_timer);
598