ftrace: add self-tests
Steven Rostedt [Mon, 12 May 2008 19:20:44 +0000 (21:20 +0200)]
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

kernel/trace/Kconfig
kernel/trace/trace.c
kernel/trace/trace.h
kernel/trace/trace_functions.c
kernel/trace/trace_irqsoff.c
kernel/trace/trace_sched_switch.c
kernel/trace/trace_sched_wakeup.c
kernel/trace/trace_selftest.c [new file with mode: 0644]

index cad9db1..3f73a17 100644 (file)
@@ -105,3 +105,16 @@ config DYNAMIC_FTRACE
         wakes up once a second and checks to see if any ftrace calls
         were made. If so, it runs stop_machine (stops all CPUS)
         and modifies the code to jump over the call to ftrace.
+
+config FTRACE_SELFTEST
+       bool
+
+config FTRACE_STARTUP_TEST
+       bool "Perform a startup test on ftrace"
+       depends on TRACING
+       select FTRACE_SELFTEST
+       help
+         This option performs a series of startup tests on ftrace. On bootup
+         a series of tests are made to verify that the tracer is
+         functioning properly. It will do tests on all the configured
+         tracers of ftrace.
index 9bad237..f6d026f 100644 (file)
@@ -32,6 +32,8 @@
 unsigned long __read_mostly    tracing_max_latency = (cycle_t)ULONG_MAX;
 unsigned long __read_mostly    tracing_thresh;
 
+static int tracing_disabled = 1;
+
 static long notrace
 ns2usecs(cycle_t nsec)
 {
@@ -217,11 +219,48 @@ int register_tracer(struct tracer *type)
                }
        }
 
+#ifdef CONFIG_FTRACE_STARTUP_TEST
+       if (type->selftest) {
+               struct tracer *saved_tracer = current_trace;
+               struct trace_array_cpu *data;
+               struct trace_array *tr = &global_trace;
+               int saved_ctrl = tr->ctrl;
+               int i;
+               /*
+                * Run a selftest on this tracer.
+                * Here we reset the trace buffer, and set the current
+                * tracer to be this tracer. The tracer can then run some
+                * internal tracing to verify that everything is in order.
+                * If we fail, we do not register this tracer.
+                */
+               for_each_possible_cpu(i) {
+                       if (!data->trace)
+                               continue;
+                       data = tr->data[i];
+                       tracing_reset(data);
+               }
+               current_trace = type;
+               tr->ctrl = 0;
+               /* the test is responsible for initializing and enabling */
+               pr_info("Testing tracer %s: ", type->name);
+               ret = type->selftest(type, tr);
+               /* the test is responsible for resetting too */
+               current_trace = saved_tracer;
+               tr->ctrl = saved_ctrl;
+               if (ret) {
+                       printk(KERN_CONT "FAILED!\n");
+                       goto out;
+               }
+               printk(KERN_CONT "PASSED\n");
+       }
+#endif
+
        type->next = trace_types;
        trace_types = type;
        len = strlen(type->name);
        if (len > max_tracer_type_len)
                max_tracer_type_len = len;
+
  out:
        mutex_unlock(&trace_types_lock);
 
