Feather-Trace: add LITMUS^RT overhead tracing infrastructure

This patch adds the main infrastructure for tracing overheads in
LITMUS^RT.  It does not yet introduce any tracepoints into the kernel.

4 files changed, 447 insertions, 0 deletions

diff --git a/include/litmus/trace.h b/include/litmus/trace.h
new file mode 100644
index 000000000000..489b3d84f880
--- /dev/null
+++ b/include/litmus/trace.h
@@ -0,0 +1,137 @@
+#ifndef _SYS_TRACE_H_
+#define _SYS_TRACE_H_
+
+#ifdef CONFIG_SCHED_OVERHEAD_TRACE
+
+
+#include <litmus/feather_trace.h>
+#include <litmus/feather_buffer.h>
+
+
+/*********************** TIMESTAMPS ************************/
+
+enum task_type_marker {
+        TSK_BE,
+        TSK_RT,
+        TSK_UNKNOWN
+};
+
+struct timestamp {
+        uint64_t                timestamp:48;
+        uint64_t                pid:16;
+        uint32_t                seq_no;
+        uint8_t                 cpu;
+        uint8_t                 event;
+        uint8_t                 task_type:2;
+        uint8_t                 irq_flag:1;
+        uint8_t                 irq_count:5;
+};
+
+/* tracing callbacks */
+feather_callback void save_timestamp(unsigned long event);
+feather_callback void save_timestamp_def(unsigned long event, unsigned long type);
+feather_callback void save_timestamp_task(unsigned long event, unsigned long t_ptr);
+feather_callback void save_timestamp_cpu(unsigned long event, unsigned long cpu);
+feather_callback void save_timestamp_time(unsigned long event, unsigned long time_ptr);
+feather_callback void save_timestamp_irq(unsigned long event, unsigned long irq_count_ptr);
+feather_callback void save_timestamp_hide_irq(unsigned long event);
+
+#define TIMESTAMP(id) ft_event0(id, save_timestamp)
+
+#define DTIMESTAMP(id, def)  ft_event1(id, save_timestamp_def, (unsigned long) def)
+
+#define TIMESTAMP_CUR(id) DTIMESTAMP(id, is_realtime(current) ? TSK_RT : TSK_BE)
+
+#define TTIMESTAMP(id, task) \
+        ft_event1(id, save_timestamp_task, (unsigned long) task)
+
+#define CTIMESTAMP(id, cpu) \
+        ft_event1(id, save_timestamp_cpu, (unsigned long) cpu)
+
+#define TIMESTAMP_TIME(id, time_ptr) \
+        ft_event1(id, save_timestamp_time, (unsigned long) time_ptr)
+
+#define TIMESTAMP_IRQ(id, irq_count_ptr) \
+        ft_event1(id, save_timestamp_irq, (unsigned long) irq_count_ptr)
+
+#define TIMESTAMP_IN_IRQ(id) \
+        ft_event0(id, save_timestamp_hide_irq)
+
+#else /* !CONFIG_SCHED_OVERHEAD_TRACE */
+
+#define TIMESTAMP(id)        /* no tracing */
+
+#define DTIMESTAMP(id, def)  /* no tracing */
+
+#define TIMESTAMP_CUR(id)    /* no tracing */
+
+#define TTIMESTAMP(id, task) /* no tracing */
+
+#define CTIMESTAMP(id, cpu)  /* no tracing */
+
+#define TIMESTAMP_TIME(id, time_ptr) /* no tracing */
+
+#define TIMESTAMP_IRQ(id, irq_count_ptr) /* no tracing */
+
+#define TIMESTAMP_IN_IRQ(id) /* no tracing */
+
+#endif
+
+
+/* Convention for timestamps
+ * =========================
+ *
+ * In order to process the trace files with a common tool, we use the following
+ * convention to measure execution times: The end time id of a code segment is
+ * always the next number after the start time event id.
+ */
+
+#define __TS_SYSCALL_IN_START(p)        TIMESTAMP_TIME(10, p)
+#define __TS_SYSCALL_IN_END(p)          TIMESTAMP_IRQ(11, p)
+
+#define TS_SYSCALL_OUT_START            TIMESTAMP_CUR(20)
+#define TS_SYSCALL_OUT_END              TIMESTAMP_CUR(21)
+
+#define TS_LOCK_START                   TIMESTAMP_CUR(30)
+#define TS_LOCK_END                     TIMESTAMP_CUR(31)
+
+#define TS_LOCK_SUSPEND                 TIMESTAMP_CUR(38)
+#define TS_LOCK_RESUME                  TIMESTAMP_CUR(39)
+
+#define TS_UNLOCK_START                 TIMESTAMP_CUR(40)
+#define TS_UNLOCK_END                   TIMESTAMP_CUR(41)
+
+#define TS_SCHED_START                  DTIMESTAMP(100, TSK_UNKNOWN) /* we only
+                                                                      * care
+                                                                      * about
+                                                                      * next */
+#define TS_SCHED_END(t)                 TTIMESTAMP(101, t)
+#define TS_SCHED2_START(t)              TTIMESTAMP(102, t)
+#define TS_SCHED2_END(t)                TTIMESTAMP(103, t)
+
+#define TS_CXS_START(t)                 TTIMESTAMP(104, t)
+#define TS_CXS_END(t)                   TTIMESTAMP(105, t)
+
+#define TS_RELEASE_START                DTIMESTAMP(106, TSK_RT)
+#define TS_RELEASE_END                  DTIMESTAMP(107, TSK_RT)
+
+#define TS_TICK_START(t)                TTIMESTAMP(110, t)
+#define TS_TICK_END(t)                  TTIMESTAMP(111, t)
+
+
+#define TS_PLUGIN_SCHED_START           /* TIMESTAMP(120) */  /* currently unused */
+#define TS_PLUGIN_SCHED_END             /* TIMESTAMP(121) */
+
+#define TS_PLUGIN_TICK_START            /* TIMESTAMP(130) */
+#define TS_PLUGIN_TICK_END              /* TIMESTAMP(131) */
+
+#define TS_ENTER_NP_START               TIMESTAMP(140)
+#define TS_ENTER_NP_END                 TIMESTAMP(141)
+
+#define TS_EXIT_NP_START                TIMESTAMP(150)
+#define TS_EXIT_NP_END                  TIMESTAMP(151)
+
+#define TS_SEND_RESCHED_START(c)        CTIMESTAMP(190, c)
+#define TS_SEND_RESCHED_END             TIMESTAMP_IN_IRQ(191)
+
+#endif /* !_SYS_TRACE_H_ */
diff --git a/litmus/Kconfig b/litmus/Kconfig
index 7456eb209cf7..0c7e06b922a1 100644
--- a/litmus/Kconfig
+++ b/litmus/Kconfig
@@ -24,6 +24,31 @@ config FEATHER_TRACE
           you still need to enable SCHED_TASK_TRACE and/or SCHED_OVERHEAD_TRACE to
           actually enable any events.
 
