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