Add schedule tracing support

This patch introduces the sched_trace infrastructure, which in
principle allows tracing the generated schedule.  However, this patch
does not yet integrate the callbacks with the kernel.

sched_trace: record exec_time in ST_COMPLETION records

sched_trace: add sched_trace_last_suspension_as_completion()

New tracepoint for tracing the completion of sporadic jobs.

4 files changed, 553 insertions, 0 deletions

diff --git a/include/litmus/sched_trace.h b/include/litmus/sched_trace.h
new file mode 100644
index 000000000000..589c63a142b5
--- /dev/null
+++ b/include/litmus/sched_trace.h
@@ -0,0 +1,259 @@
+/*
+ * sched_trace.h -- record scheduler events to a byte stream for offline analysis.
+ */
+#ifndef _LINUX_SCHED_TRACE_H_
+#define _LINUX_SCHED_TRACE_H_
+
+/* all times in nanoseconds */
+
+struct st_trace_header {
+        u8      type;           /* Of what type is this record?  */
+        u8      cpu;            /* On which CPU was it recorded? */
+        u16     pid;            /* PID of the task.              */
+        u32     job;            /* The job sequence number.      */
+};
+
+#define ST_NAME_LEN 16
+struct st_name_data {
+        char    cmd[ST_NAME_LEN];/* The name of the executable of this process. */
+};
+
+struct st_param_data {          /* regular params */
+        u32     wcet;
+        u32     period;
+        u32     phase;
+        u8      partition;
+        u8      class;
+        u8      __unused[2];
+};
+
+struct st_release_data {        /* A job is was/is going to be released. */
+        u64     release;        /* What's the release time?              */
+        u64     deadline;       /* By when must it finish?               */
+};
+
+struct st_assigned_data {       /* A job was asigned to a CPU.           */
+        u64     when;
+        u8      target;         /* Where should it execute?              */
+        u8      __unused[7];
+};
+
+struct st_switch_to_data {      /* A process was switched to on a given CPU.   */
+        u64     when;           /* When did this occur?                        */
+        u32     exec_time;      /* Time the current job has executed.          */
+        u8      __unused[4];
+
+};
+
+struct st_switch_away_data {    /* A process was switched away from on a given CPU. */
+        u64     when;
+        u64     exec_time;
+};
+
+struct st_completion_data {     /* A job completed. */
+        u64     when;
+        u64     forced:1;       /* Set to 1 if job overran and kernel advanced to the
+                                 * next task automatically; set to 0 otherwise.
+                                 */
+        u64     exec_time:63; /* Actual execution time of job. */
+};
+
+struct st_block_data {          /* A task blocks. */
+        u64     when;
+        u64     __unused;
+};
+
+struct st_resume_data {         /* A task resumes. */
+        u64     when;
+        u64     __unused;
+};
+
+struct st_action_data {
+        u64     when;
+        u8      action;
+        u8      __unused[7];
+};
+
+struct st_sys_release_data {
+        u64     when;
+        u64     release;
+};
+
+#define DATA(x) struct st_ ## x ## _data x;
+
+typedef enum {
+        ST_NAME = 1,            /* Start at one, so that we can spot
+                                 * uninitialized records. */
+        ST_PARAM,
+        ST_RELEASE,
+        ST_ASSIGNED,
+        ST_SWITCH_TO,
+        ST_SWITCH_AWAY,
+        ST_COMPLETION,
+        ST_BLOCK,
+        ST_RESUME,
+        ST_ACTION,
+        ST_SYS_RELEASE
+} st_event_record_type_t;
+
+struct st_event_record {
+        struct st_trace_header hdr;
+        union {
+                u64 raw[2];
+
+                DATA(name);
+                DATA(param);
+                DATA(release);
+                DATA(assigned);
+                DATA(switch_to);
+                DATA(switch_away);
+                DATA(completion);
+                DATA(block);
+                DATA(resume);
+                DATA(action);
+                DATA(sys_release);
+        } data;
+};
+
+#undef DATA
+
+#ifdef __KERNEL__
+
+#include <linux/sched.h>
+#include <litmus/feather_trace.h>
+
+#ifdef CONFIG_SCHED_TASK_TRACE
+
+#define SCHED_TRACE(id, callback, task) \
+        ft_event1(id, callback, task)
+#define SCHED_TRACE2(id, callback, task, xtra) \
+        ft_event2(id, callback, task, xtra)
+
+/* provide prototypes; needed on sparc64 */
+#ifndef NO_TASK_TRACE_DECLS
+feather_callback void do_sched_trace_task_name(unsigned long id,
+                                               struct task_struct* task);
+feather_callback void do_sched_trace_task_param(unsigned long id,
+                                                struct task_struct* task);
+feather_callback void do_sched_trace_task_release(unsigned long id,
+                                                  struct task_struct* task);
+feather_callback void do_sched_trace_task_switch_to(unsigned long id,
+                                                    struct task_struct* task);
+feather_callback void do_sched_trace_task_switch_away(unsigned long id,
+                                                      struct task_struct* task);
+feather_callback void do_sched_trace_task_completion(unsigned long id,
+                                                     struct task_struct* task,
+                                                     unsigned long forced);
+feather_callback void do_sched_trace_last_suspension_as_completion(
+                                                unsigned long id,
+                                                struct task_struct* task);
+feather_callback void do_sched_trace_task_block(unsigned long id,
+                                                struct task_struct* task);
+feather_callback void do_sched_trace_task_resume(unsigned long id,
+                                                 struct task_struct* task);
+feather_callback void do_sched_trace_action(unsigned long id,
+                                            struct task_struct* task,
+                                            unsigned long action);
+feather_callback void do_sched_trace_sys_release(unsigned long id,
+                                                 lt_t* start);
+
+#endif
+
+#else
+
+#define SCHED_TRACE(id, callback, task)        /* no tracing */
+#define SCHED_TRACE2(id, callback, task, xtra) /* no tracing */
+
+#endif
+
+#ifdef CONFIG_SCHED_LITMUS_TRACEPOINT
+
+#include <trace/events/litmus.h>
+
+#else
+
+/* Override trace macros to actually do nothing */
+#define trace_litmus_task_param(t)
+#define trace_litmus_task_release(t)
+#define trace_litmus_switch_to(t)
+#define trace_litmus_switch_away(prev)
+#define trace_litmus_task_completion(t, forced)
+#define trace_litmus_task_block(t)
+#define trace_litmus_task_resume(t)
+#define trace_litmus_sys_release(start)
+
+#endif
+
+
+#define SCHED_TRACE_BASE_ID 500
+
+
+#define sched_trace_task_name(t)                                        \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 1,                            \
+                        do_sched_trace_task_name, t)
+
+#define sched_trace_task_param(t)                                       \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 2,                    \
+                                do_sched_trace_task_param, t);          \
+        } while (0)
+
+#define sched_trace_task_release(t)                                     \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 3,                    \
+                                do_sched_trace_task_release, t);        \
+        } while (0)
+
+#define sched_trace_task_switch_to(t)                                   \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 4,                    \
+                        do_sched_trace_task_switch_to, t);              \
+        } while (0)
+
+#define sched_trace_task_switch_away(t)                                 \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 5,                    \
+                        do_sched_trace_task_switch_away, t);            \
+        } while (0)
+
+#define sched_trace_task_completion(t, forced)                          \
+        do {                                                            \
+                SCHED_TRACE2(SCHED_TRACE_BASE_ID + 6,                   \
+                                do_sched_trace_task_completion, t,      \
+                                (unsigned long) forced);                \
+        } while (0)
+
+#define sched_trace_task_block(t)                                       \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 7,                    \
+                        do_sched_trace_task_block, t);                  \
+        } while (0)
+
+#define sched_trace_task_resume(t)                                      \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 8,                    \
+                                do_sched_trace_task_resume, t);         \
+        } while (0)
+
+#define sched_trace_action(t, action)                                   \
+        SCHED_TRACE2(SCHED_TRACE_BASE_ID + 9,                           \
+                do_sched_trace_action, t, (unsigned long) action);
+
+/* when is a pointer, it does not need an explicit cast to unsigned long */
+#define sched_trace_sys_release(when)                                   \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 10,                   \
+                        do_sched_trace_sys_release, when);              \
+        } while (0)
+
+#define sched_trace_last_suspension_as_completion(t)    \
+        do {                                                            \
+                SCHED_TRACE(SCHED_TRACE_BASE_ID + 11,                   \
+                                do_sched_trace_last_suspension_as_completion, t); \
+        } while (0)
+
+#define sched_trace_quantum_boundary() /* NOT IMPLEMENTED */
+
+#endif /* __KERNEL__ */
+
+#endif
diff --git a/litmus/Kconfig b/litmus/Kconfig
index e4624ee20adc..19211ac1320a 100644
--- a/litmus/Kconfig
+++ b/litmus/Kconfig
@@ -24,6 +24,40 @@ config FEATHER_TRACE
           you still need to enable SCHED_TASK_TRACE and/or SCHED_OVERHEAD_TRACE to
           actually enable any events.
 
