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