xref: /openbmc/linux/kernel/trace/trace_selftest.c (revision 4800cd83)
1 /* Include in trace.c */
2 
3 #include <linux/stringify.h>
4 #include <linux/kthread.h>
5 #include <linux/delay.h>
6 #include <linux/slab.h>
7 
8 static inline int trace_valid_entry(struct trace_entry *entry)
9 {
10 	switch (entry->type) {
11 	case TRACE_FN:
12 	case TRACE_CTX:
13 	case TRACE_WAKE:
14 	case TRACE_STACK:
15 	case TRACE_PRINT:
16 	case TRACE_BRANCH:
17 	case TRACE_GRAPH_ENT:
18 	case TRACE_GRAPH_RET:
19 		return 1;
20 	}
21 	return 0;
22 }
23 
24 static int trace_test_buffer_cpu(struct trace_array *tr, int cpu)
25 {
26 	struct ring_buffer_event *event;
27 	struct trace_entry *entry;
28 	unsigned int loops = 0;
29 
30 	while ((event = ring_buffer_consume(tr->buffer, cpu, NULL, NULL))) {
31 		entry = ring_buffer_event_data(event);
32 
33 		/*
34 		 * The ring buffer is a size of trace_buf_size, if
35 		 * we loop more than the size, there's something wrong
36 		 * with the ring buffer.
37 		 */
38 		if (loops++ > trace_buf_size) {
39 			printk(KERN_CONT ".. bad ring buffer ");
40 			goto failed;
41 		}
42 		if (!trace_valid_entry(entry)) {
43 			printk(KERN_CONT ".. invalid entry %d ",
44 				entry->type);
45 			goto failed;
46 		}
47 	}
48 	return 0;
49 
50  failed:
51 	/* disable tracing */
52 	tracing_disabled = 1;
53 	printk(KERN_CONT ".. corrupted trace buffer .. ");
54 	return -1;
55 }
56 
57 /*
58  * Test the trace buffer to see if all the elements
59  * are still sane.
60  */
61 static int trace_test_buffer(struct trace_array *tr, unsigned long *count)
62 {
63 	unsigned long flags, cnt = 0;
64 	int cpu, ret = 0;
65 
66 	/* Don't allow flipping of max traces now */
67 	local_irq_save(flags);
68 	arch_spin_lock(&ftrace_max_lock);
69 
70 	cnt = ring_buffer_entries(tr->buffer);
71 
72 	/*
73 	 * The trace_test_buffer_cpu runs a while loop to consume all data.
74 	 * If the calling tracer is broken, and is constantly filling
75 	 * the buffer, this will run forever, and hard lock the box.
76 	 * We disable the ring buffer while we do this test to prevent
77 	 * a hard lock up.
78 	 */
79 	tracing_off();
80 	for_each_possible_cpu(cpu) {
81 		ret = trace_test_buffer_cpu(tr, cpu);
82 		if (ret)
83 			break;
84 	}
85 	tracing_on();
86 	arch_spin_unlock(&ftrace_max_lock);
87 	local_irq_restore(flags);
88 
89 	if (count)
90 		*count = cnt;
91 
92 	return ret;
93 }
94 
95 static inline void warn_failed_init_tracer(struct tracer *trace, int init_ret)
96 {
97 	printk(KERN_WARNING "Failed to init %s tracer, init returned %d\n",
98 		trace->name, init_ret);
99 }
100 #ifdef CONFIG_FUNCTION_TRACER
101 
102 #ifdef CONFIG_DYNAMIC_FTRACE
103 
104 /* Test dynamic code modification and ftrace filters */
105 int trace_selftest_startup_dynamic_tracing(struct tracer *trace,
106 					   struct trace_array *tr,
107 					   int (*func)(void))
108 {
109 	int save_ftrace_enabled = ftrace_enabled;
110 	int save_tracer_enabled = tracer_enabled;
111 	unsigned long count;
112 	char *func_name;
113 	int ret;
114 
115 	/* The ftrace test PASSED */
116 	printk(KERN_CONT "PASSED\n");
117 	pr_info("Testing dynamic ftrace: ");
118 
119 	/* enable tracing, and record the filter function */
120 	ftrace_enabled = 1;
121 	tracer_enabled = 1;
122 
123 	/* passed in by parameter to fool gcc from optimizing */
124 	func();
125 
126 	/*
127 	 * Some archs *cough*PowerPC*cough* add characters to the
128 	 * start of the function names. We simply put a '*' to
129 	 * accommodate them.
130 	 */
131 	func_name = "*" __stringify(DYN_FTRACE_TEST_NAME);
132 
133 	/* filter only on our function */
134 	ftrace_set_filter(func_name, strlen(func_name), 1);
135 
136 	/* enable tracing */
137 	ret = tracer_init(trace, tr);
138 	if (ret) {
139 		warn_failed_init_tracer(trace, ret);
140 		goto out;
141 	}
142 
143 	/* Sleep for a 1/10 of a second */
144 	msleep(100);
145 
146 	/* we should have nothing in the buffer */
147 	ret = trace_test_buffer(tr, &count);
148 	if (ret)
149 		goto out;
150 
151 	if (count) {
152 		ret = -1;
153 		printk(KERN_CONT ".. filter did not filter .. ");
154 		goto out;
155 	}
156 
157 	/* call our function again */
158 	func();
159 
160 	/* sleep again */
161 	msleep(100);
162 
163 	/* stop the tracing. */
164 	tracing_stop();
165 	ftrace_enabled = 0;
166 
167 	/* check the trace buffer */
168 	ret = trace_test_buffer(tr, &count);
169 	trace->reset(tr);
170 	tracing_start();
171 
172 	/* we should only have one item */
173 	if (!ret && count != 1) {
174 		printk(KERN_CONT ".. filter failed count=%ld ..", count);
175 		ret = -1;
176 		goto out;
177 	}
178 
179  out:
180 	ftrace_enabled = save_ftrace_enabled;
181 	tracer_enabled = save_tracer_enabled;
182 
183 	/* Enable tracing on all functions again */
184 	ftrace_set_filter(NULL, 0, 1);
185 
186 	return ret;
187 }
188 #else
189 # define trace_selftest_startup_dynamic_tracing(trace, tr, func) ({ 0; })
190 #endif /* CONFIG_DYNAMIC_FTRACE */
191 
192 /*
193  * Simple verification test of ftrace function tracer.
194  * Enable ftrace, sleep 1/10 second, and then read the trace
195  * buffer to see if all is in order.
196  */
197 int
198 trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
199 {
200 	int save_ftrace_enabled = ftrace_enabled;
201 	int save_tracer_enabled = tracer_enabled;
202 	unsigned long count;
203 	int ret;
204 
205 	/* make sure msleep has been recorded */
206 	msleep(1);
207 
208 	/* start the tracing */
209 	ftrace_enabled = 1;
210 	tracer_enabled = 1;
211 
212 	ret = tracer_init(trace, tr);
213 	if (ret) {
214 		warn_failed_init_tracer(trace, ret);
215 		goto out;
216 	}
217 
218 	/* Sleep for a 1/10 of a second */
219 	msleep(100);
220 	/* stop the tracing. */
221 	tracing_stop();
222 	ftrace_enabled = 0;
223 
224 	/* check the trace buffer */
225 	ret = trace_test_buffer(tr, &count);
226 	trace->reset(tr);
227 	tracing_start();
228 
229 	if (!ret && !count) {
230 		printk(KERN_CONT ".. no entries found ..");
231 		ret = -1;
232 		goto out;
233 	}
234 
235 	ret = trace_selftest_startup_dynamic_tracing(trace, tr,
236 						     DYN_FTRACE_TEST_NAME);
237 
238  out:
239 	ftrace_enabled = save_ftrace_enabled;
240 	tracer_enabled = save_tracer_enabled;
241 
242 	/* kill ftrace totally if we failed */
243 	if (ret)
244 		ftrace_kill();
245 
246 	return ret;
247 }
248 #endif /* CONFIG_FUNCTION_TRACER */
249 
250 
251 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
252 
253 /* Maximum number of functions to trace before diagnosing a hang */
254 #define GRAPH_MAX_FUNC_TEST	100000000
255 
256 static void
257 __ftrace_dump(bool disable_tracing, enum ftrace_dump_mode oops_dump_mode);
258 static unsigned int graph_hang_thresh;
259 
260 /* Wrap the real function entry probe to avoid possible hanging */
261 static int trace_graph_entry_watchdog(struct ftrace_graph_ent *trace)
262 {
263 	/* This is harmlessly racy, we want to approximately detect a hang */
264 	if (unlikely(++graph_hang_thresh > GRAPH_MAX_FUNC_TEST)) {
265 		ftrace_graph_stop();
266 		printk(KERN_WARNING "BUG: Function graph tracer hang!\n");
267 		if (ftrace_dump_on_oops)
268 			__ftrace_dump(false, DUMP_ALL);
269 		return 0;
270 	}
271 
272 	return trace_graph_entry(trace);
273 }
274 
275 /*
276  * Pretty much the same than for the function tracer from which the selftest
277  * has been borrowed.
278  */
279 int
280 trace_selftest_startup_function_graph(struct tracer *trace,
281 					struct trace_array *tr)
282 {
283 	int ret;
284 	unsigned long count;
285 
286 	/*
287 	 * Simulate the init() callback but we attach a watchdog callback
288 	 * to detect and recover from possible hangs
289 	 */
290 	tracing_reset_online_cpus(tr);
291 	set_graph_array(tr);
292 	ret = register_ftrace_graph(&trace_graph_return,
293 				    &trace_graph_entry_watchdog);
294 	if (ret) {
295 		warn_failed_init_tracer(trace, ret);
296 		goto out;
297 	}
298 	tracing_start_cmdline_record();
299 
300 	/* Sleep for a 1/10 of a second */
301 	msleep(100);
302 
303 	/* Have we just recovered from a hang? */
304 	if (graph_hang_thresh > GRAPH_MAX_FUNC_TEST) {
305 		tracing_selftest_disabled = true;
306 		ret = -1;
307 		goto out;
308 	}
309 
310 	tracing_stop();
311 
312 	/* check the trace buffer */
313 	ret = trace_test_buffer(tr, &count);
314 
315 	trace->reset(tr);
316 	tracing_start();
317 
318 	if (!ret && !count) {
319 		printk(KERN_CONT ".. no entries found ..");
320 		ret = -1;
321 		goto out;
322 	}
323 
324 	/* Don't test dynamic tracing, the function tracer already did */
325 
326 out:
327 	/* Stop it if we failed */
328 	if (ret)
329 		ftrace_graph_stop();
330 
331 	return ret;
332 }
333 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
334 
335 
336 #ifdef CONFIG_IRQSOFF_TRACER
337 int
338 trace_selftest_startup_irqsoff(struct tracer *trace, struct trace_array *tr)
339 {
340 	unsigned long save_max = tracing_max_latency;
341 	unsigned long count;
342 	int ret;
343 
344 	/* start the tracing */
345 	ret = tracer_init(trace, tr);
346 	if (ret) {
347 		warn_failed_init_tracer(trace, ret);
348 		return ret;
349 	}
350 
351 	/* reset the max latency */
352 	tracing_max_latency = 0;
353 	/* disable interrupts for a bit */
354 	local_irq_disable();
355 	udelay(100);
356 	local_irq_enable();
357 
358 	/*
359 	 * Stop the tracer to avoid a warning subsequent
360 	 * to buffer flipping failure because tracing_stop()
361 	 * disables the tr and max buffers, making flipping impossible
362 	 * in case of parallels max irqs off latencies.
363 	 */
364 	trace->stop(tr);
365 	/* stop the tracing. */
366 	tracing_stop();
367 	/* check both trace buffers */
368 	ret = trace_test_buffer(tr, NULL);
369 	if (!ret)
370 		ret = trace_test_buffer(&max_tr, &count);
371 	trace->reset(tr);
372 	tracing_start();
373 
374 	if (!ret && !count) {
375 		printk(KERN_CONT ".. no entries found ..");
376 		ret = -1;
377 	}
378 
379 	tracing_max_latency = save_max;
380 
381 	return ret;
382 }
383 #endif /* CONFIG_IRQSOFF_TRACER */
384 
385 #ifdef CONFIG_PREEMPT_TRACER
386 int
387 trace_selftest_startup_preemptoff(struct tracer *trace, struct trace_array *tr)
388 {
389 	unsigned long save_max = tracing_max_latency;
390 	unsigned long count;
391 	int ret;
392 
393 	/*
394 	 * Now that the big kernel lock is no longer preemptable,
395 	 * and this is called with the BKL held, it will always
396 	 * fail. If preemption is already disabled, simply
397 	 * pass the test. When the BKL is removed, or becomes
398 	 * preemptible again, we will once again test this,
399 	 * so keep it in.
400 	 */
401 	if (preempt_count()) {
402 		printk(KERN_CONT "can not test ... force ");
403 		return 0;
404 	}
405 
406 	/* start the tracing */
407 	ret = tracer_init(trace, tr);
408 	if (ret) {
409 		warn_failed_init_tracer(trace, ret);
410 		return ret;
411 	}
412 
413 	/* reset the max latency */
414 	tracing_max_latency = 0;
415 	/* disable preemption for a bit */
416 	preempt_disable();
417 	udelay(100);
418 	preempt_enable();
419 
420 	/*
421 	 * Stop the tracer to avoid a warning subsequent
422 	 * to buffer flipping failure because tracing_stop()
423 	 * disables the tr and max buffers, making flipping impossible
424 	 * in case of parallels max preempt off latencies.
425 	 */
426 	trace->stop(tr);
427 	/* stop the tracing. */
428 	tracing_stop();
429 	/* check both trace buffers */
430 	ret = trace_test_buffer(tr, NULL);
431 	if (!ret)
432 		ret = trace_test_buffer(&max_tr, &count);
433 	trace->reset(tr);
434 	tracing_start();
435 
436 	if (!ret && !count) {
437 		printk(KERN_CONT ".. no entries found ..");
438 		ret = -1;
439 	}
440 
441 	tracing_max_latency = save_max;
442 
443 	return ret;
444 }
445 #endif /* CONFIG_PREEMPT_TRACER */
446 
447 #if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
448 int
449 trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array *tr)
450 {
451 	unsigned long save_max = tracing_max_latency;
452 	unsigned long count;
453 	int ret;
454 
455 	/*
456 	 * Now that the big kernel lock is no longer preemptable,
457 	 * and this is called with the BKL held, it will always
458 	 * fail. If preemption is already disabled, simply
459 	 * pass the test. When the BKL is removed, or becomes
460 	 * preemptible again, we will once again test this,
461 	 * so keep it in.
462 	 */
463 	if (preempt_count()) {
464 		printk(KERN_CONT "can not test ... force ");
465 		return 0;
466 	}
467 
468 	/* start the tracing */
469 	ret = tracer_init(trace, tr);
470 	if (ret) {
471 		warn_failed_init_tracer(trace, ret);
472 		goto out_no_start;
473 	}
474 
475 	/* reset the max latency */
476 	tracing_max_latency = 0;
477 
478 	/* disable preemption and interrupts for a bit */
479 	preempt_disable();
480 	local_irq_disable();
481 	udelay(100);
482 	preempt_enable();
483 	/* reverse the order of preempt vs irqs */
484 	local_irq_enable();
485 
486 	/*
487 	 * Stop the tracer to avoid a warning subsequent
488 	 * to buffer flipping failure because tracing_stop()
489 	 * disables the tr and max buffers, making flipping impossible
490 	 * in case of parallels max irqs/preempt off latencies.
491 	 */
492 	trace->stop(tr);
493 	/* stop the tracing. */
494 	tracing_stop();
495 	/* check both trace buffers */
496 	ret = trace_test_buffer(tr, NULL);
497 	if (ret)
498 		goto out;
499 
500 	ret = trace_test_buffer(&max_tr, &count);
501 	if (ret)
502 		goto out;
503 
504 	if (!ret && !count) {
505 		printk(KERN_CONT ".. no entries found ..");
506 		ret = -1;
507 		goto out;
508 	}
509 
510 	/* do the test by disabling interrupts first this time */
511 	tracing_max_latency = 0;
512 	tracing_start();
513 	trace->start(tr);
514 
515 	preempt_disable();
516 	local_irq_disable();
517 	udelay(100);
518 	preempt_enable();
519 	/* reverse the order of preempt vs irqs */
520 	local_irq_enable();
521 
522 	trace->stop(tr);
523 	/* stop the tracing. */
524 	tracing_stop();
525 	/* check both trace buffers */
526 	ret = trace_test_buffer(tr, NULL);
527 	if (ret)
528 		goto out;
529 
530 	ret = trace_test_buffer(&max_tr, &count);
531 
532 	if (!ret && !count) {
533 		printk(KERN_CONT ".. no entries found ..");
534 		ret = -1;
535 		goto out;
536 	}
537 
538 out:
539 	tracing_start();
540 out_no_start:
541 	trace->reset(tr);
542 	tracing_max_latency = save_max;
543 
544 	return ret;
545 }
546 #endif /* CONFIG_IRQSOFF_TRACER && CONFIG_PREEMPT_TRACER */
547 
548 #ifdef CONFIG_NOP_TRACER
549 int
550 trace_selftest_startup_nop(struct tracer *trace, struct trace_array *tr)
551 {
552 	/* What could possibly go wrong? */
553 	return 0;
554 }
555 #endif
556 
557 #ifdef CONFIG_SCHED_TRACER
558 static int trace_wakeup_test_thread(void *data)
559 {
560 	/* Make this a RT thread, doesn't need to be too high */
561 	static const struct sched_param param = { .sched_priority = 5 };
562 	struct completion *x = data;
563 
564 	sched_setscheduler(current, SCHED_FIFO, &param);
565 
566 	/* Make it know we have a new prio */
567 	complete(x);
568 
569 	/* now go to sleep and let the test wake us up */
570 	set_current_state(TASK_INTERRUPTIBLE);
571 	schedule();
572 
573 	/* we are awake, now wait to disappear */
574 	while (!kthread_should_stop()) {
575 		/*
576 		 * This is an RT task, do short sleeps to let
577 		 * others run.
578 		 */
579 		msleep(100);
580 	}
581 
582 	return 0;
583 }
584 
585 int
586 trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
587 {
588 	unsigned long save_max = tracing_max_latency;
589 	struct task_struct *p;
590 	struct completion isrt;
591 	unsigned long count;
592 	int ret;
593 
594 	init_completion(&isrt);
595 
596 	/* create a high prio thread */
597 	p = kthread_run(trace_wakeup_test_thread, &isrt, "ftrace-test");
598 	if (IS_ERR(p)) {
599 		printk(KERN_CONT "Failed to create ftrace wakeup test thread ");
600 		return -1;
601 	}
602 
603 	/* make sure the thread is running at an RT prio */
604 	wait_for_completion(&isrt);
605 
606 	/* start the tracing */
607 	ret = tracer_init(trace, tr);
608 	if (ret) {
609 		warn_failed_init_tracer(trace, ret);
610 		return ret;
611 	}
612 
613 	/* reset the max latency */
614 	tracing_max_latency = 0;
615 
616 	/* sleep to let the RT thread sleep too */
617 	msleep(100);
618 
619 	/*
620 	 * Yes this is slightly racy. It is possible that for some
621 	 * strange reason that the RT thread we created, did not
622 	 * call schedule for 100ms after doing the completion,
623 	 * and we do a wakeup on a task that already is awake.
624 	 * But that is extremely unlikely, and the worst thing that
625 	 * happens in such a case, is that we disable tracing.
626 	 * Honestly, if this race does happen something is horrible
627 	 * wrong with the system.
628 	 */
629 
630 	wake_up_process(p);
631 
632 	/* give a little time to let the thread wake up */
633 	msleep(100);
634 
635 	/* stop the tracing. */
636 	tracing_stop();
637 	/* check both trace buffers */
638 	ret = trace_test_buffer(tr, NULL);
639 	if (!ret)
640 		ret = trace_test_buffer(&max_tr, &count);
641 
642 
643 	trace->reset(tr);
644 	tracing_start();
645 
646 	tracing_max_latency = save_max;
647 
648 	/* kill the thread */
649 	kthread_stop(p);
650 
651 	if (!ret && !count) {
652 		printk(KERN_CONT ".. no entries found ..");
653 		ret = -1;
654 	}
655 
656 	return ret;
657 }
658 #endif /* CONFIG_SCHED_TRACER */
659 
660 #ifdef CONFIG_CONTEXT_SWITCH_TRACER
661 int
662 trace_selftest_startup_sched_switch(struct tracer *trace, struct trace_array *tr)
663 {
664 	unsigned long count;
665 	int ret;
666 
667 	/* start the tracing */
668 	ret = tracer_init(trace, tr);
669 	if (ret) {
670 		warn_failed_init_tracer(trace, ret);
671 		return ret;
672 	}
673 
674 	/* Sleep for a 1/10 of a second */
675 	msleep(100);
676 	/* stop the tracing. */
677 	tracing_stop();
678 	/* check the trace buffer */
679 	ret = trace_test_buffer(tr, &count);
680 	trace->reset(tr);
681 	tracing_start();
682 
683 	if (!ret && !count) {
684 		printk(KERN_CONT ".. no entries found ..");
685 		ret = -1;
686 	}
687 
688 	return ret;
689 }
690 #endif /* CONFIG_CONTEXT_SWITCH_TRACER */
691 
692 #ifdef CONFIG_BRANCH_TRACER
693 int
694 trace_selftest_startup_branch(struct tracer *trace, struct trace_array *tr)
695 {
696 	unsigned long count;
697 	int ret;
698 
699 	/* start the tracing */
700 	ret = tracer_init(trace, tr);
701 	if (ret) {
702 		warn_failed_init_tracer(trace, ret);
703 		return ret;
704 	}
705 
706 	/* Sleep for a 1/10 of a second */
707 	msleep(100);
708 	/* stop the tracing. */
709 	tracing_stop();
710 	/* check the trace buffer */
711 	ret = trace_test_buffer(tr, &count);
712 	trace->reset(tr);
713 	tracing_start();
714 
715 	if (!ret && !count) {
716 		printk(KERN_CONT ".. no entries found ..");
717 		ret = -1;
718 	}
719 
720 	return ret;
721 }
722 #endif /* CONFIG_BRANCH_TRACER */
723 
724