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