+config SCHED_TASK_TRACE
+        bool "Trace real-time tasks"
+        depends on FEATHER_TRACE
+        default y
+        help
+          Include support for the sched_trace_XXX() tracing functions. This
+          allows the collection of real-time task events such as job
+          completions, job releases, early completions, etc. This results in  a
+          small overhead in the scheduling code. Disable if the overhead is not
+          acceptable (e.g., benchmarking).
+
+          Say Yes for debugging.
+          Say No for overhead tracing.
+
+config SCHED_TASK_TRACE_SHIFT
+       int "Buffer size for sched_trace_xxx() events"
+       depends on SCHED_TASK_TRACE
+       range 8 13
+       default 9
+       help
+
+         Select the buffer size of sched_trace_xxx() events as a power of two.
+         These buffers are statically allocated as per-CPU data. Each event
+         requires 24 bytes storage plus one additional flag byte. Too large
+         buffers can cause issues with the per-cpu allocator (and waste
+         memory). Too small buffers can cause scheduling events to be lost. The
+         "right" size is workload dependent and depends on the number of tasks,
+         each task's period, each task's number of suspensions, and how often
+         the buffer is flushed.
+
+         Examples: 12 =>   4k events
+                   10 =>   1k events
+                    8 =>  512 events
+
 config SCHED_OVERHEAD_TRACE
         bool "Record timestamps for overhead measurements"
         depends on FEATHER_TRACE
