xref: /linux/kernel/trace/trace_selftest.c (revision 367b8112fe2ea5c39a7bb4d263dcdd9b612fae18)
1 /* Include in trace.c */
2 
3 #include <linux/kthread.h>
4 #include <linux/delay.h>
5 
6 static inline int trace_valid_entry(struct trace_entry *entry)
7 {
8 	switch (entry->type) {
9 	case TRACE_FN:
10 	case TRACE_CTX:
11 	case TRACE_WAKE:
12 	case TRACE_CONT:
13 	case TRACE_STACK:
14 	case TRACE_PRINT:
15 	case TRACE_SPECIAL:
16 		return 1;
17 	}
18 	return 0;
19 }
20 
21 static int trace_test_buffer_cpu(struct trace_array *tr, int cpu)
22 {
23 	struct ring_buffer_event *event;
24 	struct trace_entry *entry;
25 
26 	while ((event = ring_buffer_consume(tr->buffer, cpu, NULL))) {
27 		entry = ring_buffer_event_data(event);
28 
29 		if (!trace_valid_entry(entry)) {
30 			printk(KERN_CONT ".. invalid entry %d ",
31 				entry->type);
32 			goto failed;
33 		}
34 	}
35 	return 0;
36 
37  failed:
38 	/* disable tracing */
39 	tracing_disabled = 1;
40 	printk(KERN_CONT ".. corrupted trace buffer .. ");
41 	return -1;
42 }
43 
44 /*
45  * Test the trace buffer to see if all the elements
46  * are still sane.
47  */
48 static int trace_test_buffer(struct trace_array *tr, unsigned long *count)
49 {
50 	unsigned long flags, cnt = 0;
51 	int cpu, ret = 0;
52 
53 	/* Don't allow flipping of max traces now */
54 	raw_local_irq_save(flags);
55 	__raw_spin_lock(&ftrace_max_lock);
56 
57 	cnt = ring_buffer_entries(tr->buffer);
58 
59 	for_each_possible_cpu(cpu) {
60 		ret = trace_test_buffer_cpu(tr, cpu);
61 		if (ret)
62 			break;
63 	}
64 	__raw_spin_unlock(&ftrace_max_lock);
65 	raw_local_irq_restore(flags);
66 
67 	if (count)
68 		*count = cnt;
69 
70 	return ret;
71 }
72 
73 #ifdef CONFIG_FUNCTION_TRACER
74 
75 #ifdef CONFIG_DYNAMIC_FTRACE
76 
77 #define __STR(x) #x
78 #define STR(x) __STR(x)
79 
80 /* Test dynamic code modification and ftrace filters */
81 int trace_selftest_startup_dynamic_tracing(struct tracer *trace,
82 					   struct trace_array *tr,
83 					   int (*func)(void))
84 {
85 	int save_ftrace_enabled = ftrace_enabled;
86 	int save_tracer_enabled = tracer_enabled;
87 	unsigned long count;
88 	char *func_name;
89 	int ret;
90 
91 	/* The ftrace test PASSED */
92 	printk(KERN_CONT "PASSED\n");
93 	pr_info("Testing dynamic ftrace: ");
94 
95 	/* enable tracing, and record the filter function */
96 	ftrace_enabled = 1;
97 	tracer_enabled = 1;
98 
99 	/* passed in by parameter to fool gcc from optimizing */
100 	func();
101 
102 	/*
103 	 * Some archs *cough*PowerPC*cough* add charachters to the
104 	 * start of the function names. We simply put a '*' to
105 	 * accomodate them.
106 	 */
107 	func_name = "*" STR(DYN_FTRACE_TEST_NAME);
108 
109 	/* filter only on our function */
110 	ftrace_set_filter(func_name, strlen(func_name), 1);
111 
112 	/* enable tracing */
113 	tr->ctrl = 1;
114 	trace->init(tr);
115 
116 	/* Sleep for a 1/10 of a second */
117 	msleep(100);
118 
119 	/* we should have nothing in the buffer */
120 	ret = trace_test_buffer(tr, &count);
121 	if (ret)
122 		goto out;
123 
124 	if (count) {
125 		ret = -1;
126 		printk(KERN_CONT ".. filter did not filter .. ");
127 		goto out;
128 	}
129 
130 	/* call our function again */
131 	func();
132 
133 	/* sleep again */
134 	msleep(100);
135 
136 	/* stop the tracing. */
137 	tr->ctrl = 0;
138 	trace->ctrl_update(tr);
139 	ftrace_enabled = 0;
140 
141 	/* check the trace buffer */
142 	ret = trace_test_buffer(tr, &count);
143 	trace->reset(tr);
144 
145 	/* we should only have one item */
146 	if (!ret && count != 1) {
147 		printk(KERN_CONT ".. filter failed count=%ld ..", count);
148 		ret = -1;
149 		goto out;
150 	}
151  out:
152 	ftrace_enabled = save_ftrace_enabled;
153 	tracer_enabled = save_tracer_enabled;
154 
155 	/* Enable tracing on all functions again */
156 	ftrace_set_filter(NULL, 0, 1);
157 
158 	return ret;
159 }
160 #else
161 # define trace_selftest_startup_dynamic_tracing(trace, tr, func) ({ 0; })
162 #endif /* CONFIG_DYNAMIC_FTRACE */
163 /*
164  * Simple verification test of ftrace function tracer.
165  * Enable ftrace, sleep 1/10 second, and then read the trace
166  * buffer to see if all is in order.
167  */
168 int
169 trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
170 {
171 	int save_ftrace_enabled = ftrace_enabled;
172 	int save_tracer_enabled = tracer_enabled;
173 	unsigned long count;
174 	int ret;
175 
176 	/* make sure msleep has been recorded */
177 	msleep(1);
178 
179 	/* start the tracing */
180 	ftrace_enabled = 1;
181 	tracer_enabled = 1;
182 
183 	tr->ctrl = 1;
184 	trace->init(tr);
185 	/* Sleep for a 1/10 of a second */
186 	msleep(100);
187 	/* stop the tracing. */
188 	tr->ctrl = 0;
189 	trace->ctrl_update(tr);
190 	ftrace_enabled = 0;
191 
192 	/* check the trace buffer */
193 	ret = trace_test_buffer(tr, &count);
194 	trace->reset(tr);
195 
196 	if (!ret && !count) {
197 		printk(KERN_CONT ".. no entries found ..");
198 		ret = -1;
199 		goto out;
200 	}
201 
202 	ret = trace_selftest_startup_dynamic_tracing(trace, tr,
203 						     DYN_FTRACE_TEST_NAME);
204 
205  out:
206 	ftrace_enabled = save_ftrace_enabled;
207 	tracer_enabled = save_tracer_enabled;
208 
209 	/* kill ftrace totally if we failed */
210 	if (ret)
211 		ftrace_kill();
212 
213 	return ret;
214 }
215 #endif /* CONFIG_FUNCTION_TRACER */
216 
217 #ifdef CONFIG_IRQSOFF_TRACER
218 int
219 trace_selftest_startup_irqsoff(struct tracer *trace, struct trace_array *tr)
220 {
221 	unsigned long save_max = tracing_max_latency;
222 	unsigned long count;
223 	int ret;
224 
225 	/* start the tracing */
226 	tr->ctrl = 1;
227 	trace->init(tr);
228 	/* reset the max latency */
229 	tracing_max_latency = 0;
230 	/* disable interrupts for a bit */
231 	local_irq_disable();
232 	udelay(100);
233 	local_irq_enable();
234 	/* stop the tracing. */
235 	tr->ctrl = 0;
236 	trace->ctrl_update(tr);
237 	/* check both trace buffers */
238 	ret = trace_test_buffer(tr, NULL);
239 	if (!ret)
240 		ret = trace_test_buffer(&max_tr, &count);
241 	trace->reset(tr);
242 
243 	if (!ret && !count) {
244 		printk(KERN_CONT ".. no entries found ..");
245 		ret = -1;
246 	}
247 
248 	tracing_max_latency = save_max;
249 
250 	return ret;
251 }
252 #endif /* CONFIG_IRQSOFF_TRACER */
253 
254 #ifdef CONFIG_PREEMPT_TRACER
255 int
256 trace_selftest_startup_preemptoff(struct tracer *trace, struct trace_array *tr)
257 {
258 	unsigned long save_max = tracing_max_latency;
259 	unsigned long count;
260 	int ret;
261 
262 	/* start the tracing */
263 	tr->ctrl = 1;
264 	trace->init(tr);
265 	/* reset the max latency */
266 	tracing_max_latency = 0;
267 	/* disable preemption for a bit */
268 	preempt_disable();
269 	udelay(100);
270 	preempt_enable();
271 	/* stop the tracing. */
272 	tr->ctrl = 0;
273 	trace->ctrl_update(tr);
274 	/* check both trace buffers */
275 	ret = trace_test_buffer(tr, NULL);
276 	if (!ret)
277 		ret = trace_test_buffer(&max_tr, &count);
278 	trace->reset(tr);
279 
280 	if (!ret && !count) {
281 		printk(KERN_CONT ".. no entries found ..");
282 		ret = -1;
283 	}
284 
285 	tracing_max_latency = save_max;
286 
287 	return ret;
288 }
289 #endif /* CONFIG_PREEMPT_TRACER */
290 
291 #if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
292 int
293 trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array *tr)
294 {
295 	unsigned long save_max = tracing_max_latency;
296 	unsigned long count;
297 	int ret;
298 
299 	/* start the tracing */
300 	tr->ctrl = 1;
301 	trace->init(tr);
302 
303 	/* reset the max latency */
304 	tracing_max_latency = 0;
305 
306 	/* disable preemption and interrupts for a bit */
307 	preempt_disable();
308 	local_irq_disable();
309 	udelay(100);
310 	preempt_enable();
311 	/* reverse the order of preempt vs irqs */
312 	local_irq_enable();
313 
314 	/* stop the tracing. */
315 	tr->ctrl = 0;
316 	trace->ctrl_update(tr);
317 	/* check both trace buffers */
318 	ret = trace_test_buffer(tr, NULL);
319 	if (ret)
320 		goto out;
321 
322 	ret = trace_test_buffer(&max_tr, &count);
323 	if (ret)
324 		goto out;
325 
326 	if (!ret && !count) {
327 		printk(KERN_CONT ".. no entries found ..");
328 		ret = -1;
329 		goto out;
330 	}
331 
332 	/* do the test by disabling interrupts first this time */
333 	tracing_max_latency = 0;
334 	tr->ctrl = 1;
335 	trace->ctrl_update(tr);
336 	preempt_disable();
337 	local_irq_disable();
338 	udelay(100);
339 	preempt_enable();
340 	/* reverse the order of preempt vs irqs */
341 	local_irq_enable();
342 
343 	/* stop the tracing. */
344 	tr->ctrl = 0;
345 	trace->ctrl_update(tr);
346 	/* check both trace buffers */
347 	ret = trace_test_buffer(tr, NULL);
348 	if (ret)
349 		goto out;
350 
351 	ret = trace_test_buffer(&max_tr, &count);
352 
353 	if (!ret && !count) {
354 		printk(KERN_CONT ".. no entries found ..");
355 		ret = -1;
356 		goto out;
357 	}
358 
359  out:
360 	trace->reset(tr);
361 	tracing_max_latency = save_max;
362 
363 	return ret;
364 }
365 #endif /* CONFIG_IRQSOFF_TRACER && CONFIG_PREEMPT_TRACER */
366 
367 #ifdef CONFIG_NOP_TRACER
368 int
369 trace_selftest_startup_nop(struct tracer *trace, struct trace_array *tr)
370 {
371 	/* What could possibly go wrong? */
372 	return 0;
373 }
374 #endif
375 
376 #ifdef CONFIG_SCHED_TRACER
377 static int trace_wakeup_test_thread(void *data)
378 {
379 	/* Make this a RT thread, doesn't need to be too high */
380 	struct sched_param param = { .sched_priority = 5 };
381 	struct completion *x = data;
382 
383 	sched_setscheduler(current, SCHED_FIFO, &param);
384 
385 	/* Make it know we have a new prio */
386 	complete(x);
387 
388 	/* now go to sleep and let the test wake us up */
389 	set_current_state(TASK_INTERRUPTIBLE);
390 	schedule();
391 
392 	/* we are awake, now wait to disappear */
393 	while (!kthread_should_stop()) {
394 		/*
395 		 * This is an RT task, do short sleeps to let
396 		 * others run.
397 		 */
398 		msleep(100);
399 	}
400 
401 	return 0;
402 }
403 
404 int
405 trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
406 {
407 	unsigned long save_max = tracing_max_latency;
408 	struct task_struct *p;
409 	struct completion isrt;
410 	unsigned long count;
411 	int ret;
412 
413 	init_completion(&isrt);
414 
415 	/* create a high prio thread */
416 	p = kthread_run(trace_wakeup_test_thread, &isrt, "ftrace-test");
417 	if (IS_ERR(p)) {
418 		printk(KERN_CONT "Failed to create ftrace wakeup test thread ");
419 		return -1;
420 	}
421 
422 	/* make sure the thread is running at an RT prio */
423 	wait_for_completion(&isrt);
424 
425 	/* start the tracing */
426 	tr->ctrl = 1;
427 	trace->init(tr);
428 	/* reset the max latency */
429 	tracing_max_latency = 0;
430 
431 	/* sleep to let the RT thread sleep too */
432 	msleep(100);
433 
434 	/*
435 	 * Yes this is slightly racy. It is possible that for some
436 	 * strange reason that the RT thread we created, did not
437 	 * call schedule for 100ms after doing the completion,
438 	 * and we do a wakeup on a task that already is awake.
439 	 * But that is extremely unlikely, and the worst thing that
440 	 * happens in such a case, is that we disable tracing.
441 	 * Honestly, if this race does happen something is horrible
442 	 * wrong with the system.
443 	 */
444 
445 	wake_up_process(p);
446 
447 	/* give a little time to let the thread wake up */
448 	msleep(100);
449 
450 	/* stop the tracing. */
451 	tr->ctrl = 0;
452 	trace->ctrl_update(tr);
453 	/* check both trace buffers */
454 	ret = trace_test_buffer(tr, NULL);
455 	if (!ret)
456 		ret = trace_test_buffer(&max_tr, &count);
457 
458 
459 	trace->reset(tr);
460 
461 	tracing_max_latency = save_max;
462 
463 	/* kill the thread */
464 	kthread_stop(p);
465 
466 	if (!ret && !count) {
467 		printk(KERN_CONT ".. no entries found ..");
468 		ret = -1;
469 	}
470 
471 	return ret;
472 }
473 #endif /* CONFIG_SCHED_TRACER */
474 
475 #ifdef CONFIG_CONTEXT_SWITCH_TRACER
476 int
477 trace_selftest_startup_sched_switch(struct tracer *trace, struct trace_array *tr)
478 {
479 	unsigned long count;
480 	int ret;
481 
482 	/* start the tracing */
483 	tr->ctrl = 1;
484 	trace->init(tr);
485 	/* Sleep for a 1/10 of a second */
486 	msleep(100);
487 	/* stop the tracing. */
488 	tr->ctrl = 0;
489 	trace->ctrl_update(tr);
490 	/* check the trace buffer */
491 	ret = trace_test_buffer(tr, &count);
492 	trace->reset(tr);
493 
494 	if (!ret && !count) {
495 		printk(KERN_CONT ".. no entries found ..");
496 		ret = -1;
497 	}
498 
499 	return ret;
500 }
501 #endif /* CONFIG_CONTEXT_SWITCH_TRACER */
502 
503 #ifdef CONFIG_SYSPROF_TRACER
504 int
505 trace_selftest_startup_sysprof(struct tracer *trace, struct trace_array *tr)
506 {
507 	unsigned long count;
508 	int ret;
509 
510 	/* start the tracing */
511 	tr->ctrl = 1;
512 	trace->init(tr);
513 	/* Sleep for a 1/10 of a second */
514 	msleep(100);
515 	/* stop the tracing. */
516 	tr->ctrl = 0;
517 	trace->ctrl_update(tr);
518 	/* check the trace buffer */
519 	ret = trace_test_buffer(tr, &count);
520 	trace->reset(tr);
521 
522 	return ret;
523 }
524 #endif /* CONFIG_SYSPROF_TRACER */
525