@@ -985,6 +1024,11 @@ __tracing_open(struct inode *inode, struct file *file, int *ret)
 {
        struct trace_iterator *iter;
 
+       if (tracing_disabled) {
+               *ret = -ENODEV;
+               return NULL;
+       }
+
        iter = kzalloc(sizeof(*iter), GFP_KERNEL);
        if (!iter) {
                *ret = -ENOMEM;
@@ -1023,6 +1067,9 @@ __tracing_open(struct inode *inode, struct file *file, int *ret)
 
 int tracing_open_generic(struct inode *inode, struct file *filp)
 {
+       if (tracing_disabled)
+               return -ENODEV;
+
        filp->private_data = inode->i_private;
        return 0;
 }
@@ -1128,6 +1175,9 @@ static int show_traces_open(struct inode *inode, struct file *file)
 {
        int ret;
 
+       if (tracing_disabled)
+               return -ENODEV;
+
        ret = seq_open(file, &show_traces_seq_ops);
        if (!ret) {
                struct seq_file *m = file->private_data;
@@ -1452,6 +1502,11 @@ struct dentry *tracing_init_dentry(void)
        return d_tracer;
 }
 
+#ifdef CONFIG_FTRACE_SELFTEST
+/* Let selftest have access to static functions in this file */
+#include "trace_selftest.c"
+#endif
+
 static __init void tracer_init_debugfs(void)
 {
        struct dentry *d_tracer;
@@ -1585,6 +1640,7 @@ __init static int tracer_alloc_buffers(void)
        void *array;
        struct page *page;
        int pages = 0;
+       int ret = -ENOMEM;
        int i;
 
        /* Allocate the first page for all buffers */
@@ -1650,6 +1706,9 @@ __init static int tracer_alloc_buffers(void)
        register_tracer(&no_tracer);
        current_trace = &no_tracer;
 
+       /* All seems OK, enable tracing */
+       tracing_disabled = 0;
+
        return 0;
 
  free_buffers:
@@ -1678,7 +1737,7 @@ __init static int tracer_alloc_buffers(void)
                }
 #endif
        }
-       return -ENOMEM;
+       return ret;
 }
 
-device_initcall(tracer_alloc_buffers);
+fs_initcall(tracer_alloc_buffers);
index 83e257e..88edbf1 100644 (file)
@@ -99,6 +99,10 @@ struct tracer {
        void                    (*start)(struct trace_iterator *iter);
        void                    (*stop)(struct trace_iterator *iter);
        void                    (*ctrl_update)(struct trace_array *tr);
+#ifdef CONFIG_FTRACE_STARTUP_TEST
+       int                     (*selftest)(struct tracer *trace,
+                                           struct trace_array *tr);
+#endif
        struct tracer           *next;
        int                     print_max;
 };
@@ -185,4 +189,31 @@ extern int unregister_tracer_switch(struct tracer_switch_ops *ops);
 extern unsigned long ftrace_update_tot_cnt;
 #endif
 
+#ifdef CONFIG_FTRACE_STARTUP_TEST
+#ifdef CONFIG_FTRACE
+extern int trace_selftest_startup_function(struct tracer *trace,
+                                          struct trace_array *tr);
+#endif
+#ifdef CONFIG_IRQSOFF_TRACER
+extern int trace_selftest_startup_irqsoff(struct tracer *trace,
+                                         struct trace_array *tr);
+#endif
+#ifdef CONFIG_PREEMPT_TRACER
+extern int trace_selftest_startup_preemptoff(struct tracer *trace,
+                                            struct trace_array *tr);
+#endif
+#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
+extern int trace_selftest_startup_preemptirqsoff(struct tracer *trace,
+                                                struct trace_array *tr);
+#endif
+#ifdef CONFIG_SCHED_TRACER
+extern int trace_selftest_startup_wakeup(struct tracer *trace,
+                                        struct trace_array *tr);
+#endif
+#ifdef CONFIG_CONTEXT_SWITCH_TRACER
+extern int trace_selftest_startup_sched_switch(struct tracer *trace,
+                                              struct trace_array *tr);
+#endif
+#endif /* CONFIG_FTRACE_STARTUP_TEST */
+
 #endif /* _LINUX_KERNEL_TRACE_H */
index 82988c5..5d8ad7a 100644 (file)
@@ -63,6 +63,9 @@ static struct tracer function_trace __read_mostly =
        .init        = function_trace_init,
        .reset       = function_trace_reset,
        .ctrl_update = function_trace_ctrl_update,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_function,
+#endif
 };
 
 static __init int init_function_trace(void)