+config SCHED_OVERHEAD_TRACE
+        bool "Record timestamps for overhead measurements"
+        depends on FEATHER_TRACE
+        default y
+        help
+          Export event stream for overhead tracing.
+          Say Yes for overhead tracing.
+
+config SCHED_OVERHEAD_TRACE_SHIFT
+       int "Buffer size for Feather-Trace overhead data"
+       depends on SCHED_OVERHEAD_TRACE
+       range 15 32
+       default 22
+       help
+
+         Select the buffer size for the Feather-Trace overhead tracing
+         infrastructure (/dev/litmus/ft_trace0 & ftcat) as a power of two.  The
+         larger the buffer, the less likely the chance of buffer overflows if
+         the ftcat process is starved by real-time activity. In machines with
+         large memories, large buffer sizes are recommended.
+
+         Examples: 16 =>   2 MB
+                   24 => 512 MB
+                   26 =>  2G MB
+
 endmenu
 
 endmenu
diff --git a/litmus/Makefile b/litmus/Makefile
index bca61e6deb71..99f90c34f141 100644
--- a/litmus/Makefile
+++ b/litmus/Makefile
@@ -3,3 +3,4 @@
 #
 
 obj-$(CONFIG_FEATHER_TRACE) += ft_event.o ftdev.o
