sched_trace: new implementation

This provides and hooks up a new made-from-scratch sched_trace()
implementation based on Feather-Trace and ftdev.

10 files changed, 239 insertions, 44 deletions

diff --git a/include/litmus/sched_trace.h b/include/litmus/sched_trace.h
index 3be349a69b..c5c55c6554 100644
--- a/include/litmus/sched_trace.h
+++ b/include/litmus/sched_trace.h
@@ -12,8 +12,9 @@ struct st_trace_header {
         u32     job;            /* The job sequence number.      */
 };
 
+#define ST_NAME_LEN 16
 struct st_name_data {
-        char    cmd[16];        /* The name of the executable of this process. */
+        char    cmd[ST_NAME_LEN];/* The name of the executable of this process. */
 };
 
 struct st_param_data {          /* regular params */
@@ -104,31 +105,45 @@ struct st_event_record {
 #ifdef __KERNEL__
 
 #include <linux/sched.h>
-
-/* dummies, need to be re-implemented */
-/* used in sched.c */
-#define sched_trace_task_arrival(t)
-#define sched_trace_task_departure(t)
-#define sched_trace_task_preemption(t, by)
-#define sched_trace_task_scheduled(t)
-
-/* used in scheduler plugins */
-#define sched_trace_job_release(t)
-#define sched_trace_job_completion(t)
-
-
+#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)
 
 #else
 
+#define SCHED_TRACE(id, callback, task)        /* no tracing */
+#define SCHED_TRACE2(id, callback, task, xtra) /* no tracing */
 
 #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) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 2, do_sched_trace_task_param, t)
+#define sched_trace_task_release(t) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 3, do_sched_trace_task_release, t)
+#define sched_trace_task_switch_to(t) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 4, do_sched_trace_task_switch_to, t)
+#define sched_trace_task_switch_away(t) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 5, do_sched_trace_task_switch_away, t)
+#define sched_trace_task_completion(t, forced) \
+        SCHED_TRACE2(SCHED_TRACE_BASE_ID + 6, do_sched_trace_task_completion, t, \
+                     forced)
+#define sched_trace_task_block(t) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 7, do_sched_trace_task_block, t)
+#define sched_trace_task_resume(t) \
+        SCHED_TRACE(SCHED_TRACE_BASE_ID + 8, do_sched_trace_task_resume, t)
+
+
 #ifdef CONFIG_SCHED_DEBUG_TRACE
 void sched_trace_log_message(const char* fmt, ...);
 
diff --git a/kernel/sched.c b/kernel/sched.c
index 9ee07ba365..fdeced2628 100644
--- a/kernel/sched.c
+++ b/kernel/sched.c
@@ -67,6 +67,7 @@
 #include <asm/tlb.h>
 #include <asm/irq_regs.h>
 
+#include <litmus/sched_trace.h>
 #include <litmus/trace.h>
 
 #include <litmus/norqlock.h>
@@ -3691,6 +3692,8 @@ need_resched_nonpreemptible:
                 rq->nr_switches++;
                 rq->curr = next;
                 ++*switch_count;
+                sched_trace_task_switch_away(prev);
+                sched_trace_task_switch_to(next);
 
                 TS_SCHED_END(next);
                 TS_CXS_START(next);
diff --git a/litmus/Makefile b/litmus/Makefile
index 2b2ab5be1f..fa39a2b753 100644
--- a/litmus/Makefile
+++ b/litmus/Makefile
@@ -12,4 +12,5 @@ obj-y     = sched_plugin.o litmus.o \
             sched_pfair.o
 
 obj-$(CONFIG_FEATHER_TRACE) += trace.o ft_event.o ftdev.o
+obj-$(CONFIG_SCHED_TASK_TRACE) += sched_task_trace.o
 obj-$(CONFIG_SCHED_DEBUG_TRACE) +=  sched_trace.o
\ No newline at end of file
diff --git a/litmus/rt_domain.c b/litmus/rt_domain.c
index 039e7c1374..be4ef5ea6a 100644
--- a/litmus/rt_domain.c
+++ b/litmus/rt_domain.c
@@ -185,6 +185,7 @@ static void arm_release_timer(unsigned long _rt)
 
         list_for_each_safe(pos, safe, &list) {
                 t = list_entry(pos, struct task_struct, rt_param.list);
+                sched_trace_task_release(t);
                 list_del(pos);
                 rh = get_release_heap(rt, get_release(t));
                 heap_add(rt->order, &rh->heap, t, GFP_ATOMIC);
diff --git a/litmus/sched_cedf.c b/litmus/sched_cedf.c
index bebb2c7ba5..f614430c6b 100755
--- a/litmus/sched_cedf.c
+++ b/litmus/sched_cedf.c
@@ -409,11 +409,11 @@ static void cedf_tick(struct task_struct* t)
 }
 
 /* caller holds cedf_lock */
-static noinline void job_completion(struct task_struct *t)
+static noinline void job_completion(struct task_struct *t, int forced)
 {
         BUG_ON(!t);
 
-        sched_trace_job_completion(t);
+        sched_trace_task_completion(t, forced);
 
         TRACE_TASK(t, "job_completion(). [state:%d]\n", t->state);
 
@@ -504,7 +504,7 @@ static struct task_struct* cedf_schedule(struct task_struct * prev)
          * running for blocked jobs). Preemption go first for the same reason.
          */
         if (!np && (out_of_time || sleep) && !blocks && !preempt)
-                job_completion(entry->scheduled);
+                job_completion(entry->scheduled, !sleep);
 
         /* Link pending task if we became unlinked.
          */
@@ -602,7 +602,7 @@ static void cedf_task_wake_up(struct task_struct *task)
                 if (is_tardy(task, now)) {
                         /* new sporadic release */
                         release_at(task, now);
-                        sched_trace_job_release(task);
+                        sched_trace_task_release(task);
                 }
                 else if (task->time_slice)
                         /* came back in time before deadline
diff --git a/litmus/sched_gsn_edf.c b/litmus/sched_gsn_edf.c
index a10c6cbe40..a93b6603ae 100644
--- a/litmus/sched_gsn_edf.c
+++ b/litmus/sched_gsn_edf.c
@@ -333,11 +333,11 @@ static void gsnedf_release_jobs(rt_domain_t* rt, struct heap* tasks)
 }
 
 /* caller holds gsnedf_lock */
-static noinline void job_completion(struct task_struct *t)
+static noinline void job_completion(struct task_struct *t, int forced)
 {
         BUG_ON(!t);
 
-        sched_trace_job_completion(t);
+        sched_trace_task_completion(t, forced);
 
         TRACE_TASK(t, "job_completion().\n");
 
@@ -458,7 +458,7 @@ static struct task_struct* gsnedf_schedule(struct task_struct * prev)
          * for blocked jobs). Preemption go first for the same reason.
          */
         if (!np && (out_of_time || sleep) && !blocks && !preempt)
-                job_completion(entry->scheduled);
+                job_completion(entry->scheduled, !sleep);
 
         /* Link pending task if we became unlinked.
          */
@@ -558,7 +558,7 @@ static void gsnedf_task_wake_up(struct task_struct *task)
                 if (is_tardy(task, now)) {
                         /* new sporadic release */
                         release_at(task, now);
-                        sched_trace_job_release(task);
+                        sched_trace_task_release(task);
                 }
                 else if (task->time_slice)
                         /* came back in time before deadline
diff --git a/litmus/sched_litmus.c b/litmus/sched_litmus.c
index 1e541e4ac0..b4858f82a7 100644
--- a/litmus/sched_litmus.c
+++ b/litmus/sched_litmus.c
@@ -41,7 +41,7 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
                 other_rq = task_rq(rq->litmus_next);
                 TRACE_TASK(rq->litmus_next, "migrate from %d\n", other_rq->cpu);
 
-                /* while we drop the lock, the prev task could change its 
+                /* while we drop the lock, the prev task could change its
                  * state
                  */
                 prev_state = prev->state;
@@ -52,7 +52,7 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
                  * This could deadlock in the case of cross or circular migrations.
                  * It's the job of the plugin to make sure that doesn't happen.
                  */
-                TRACE_TASK(rq->litmus_next, "stack_in_use=%d\n", 
+                TRACE_TASK(rq->litmus_next, "stack_in_use=%d\n",
                            rq->litmus_next->rt_param.stack_in_use);
                 if (rq->litmus_next->rt_param.stack_in_use != NO_CPU) {
                         TRACE_TASK(rq->litmus_next, "waiting to deschedule\n");
@@ -67,14 +67,14 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
                         if (lt_before(_maybe_deadlock + 10000000, litmus_clock())) {
                                 /* We've been spinning for 10ms.
                                  * Something can't be right!
-                                 * Let's abandon the task and bail out; at least 
+                                 * Let's abandon the task and bail out; at least
                                  * we will have debug info instead of a hard
                                  * deadlock.
                                  */
-                                TRACE_TASK(rq->litmus_next, 
+                                TRACE_TASK(rq->litmus_next,
                                            "stack too long in use. Deadlock?\n");
                                 rq->litmus_next = NULL;
-                                
+
                                 /* bail out */
                                 spin_lock(&rq->lock);
                                 return;
@@ -91,13 +91,13 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
                 double_rq_lock(rq, other_rq);
                 mb();
                 if (prev->state != prev_state && is_realtime(prev)) {
-                        TRACE_TASK(prev, 
+                        TRACE_TASK(prev,
                                    "state changed while we dropped"
                                    " the lock: now=%d, old=%d\n",
                                    prev->state, prev_state);
                         if (prev_state && !prev->state) {
                                 /* prev task became unblocked
-                                 * we need to simulate normal sequence of events 
+                                 * we need to simulate normal sequence of events
                                  * to scheduler plugins.
                                  */
                                 litmus->task_block(prev);
@@ -115,9 +115,9 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
                 if (!is_realtime(rq->litmus_next) ||
                     !is_running(rq->litmus_next)) {
                         /* BAD BAD BAD */
-                        TRACE_TASK(rq->litmus_next, 
+                        TRACE_TASK(rq->litmus_next,
                                    "migration invariant FAILED: rt=%d running=%d\n",
-                                   is_realtime(rq->litmus_next),                           
+                                   is_realtime(rq->litmus_next),
                                    is_running(rq->litmus_next));
                         /* drop the task */
                         rq->litmus_next = NULL;
@@ -131,17 +131,19 @@ static void litmus_schedule(struct rq *rq, struct task_struct *prev)
 
 static void enqueue_task_litmus(struct rq *rq, struct task_struct *p, int wakeup)
 {
-        if (wakeup)
+        if (wakeup) {
+                sched_trace_task_resume(p);
                 litmus->task_wake_up(p);
-        else
+        } else
                 TRACE_TASK(p, "ignoring an enqueue, not a wake up.\n");
 }
 
 static void dequeue_task_litmus(struct rq *rq, struct task_struct *p, int sleep)
 {
-        if (sleep)
+        if (sleep) {
                 litmus->task_block(p);
-        else
+                sched_trace_task_block(p);
+        } else
                 TRACE_TASK(p, "ignoring a dequeue, not going to sleep.\n");
 }
 
diff --git a/litmus/sched_psn_edf.c b/litmus/sched_psn_edf.c
index 71dcfa1fcd..9a2bdfcba0 100644
--- a/litmus/sched_psn_edf.c
+++ b/litmus/sched_psn_edf.c
@@ -261,7 +261,7 @@ static void psnedf_task_wake_up(struct task_struct *task)
             get_rt_flags(task) != RT_F_EXIT_SEM) {
                 /* new sporadic release */
                 release_at(task, now);
-                sched_trace_job_release(task);
+                sched_trace_task_release(task);
         }
         requeue(task, edf);
         spin_unlock_irqrestore(&pedf->slock, flags);
diff --git a/litmus/sched_task_trace.c b/litmus/sched_task_trace.c
new file mode 100644
index 0000000000..07155b82da
--- /dev/null
+++ b/litmus/sched_task_trace.c
@@ -0,0 +1,179 @@
+/* sched_task_trace.c -- record scheduling events to a byte stream
+ *
+ */
+
+#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 FT_TASK_TRACE_MAJOR     253
+#define NO_EVENTS               4096 /* this is a buffer of 12 4k pages per CPU */
+
+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;
+        ftdev_init(&st_dev, THIS_MODULE);
+        for (i = 0; i < NR_CPUS; 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 == NR_CPUS) {
+                st_dev.minor_cnt = NR_CPUS;
+                st_dev.can_open = st_dev_can_open;
+                return register_ftdev(&st_dev, "sched_trace", FT_TASK_TRACE_MAJOR);
+        } else
+                return -EINVAL;
+}
+
+module_init(init_sched_task_trace);
+
+
+static inline struct st_event_record* get_record(u8 type, struct task_struct* t)
+{
+        struct st_event_record* rec;
+        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 : -1;
+        } 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;
+        buf = &__get_cpu_var(st_event_buffer);
+        ft_buffer_finish_write(&buf->ftbuf, rec);
+        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);
+                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      = sched_clock();
+                        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      = sched_clock();
+                        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   = sched_clock();
+                rec->data.completion.forced = forced;
+                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      = sched_clock();
+                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      = sched_clock();
+                put_record(rec);
+        }
+}
diff --git a/litmus/trace.c b/litmus/trace.c
index 2ac79a2d8b..8851198330 100644
--- a/litmus/trace.c
+++ b/litmus/trace.c
@@ -1,12 +1,6 @@
-#include <linux/sched.h>
-#include <linux/fs.h>
-#include <linux/cdev.h>
-#include <asm/semaphore.h>
-#include <asm/uaccess.h>
 #include <linux/module.h>
 
 #include <litmus/ftdev.h>
-
 #include <litmus/litmus.h>
 #include <litmus/trace.h>