index 74165f6..14183b8 100644 (file)
@@ -432,6 +432,9 @@ static struct tracer irqsoff_tracer __read_mostly =
        .close          = irqsoff_tracer_close,
        .ctrl_update    = irqsoff_tracer_ctrl_update,
        .print_max      = 1,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_irqsoff,
+#endif
 };
 # define register_irqsoff(trace) register_tracer(&trace)
 #else
@@ -455,6 +458,9 @@ static struct tracer preemptoff_tracer __read_mostly =
        .close          = irqsoff_tracer_close,
        .ctrl_update    = irqsoff_tracer_ctrl_update,
        .print_max      = 1,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_preemptoff,
+#endif
 };
 # define register_preemptoff(trace) register_tracer(&trace)
 #else
@@ -480,6 +486,9 @@ static struct tracer preemptirqsoff_tracer __read_mostly =
        .close          = irqsoff_tracer_close,
        .ctrl_update    = irqsoff_tracer_ctrl_update,
        .print_max      = 1,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_preemptirqsoff,
+#endif
 };
 
 # define register_preemptirqsoff(trace) register_tracer(&trace)
index 2715267..6c92841 100644 (file)
@@ -107,6 +107,9 @@ static struct tracer sched_switch_trace __read_mostly =
        .init           = sched_switch_trace_init,
        .reset          = sched_switch_trace_reset,
        .ctrl_update    = sched_switch_trace_ctrl_update,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_sched_switch,
+#endif
 };
 
 __init static int init_sched_switch_trace(void)
index 7c3ccef..3d10ff0 100644 (file)
@@ -295,6 +295,9 @@ static struct tracer wakeup_tracer __read_mostly =
        .close          = wakeup_tracer_close,
        .ctrl_update    = wakeup_tracer_ctrl_update,
        .print_max      = 1,
+#ifdef CONFIG_FTRACE_SELFTEST
+       .selftest    = trace_selftest_startup_wakeup,
+#endif
 };
 
 __init static int init_wakeup_tracer(void)
diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
new file mode 100644 (file)
index 0000000..ef4d3cc
--- /dev/null
@@ -0,0 +1,415 @@
+/* Include in trace.c */
+
+#include <linux/kthread.h>
+
+static inline int trace_valid_entry(struct trace_entry *entry)
+{
+       switch (entry->type) {
+       case TRACE_FN:
+       case TRACE_CTX:
+               return 1;
+       }
+       return 0;
+}
+
+static int
+trace_test_buffer_cpu(struct trace_array *tr, struct trace_array_cpu *data)
+{
+       struct page *page;
+       struct trace_entry *entries;
+       int idx = 0;
+       int i;
+
+       page = list_entry(data->trace_pages.next, struct page, lru);
+       entries = page_address(page);
+
+       if (data->trace != entries)
+               goto failed;
+
+       /*
+        * The starting trace buffer always has valid elements,
+        * if any element exits.
+        */
+       entries = data->trace;
+
+       for (i = 0; i < tr->entries; i++) {
+
+               if (i < data->trace_idx &&
+                   !trace_valid_entry(&entries[idx])) {
+                       printk(KERN_CONT ".. invalid entry %d ", entries[idx].type);
+                       goto failed;
+               }
+
+               idx++;
+               if (idx >= ENTRIES_PER_PAGE) {
+                       page = virt_to_page(entries);
+                       if (page->lru.next == &data->trace_pages) {
+                               if (i != tr->entries - 1) {
+                                       printk(KERN_CONT ".. entries buffer mismatch");
+                                       goto failed;
+                               }
+                       } else {
+                               page = list_entry(page->lru.next, struct page, lru);
+                               entries = page_address(page);
+                       }
+                       idx = 0;
+               }
+       }
+
+       page = virt_to_page(entries);
+       if (page->lru.next != &data->trace_pages) {
+               printk(KERN_CONT ".. too many entries");
+               goto failed;
+       }
+
+       return 0;
+
+ failed:
+       printk(KERN_CONT ".. corrupted trace buffer .. ");
+       return -1;
+}
+
+/*
+ * Test the trace buffer to see if all the elements
+ * are still sane.
+ */
+static int trace_test_buffer(struct trace_array *tr, unsigned long *count)
+{
+       unsigned long cnt = 0;
+       int cpu;
+       int ret = 0;
+
+       for_each_possible_cpu(cpu) {
+               if (!tr->data[cpu]->trace)
+                       continue;
+
+               cnt += tr->data[cpu]->trace_idx;
+               printk("%d: count = %ld\n", cpu, cnt);
+
+               ret = trace_test_buffer_cpu(tr, tr->data[cpu]);
+               if (ret)
+                       break;
+       }
+
+       if (count)
+               *count = cnt;
+
+       return ret;
+}
+
+#ifdef CONFIG_FTRACE
+/*
+ * Simple verification test of ftrace function tracer.
+ * Enable ftrace, sleep 1/10 second, and then read the trace
+ * buffer to see if all is in order.
+ */
+int
+trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long count;
+       int ret;
+
+       /* make sure functions have been recorded */
+       ret = ftrace_force_update();
+       if (ret) {
+               printk(KERN_CONT ".. ftraced failed .. ");
+               return ret;
+       }
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+       /* Sleep for a 1/10 of a second */
+       msleep(100);
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check the trace buffer */
+       ret = trace_test_buffer(tr, &count);
+       trace->reset(tr);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+       }
+
+       return ret;
+}
+#endif /* CONFIG_FTRACE */
+
+#ifdef CONFIG_IRQSOFF_TRACER
+int
+trace_selftest_startup_irqsoff(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long save_max = tracing_max_latency;
+       unsigned long count;
+       int ret;
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+       /* reset the max latency */
+       tracing_max_latency = 0;
+       /* disable interrupts for a bit */
+       local_irq_disable();
+       udelay(100);
+       local_irq_enable();
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check both trace buffers */
+       ret = trace_test_buffer(tr, NULL);
+       if (!ret)
+               ret = trace_test_buffer(&max_tr, &count);
+       trace->reset(tr);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+       }
+
+       tracing_max_latency = save_max;
+
+       return ret;
+}
+#endif /* CONFIG_IRQSOFF_TRACER */
+
+#ifdef CONFIG_PREEMPT_TRACER
+int
+trace_selftest_startup_preemptoff(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long save_max = tracing_max_latency;
+       unsigned long count;
+       int ret;
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+       /* reset the max latency */
+       tracing_max_latency = 0;
+       /* disable preemption for a bit */
+       preempt_disable();
+       udelay(100);
+       preempt_enable();
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check both trace buffers */
+       ret = trace_test_buffer(tr, NULL);
+       if (!ret)
+               ret = trace_test_buffer(&max_tr, &count);
+       trace->reset(tr);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+       }
+
+       tracing_max_latency = save_max;
+
+       return ret;
+}
+#endif /* CONFIG_PREEMPT_TRACER */
+
+#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
+int
+trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long save_max = tracing_max_latency;
+       unsigned long count;
+       int ret;
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+
+       /* reset the max latency */
+       tracing_max_latency = 0;
+
+       /* disable preemption and interrupts for a bit */
+       preempt_disable();
+       local_irq_disable();
+       udelay(100);
+       preempt_enable();
+       /* reverse the order of preempt vs irqs */
+       local_irq_enable();
+
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check both trace buffers */
+       ret = trace_test_buffer(tr, NULL);
+       if (ret)
+               goto out;
+
+       ret = trace_test_buffer(&max_tr, &count);
+       if (ret)
+               goto out;
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+               goto out;
+       }
+
+       /* do the test by disabling interrupts first this time */
+       tracing_max_latency = 0;
+       tr->ctrl = 1;
+       trace->ctrl_update(tr);
+       preempt_disable();
+       local_irq_disable();
+       udelay(100);
+       preempt_enable();
+       /* reverse the order of preempt vs irqs */
+       local_irq_enable();
+
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check both trace buffers */
+       ret = trace_test_buffer(tr, NULL);
+       if (ret)
+               goto out;
+
+       ret = trace_test_buffer(&max_tr, &count);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+               goto out;
+       }
+
+ out:
+       trace->reset(tr);
+       tracing_max_latency = save_max;
+
+       return ret;
+}
+#endif /* CONFIG_IRQSOFF_TRACER && CONFIG_PREEMPT_TRACER */
+
+#ifdef CONFIG_SCHED_TRACER
+static int trace_wakeup_test_thread(void *data)
+{
+       struct completion *x = data;
+
+       /* Make this a RT thread, doesn't need to be too high */
+
+       rt_mutex_setprio(current, MAX_RT_PRIO - 5);
+
+       /* Make it know we have a new prio */
+       complete(x);
+
+       /* now go to sleep and let the test wake us up */
+       set_current_state(TASK_INTERRUPTIBLE);
+       schedule();
+
+       /* we are awake, now wait to disappear */
+       while (!kthread_should_stop()) {
+               /*
+                * This is an RT task, do short sleeps to let
+                * others run.
+                */
+               msleep(100);
+       }
+
+       return 0;
+}
+
+int
+trace_selftest_startup_wakeup(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long save_max = tracing_max_latency;
+       struct task_struct *p;
+       struct completion isrt;
+       unsigned long count;
+       int ret;
+
+       init_completion(&isrt);
+
+       /* create a high prio thread */
+       p = kthread_run(trace_wakeup_test_thread, &isrt, "ftrace-test");
+       if (!IS_ERR(p)) {
+               printk(KERN_CONT "Failed to create ftrace wakeup test thread ");
+               return -1;
+       }
+
+       /* make sure the thread is running at an RT prio */
+       wait_for_completion(&isrt);
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+       /* reset the max latency */
+       tracing_max_latency = 0;
+
+       /* sleep to let the RT thread sleep too */
+       msleep(100);
+
+       /*
+        * Yes this is slightly racy. It is possible that for some
+        * strange reason that the RT thread we created, did not
+        * call schedule for 100ms after doing the completion,
+        * and we do a wakeup on a task that already is awake.
+        * But that is extremely unlikely, and the worst thing that
+        * happens in such a case, is that we disable tracing.
+        * Honestly, if this race does happen something is horrible
+        * wrong with the system.
+        */
+
+       wake_up_process(p);
+
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check both trace buffers */
+       ret = trace_test_buffer(tr, NULL);
+       if (!ret)
+               ret = trace_test_buffer(&max_tr, &count);
+
+
+       trace->reset(tr);
+
+       tracing_max_latency = save_max;
+
+       /* kill the thread */
+       kthread_stop(p);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+       }
+
+       return ret;
+}
+#endif /* CONFIG_SCHED_TRACER */
+
+#ifdef CONFIG_CONTEXT_SWITCH_TRACER
+int
+trace_selftest_startup_sched_switch(struct tracer *trace, struct trace_array *tr)
+{
+       unsigned long count;
+       int ret;
+
+       /* start the tracing */
+       tr->ctrl = 1;
+       trace->init(tr);
+       /* Sleep for a 1/10 of a second */
+       msleep(100);
+       /* stop the tracing. */
+       tr->ctrl = 0;
+       trace->ctrl_update(tr);
+       /* check the trace buffer */
+       ret = trace_test_buffer(tr, &count);
+       trace->reset(tr);
+
+       if (!ret && !count) {
+               printk(KERN_CONT ".. no entries found ..");
+               ret = -1;
+       }
+
+       return ret;
+}
+#endif /* CONFIG_CONTEXT_SWITCH_TRACER */
+
+#ifdef CONFIG_DYNAMIC_FTRACE
+#endif /* CONFIG_DYNAMIC_FTRACE */