test_timer.c revision 5d4e5dcd
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
145static volatile uint64_t end_time;
146static volatile int test_failed;
147
148struct mytimerinfo {
149	struct rte_timer tim;
150	unsigned id;
151	unsigned count;
152};
153
154static struct mytimerinfo mytiminfo[NB_TIMER];
155
156static void timer_basic_cb(struct rte_timer *tim, void *arg);
157
158static void
159mytimer_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 */
168static void
169timer_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
194static int
195timer_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. */
234enum { SLAVE_WAITING = 1, SLAVE_RUN_SIGNAL, SLAVE_RUNNING, SLAVE_FINISHED };
235static rte_atomic16_t slave_state[RTE_MAX_LCORE];
236
237static void
238master_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
247static void
248master_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
261static void
262master_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
272static void
273slave_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
282static void
283slave_finish(void)
284{
285	unsigned lcore_id = rte_lcore_id();
286
287	rte_atomic16_set(&slave_state[lcore_id], SLAVE_FINISHED);
288}
289
290
291static volatile int cb_count = 0;
292
293/* callback for second stress test. will only be called
294 * on master lcore */
295static void
296timer_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
303static int
304timer_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
417cleanup:
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 */
432static void
433timer_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
488static int
489timer_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
526static int
527timer_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
563static int
564test_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
629REGISTER_TEST_COMMAND(timer_autotest, test_timer);
630