+obj-$(CONFIG_SCHED_OVERHEAD_TRACE) += trace.o
diff --git a/litmus/trace.c b/litmus/trace.c
new file mode 100644
index 000000000000..7d29590252fd
--- /dev/null
+++ b/litmus/trace.c
@@ -0,0 +1,284 @@
+#include <linux/sched.h>
+#include <linux/module.h>
+#include <linux/uaccess.h>
+
+#include <litmus/ftdev.h>
+#include <litmus/trace.h>
+
+/* dummy definition of is_realtime() */
+#define is_realtime(t) (0)
+
+/******************************************************************************/
+/*                          Allocation                                        */
+/******************************************************************************/
+
+static struct ftdev overhead_dev;
+
+#define trace_ts_buf overhead_dev.minor[0].buf
+
+static unsigned int ts_seq_no = 0;
+
+DEFINE_PER_CPU(atomic_t, irq_fired_count);
+
+void ft_irq_fired(void)
+{
+        /* Only called with preemptions disabled.  */
+        atomic_inc(&__get_cpu_var(irq_fired_count));
+}
+
+static inline void clear_irq_fired(void)
+{
+        atomic_set(&__raw_get_cpu_var(irq_fired_count), 0);
+}
+
+static inline unsigned int get_and_clear_irq_fired(void)
+{
+        /* This is potentially not atomic  since we might migrate if
+         * preemptions are not disabled. As a tradeoff between
+         * accuracy and tracing overheads, this seems acceptable.
+         * If it proves to be a problem, then one could add a callback
+         * from the migration code to invalidate irq_fired_count.
+         */
+        return atomic_xchg(&__raw_get_cpu_var(irq_fired_count), 0);
+}
+
+static inline void save_irq_flags(struct timestamp *ts, unsigned int irq_count)
+{
+        /* Store how many interrupts occurred. */
+        ts->irq_count = irq_count;
+        /* Extra flag because ts->irq_count overflows quickly. */
+        ts->irq_flag  = irq_count > 0;
+
+}
+
+static inline void write_timestamp(uint8_t event,
+                                   uint8_t type,
+                                   uint8_t cpu,
+                                   uint16_t pid_fragment,
+                                   unsigned int irq_count,
+                                   int record_irq,
+                                   int hide_irq,
+                                   uint64_t timestamp,
+                                   int record_timestamp)
+{
+        unsigned long flags;
+        unsigned int seq_no;
+        struct timestamp *ts;
+
+        /* Avoid preemptions while recording the timestamp. This reduces the
+         * number of "out of order" timestamps in the stream and makes
+         * post-processing easier. */
+
+        local_irq_save(flags);
+
+        seq_no = fetch_and_inc((int *) &ts_seq_no);
+        if (ft_buffer_start_write(trace_ts_buf, (void**)  &ts)) {
+                ts->event     = event;
+                ts->seq_no    = seq_no;
+
+                ts->task_type = type;
+                ts->pid       = pid_fragment;
+
+                ts->cpu       = cpu;
+
+                if (record_irq)
+                        irq_count = get_and_clear_irq_fired();
+
+                save_irq_flags(ts, irq_count - hide_irq);
+
+                if (record_timestamp)
+                        timestamp = ft_timestamp();
+
+                ts->timestamp = timestamp;
+                ft_buffer_finish_write(trace_ts_buf, ts);
+        }
+
+        local_irq_restore(flags);
+}
+
+static void __add_timestamp_user(struct timestamp *pre_recorded)
+{
+        unsigned long flags;
+        unsigned int seq_no;
+        struct timestamp *ts;
+
+
+        local_irq_save(flags);
+
+        seq_no = fetch_and_inc((int *) &ts_seq_no);
+        if (ft_buffer_start_write(trace_ts_buf, (void**)  &ts)) {
+                *ts = *pre_recorded;
+                ts->seq_no = seq_no;
+                ts->cpu    = raw_smp_processor_id();
+                save_irq_flags(ts, get_and_clear_irq_fired());
+                ft_buffer_finish_write(trace_ts_buf, ts);
+        }
+
+        local_irq_restore(flags);
+}
+
+feather_callback void save_timestamp(unsigned long event)
+{
+        write_timestamp(event, TSK_UNKNOWN,
+                        raw_smp_processor_id(),
+                        current->pid,
+                        0, 1, 0,
+                        0, 1);
+}
+
+feather_callback void save_timestamp_def(unsigned long event,
+                                         unsigned long type)
+{
+        write_timestamp(event, type,
+                        raw_smp_processor_id(),
+                        current->pid,
+                        0, 1, 0,
+                        0, 1);
+}
+
+feather_callback void save_timestamp_task(unsigned long event,
+                                          unsigned long t_ptr)
+{
+        struct task_struct *t = (struct task_struct *) t_ptr;
+        int rt = is_realtime(t);
+
+        write_timestamp(event, rt ? TSK_RT : TSK_BE,
+                        raw_smp_processor_id(),
+                        t->pid,
+                        0, 1, 0,
+                        0, 1);
+}
+
+feather_callback void save_timestamp_cpu(unsigned long event,
+                                         unsigned long cpu)
+{
+        write_timestamp(event, TSK_UNKNOWN, cpu, current->pid,
+                        0, 1, 0,
+                        0, 1);
+}
+
+/* fake timestamp to user-reported time */
+feather_callback void save_timestamp_time(unsigned long event,
+                         unsigned long ptr)
+{
+        uint64_t* time = (uint64_t*) ptr;
+
+        write_timestamp(event, is_realtime(current) ? TSK_RT : TSK_BE,
+                        raw_smp_processor_id(), current->pid,
+                        0, 1, 0,
+                        *time, 0);
+}
+
+/* Record user-reported IRQ count */
+feather_callback void save_timestamp_irq(unsigned long event,
+                        unsigned long irq_counter_ptr)
+{
+        uint64_t* irqs = (uint64_t*) irq_counter_ptr;
+
+        write_timestamp(event, is_realtime(current) ? TSK_RT : TSK_BE,
+                        raw_smp_processor_id(), current->pid,
+                        *irqs, 0, 0,
+                        0, 1);
+}
+
+/* Suppress one IRQ from the irq count. Used by TS_SEND_RESCHED_END, which is
+ * called from within an interrupt that is expected. */
+feather_callback void save_timestamp_hide_irq(unsigned long event)
+{
+        write_timestamp(event, is_realtime(current) ? TSK_RT : TSK_BE,
+                        raw_smp_processor_id(), current->pid,
+                        0, 1, 1,
+                        0, 1);
+}
+
+/******************************************************************************/
+/*                        DEVICE FILE DRIVER                                  */
+/******************************************************************************/
+
+#define NO_TIMESTAMPS (2 << CONFIG_SCHED_OVERHEAD_TRACE_SHIFT)
+
+static int alloc_timestamp_buffer(struct ftdev* ftdev, unsigned int idx)
+{
+        unsigned int count = NO_TIMESTAMPS;
+
+        /* An overhead-tracing timestamp should be exactly 16 bytes long. */
+        BUILD_BUG_ON(sizeof(struct timestamp) != 16);
+
+        while (count && !trace_ts_buf) {
+                printk("time stamp buffer: trying to allocate %u time stamps.\n", count);
+                ftdev->minor[idx].buf = alloc_ft_buffer(count, sizeof(struct timestamp));
+                count /= 2;
+        }
+        return ftdev->minor[idx].buf ? 0 : -ENOMEM;
+}
+
+static void free_timestamp_buffer(struct ftdev* ftdev, unsigned int idx)
+{
+        free_ft_buffer(ftdev->minor[idx].buf);
+        ftdev->minor[idx].buf = NULL;
+}
+
+static ssize_t write_timestamp_from_user(struct ft_buffer* buf, size_t len,
+                                         const char __user *from)
+{
+        ssize_t consumed = 0;
+        struct timestamp ts;
+
+        /* don't give us partial timestamps */
+        if (len % sizeof(ts))
+                return -EINVAL;
+
+        while (len >= sizeof(ts)) {
+                if (copy_from_user(&ts, from, sizeof(ts))) {
+                        consumed = -EFAULT;
+                        goto out;
+                }
+                len  -= sizeof(ts);
+                from += sizeof(ts);
+                consumed += sizeof(ts);
+
+                __add_timestamp_user(&ts);
+        }
+
+out:
+        return consumed;
+}
+
+static int __init init_ft_overhead_trace(void)
+{
+        int err, cpu;
+
+        printk("Initializing Feather-Trace overhead tracing device.\n");
+        err = ftdev_init(&overhead_dev, THIS_MODULE, 1, "ft_trace");
+        if (err)
+                goto err_out;
+
+        overhead_dev.alloc = alloc_timestamp_buffer;
+        overhead_dev.free  = free_timestamp_buffer;
+        overhead_dev.write = write_timestamp_from_user;
+
+        err = register_ftdev(&overhead_dev);
+        if (err)
+                goto err_dealloc;
+
+        /* initialize IRQ flags */
+        for (cpu = 0; cpu < NR_CPUS; cpu++)  {
+                clear_irq_fired();
+        }
+
+        return 0;
+
+err_dealloc:
+        ftdev_exit(&overhead_dev);
+err_out:
+        printk(KERN_WARNING "Could not register ft_trace module.\n");
+        return err;
+}
+
+static void __exit exit_ft_overhead_trace(void)
+{
+        ftdev_exit(&overhead_dev);
+}
+
+module_init(init_ft_overhead_trace);
+module_exit(exit_ft_overhead_trace);