diff --git a/litmus/Makefile b/litmus/Makefile
index 07f065f9748f..6318f1c6fac8 100644
--- a/litmus/Makefile
+++ b/litmus/Makefile
@@ -3,5 +3,6 @@
 #
 
 obj-$(CONFIG_FEATHER_TRACE) += ft_event.o ftdev.o
+obj-$(CONFIG_SCHED_TASK_TRACE) += sched_task_trace.o
 obj-$(CONFIG_SCHED_DEBUG_TRACE) += sched_trace.o
 obj-$(CONFIG_SCHED_OVERHEAD_TRACE) += trace.o
diff --git a/litmus/sched_task_trace.c b/litmus/sched_task_trace.c
new file mode 100644
index 000000000000..cfbc1c77383a
--- /dev/null
+++ b/litmus/sched_task_trace.c
@@ -0,0 +1,259 @@
+/*
+ * sched_task_trace.c -- record scheduling events to a byte stream
+ */
+
+#define NO_TASK_TRACE_DECLS
+
+#include <linux/module.h>
+#include <linux/sched.h>
+#include <linux/percpu.h>
+
+#include <litmus/ftdev.h>
+#include <litmus/litmus.h>
+
+#include <litmus/sched_trace.h>
+#include <litmus/feather_trace.h>
+#include <litmus/ftdev.h>
+
+
+#define NO_EVENTS               (1 << CONFIG_SCHED_TASK_TRACE_SHIFT)
+
+#define now() litmus_clock()
+
+struct local_buffer {
+        struct st_event_record record[NO_EVENTS];
+        char   flag[NO_EVENTS];
+        struct ft_buffer ftbuf;
+};
+
+DEFINE_PER_CPU(struct local_buffer, st_event_buffer);
+
+static struct ftdev st_dev;
+
+static int st_dev_can_open(struct ftdev *dev, unsigned int cpu)
+{
+        return cpu_online(cpu) ? 0 : -ENODEV;
+}
+
+static int __init init_sched_task_trace(void)
+{
+        struct local_buffer* buf;
+        int i, ok = 0, err;
+        printk("Allocated %u sched_trace_xxx() events per CPU "
+               "(buffer size: %d bytes)\n",
+               NO_EVENTS, (int) sizeof(struct local_buffer));
+
+        err = ftdev_init(&st_dev, THIS_MODULE,
+                        num_online_cpus(), "sched_trace");
+        if (err)
+                goto err_out;
+
+        for (i = 0; i < st_dev.minor_cnt; i++) {
+                buf = &per_cpu(st_event_buffer, i);
+                ok += init_ft_buffer(&buf->ftbuf, NO_EVENTS,
+                                     sizeof(struct st_event_record),
+                                     buf->flag,
+                                     buf->record);
+                st_dev.minor[i].buf = &buf->ftbuf;
+        }
+        if (ok == st_dev.minor_cnt) {
+                st_dev.can_open = st_dev_can_open;
+                err = register_ftdev(&st_dev);
+                if (err)
+                        goto err_dealloc;
+        } else {
+                err = -EINVAL;
+                goto err_dealloc;
+        }
+
+        return 0;
+
+err_dealloc:
+        ftdev_exit(&st_dev);
+err_out:
+        printk(KERN_WARNING "Could not register sched_trace module\n");
+        return err;
+}
+
+static void __exit exit_sched_task_trace(void)
+{
+        ftdev_exit(&st_dev);
+}
+
+module_init(init_sched_task_trace);
+module_exit(exit_sched_task_trace);
+
+
+static inline struct st_event_record* get_record(u8 type, struct task_struct* t)
+{
+        struct st_event_record* rec = NULL;
+        struct local_buffer* buf;
+
+        buf = &get_cpu_var(st_event_buffer);
+        if (ft_buffer_start_write(&buf->ftbuf, (void**) &rec)) {
+                rec->hdr.type = type;
+                rec->hdr.cpu  = smp_processor_id();
+                rec->hdr.pid  = t ? t->pid : 0;
+                rec->hdr.job  = t ? t->rt_param.job_params.job_no : 0;
+        } else {
+                put_cpu_var(st_event_buffer);
+        }
+        /* rec will be NULL if it failed */
+        return rec;
+}
+
+static inline void put_record(struct st_event_record* rec)
+{
+        struct local_buffer* buf;
+        /* don't use get_cpu_var() here, get_record() did that already for us */
+        buf = this_cpu_ptr(&st_event_buffer);
+        ft_buffer_finish_write(&buf->ftbuf, rec);
+        /* matches the get_cpu_var() in get_record() */
+        put_cpu_var(st_event_buffer);
+}
+
+feather_callback void do_sched_trace_task_name(unsigned long id, unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_NAME, t);
+        int i;
+        if (rec) {
+                for (i = 0; i < min(TASK_COMM_LEN, ST_NAME_LEN); i++)
+                        rec->data.name.cmd[i] = t->comm[i];
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_task_param(unsigned long id, unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_PARAM, t);
+        if (rec) {
+                rec->data.param.wcet      = get_exec_cost(t);
+                rec->data.param.period    = get_rt_period(t);
+                rec->data.param.phase     = get_rt_phase(t);
+                rec->data.param.partition = get_partition(t);
+                rec->data.param.class     = get_class(t);
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_task_release(unsigned long id, unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_RELEASE, t);
+        if (rec) {
+                rec->data.release.release  = get_release(t);
+                rec->data.release.deadline = get_deadline(t);
+                put_record(rec);
+        }
+}
+
+/* skipped: st_assigned_data, we don't use it atm */
+
+feather_callback void do_sched_trace_task_switch_to(unsigned long id,
+                                                    unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec;
+        if (is_realtime(t)) {
+                rec = get_record(ST_SWITCH_TO, t);
+                if (rec) {
+                        rec->data.switch_to.when      = now();
+                        rec->data.switch_to.exec_time = get_exec_time(t);
+                        put_record(rec);
+                }
+        }
+}
+
+feather_callback void do_sched_trace_task_switch_away(unsigned long id,
+                                                      unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec;
+        if (is_realtime(t)) {
+                rec = get_record(ST_SWITCH_AWAY, t);
+                if (rec) {
+                        rec->data.switch_away.when      = now();
+                        rec->data.switch_away.exec_time = get_exec_time(t);
+                        put_record(rec);
+                }
+        }
+}
+
+feather_callback void do_sched_trace_task_completion(unsigned long id,
+                                                     unsigned long _task,
+                                                     unsigned long forced)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_COMPLETION, t);
+        if (rec) {
+                rec->data.completion.when   = now();
+                rec->data.completion.forced = forced;
+                rec->data.completion.exec_time = get_exec_time(t);
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_last_suspension_as_completion(
+        unsigned long id,
+        unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_COMPLETION, t);
+        if (rec) {
+                rec->data.completion.when
+                        = tsk_rt(t)->job_params.last_suspension;
+                rec->data.completion.forced = 0;
+                rec->data.completion.exec_time = get_exec_time(t);
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_task_block(unsigned long id,
+                                                unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_BLOCK, t);
+        if (rec) {
+                rec->data.block.when      = now();
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_task_resume(unsigned long id,
+                                                 unsigned long _task)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_RESUME, t);
+        if (rec) {
+                rec->data.resume.when      = now();
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_sys_release(unsigned long id,
+                                                 unsigned long _start)
+{
+        lt_t *start = (lt_t*) _start;
+        struct st_event_record* rec = get_record(ST_SYS_RELEASE, NULL);
+        if (rec) {
+                rec->data.sys_release.when    = now();
+                rec->data.sys_release.release = *start;
+                put_record(rec);
+        }
+}
+
+feather_callback void do_sched_trace_action(unsigned long id,
+                                            unsigned long _task,
+                                            unsigned long action)
+{
+        struct task_struct *t = (struct task_struct*) _task;
+        struct st_event_record* rec = get_record(ST_ACTION, t);
+
+        if (rec) {
+                rec->data.action.when   = now();
+                rec->data.action.action = action;
+                put_record(rec);
+        }
+}