Add TRACE() debug tracing support

This patch adds the infrastructure for the TRACE() debug macro.

Conflicts:
	kernel/printk.c

5 files changed, 357 insertions, 1 deletions

diff --git a/include/litmus/debug_trace.h b/include/litmus/debug_trace.h
new file mode 100644
index 000000000000..1266ac6a760c
--- /dev/null
+++ b/include/litmus/debug_trace.h
@@ -0,0 +1,40 @@
+#ifndef LITMUS_DEBUG_TRACE_H
+#define LITMUS_DEBUG_TRACE_H
+
+#ifdef CONFIG_SCHED_DEBUG_TRACE
+void sched_trace_log_message(const char* fmt, ...);
+void dump_trace_buffer(int max);
+#else
+
+#define sched_trace_log_message(fmt, ...)
+
+#endif
+
+extern atomic_t __log_seq_no;
+
+#ifdef CONFIG_SCHED_DEBUG_TRACE_CALLER
+#define TRACE_PREFIX "%d P%d [%s@%s:%d]: "
+#define TRACE_ARGS  atomic_add_return(1, &__log_seq_no),        \
+                raw_smp_processor_id(),                         \
+                __FUNCTION__, __FILE__, __LINE__
+#else
+#define TRACE_PREFIX "%d P%d: "
+#define TRACE_ARGS  atomic_add_return(1, &__log_seq_no), \
+                raw_smp_processor_id()
+#endif
+
+#define TRACE(fmt, args...)                                             \
+        sched_trace_log_message(TRACE_PREFIX fmt,                       \
+                                TRACE_ARGS,  ## args)
+
+#define TRACE_TASK(t, fmt, args...)                     \
+        TRACE("(%s/%d:%d) " fmt,                         \
+              t ? (t)->comm : "null",                    \
+              t ? (t)->pid : 0,                          \
+              t ? (t)->rt_param.job_params.job_no : 0,   \
+              ##args)
+
+#define TRACE_CUR(fmt, args...) \
+        TRACE_TASK(current, fmt, ## args)
+
+#endif
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c099b082cd02..1c7c3dcdc919 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -63,6 +63,13 @@ int console_printk[4] = {
 };
 
 /*
+ * divert printk() messages when there is a LITMUS^RT debug listener
+ */
+#include <litmus/debug_trace.h>
+int trace_override = 0;
+int trace_recurse  = 0;
+
+/*
  * Low level drivers may need that to know if they can schedule in
  * their unblank() callback or not. So let's export it.
  */
@@ -1678,6 +1685,10 @@ asmlinkage int vprintk_emit(int facility, int level,
          */
         text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
+        /* if LITMUS^RT tracer is active divert printk() msgs */
+        if (trace_override && !trace_recurse)
+                TRACE("%s", text);
+
         /* mark and strip a trailing newline */
         if (text_len && text[text_len-1] == '\n') {
                 text_len--;
@@ -2628,7 +2639,7 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 void wake_up_klogd(void)
 {
         preempt_disable();
-        if (waitqueue_active(&log_wait)) {
+        if (!trace_override && waitqueue_active(&log_wait)) {
                 this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
                 irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
         }
diff --git a/litmus/Kconfig b/litmus/Kconfig
index 0c7e06b922a1..e4624ee20adc 100644
--- a/litmus/Kconfig
+++ b/litmus/Kconfig
@@ -49,6 +49,59 @@ config SCHED_OVERHEAD_TRACE_SHIFT
                    24 => 512 MB
                    26 =>  2G MB
 
+config SCHED_DEBUG_TRACE
+        bool "TRACE() debugging"
+        default n
+        help
+          Include support for sched_trace_log_messageg(), which is used to
+          implement TRACE(). If disabled, no TRACE() messages will be included
+          in the kernel, and no overheads due to debugging statements will be
+          incurred by the scheduler. Disable if the overhead is not acceptable
+          (e.g. benchmarking).
+
+          Say Yes for debugging.
+          Say No for overhead tracing.
+
+config SCHED_DEBUG_TRACE_SHIFT
+       int "Buffer size for TRACE() buffer"
+       depends on SCHED_DEBUG_TRACE
+       range 14 22
+       default 18
+       help
+
+        Select the amount of memory needed per for the TRACE() buffer, as a
+        power of two. The TRACE() buffer is global and statically allocated. If
+        the buffer is too small, there will be holes in the TRACE() log if the
+        buffer-flushing task is starved.
+
+        The default should be sufficient for most systems. Increase the buffer
+        size if the log contains holes. Reduce the buffer size when running on
+        a memory-constrained system.
+
+        Examples: 14 =>  16KB
+                  18 => 256KB
+                  20 =>   1MB
+
+        This buffer is exported to usespace using a misc device as
+        'litmus/log'. On a system with default udev rules, a corresponding
+        character device node should be created at /dev/litmus/log. The buffer
+        can be flushed using cat, e.g., 'cat /dev/litmus/log > my_log_file.txt'.
+
+config SCHED_DEBUG_TRACE_CALLER
+       bool "Include [function@file:line] tag in TRACE() log"
+       depends on SCHED_DEBUG_TRACE
+       default n
+       help
+         With this option enabled, TRACE() prepends
+
+              "[<function name>@<filename>:<line number>]"
+
+         to each message in the debug log. Enable this to aid in figuring out
+         what was called in which order. The downside is that it adds a lot of
+         clutter.
+
+         If unsure, say No.
+
 endmenu
 
 endmenu
diff --git a/litmus/Makefile b/litmus/Makefile
index 99f90c34f141..07f065f9748f 100644
--- a/litmus/Makefile
+++ b/litmus/Makefile
@@ -3,4 +3,5 @@
 #
 
 obj-$(CONFIG_FEATHER_TRACE) += ft_event.o ftdev.o
+obj-$(CONFIG_SCHED_DEBUG_TRACE) += sched_trace.o
 obj-$(CONFIG_SCHED_OVERHEAD_TRACE) += trace.o
diff --git a/litmus/sched_trace.c b/litmus/sched_trace.c
new file mode 100644
index 000000000000..e8648f308ccd
--- /dev/null
+++ b/litmus/sched_trace.c
@@ -0,0 +1,251 @@
+/*
+ * sched_trace.c -- record scheduling events to a byte stream.
+ */
+#include <linux/spinlock.h>
+#include <linux/mutex.h>
+
+#include <linux/fs.h>
+#include <linux/slab.h>
+#include <linux/miscdevice.h>
+#include <asm/uaccess.h>
+#include <linux/module.h>
+#include <linux/sysrq.h>
+#include <linux/sched.h>
+#include <linux/kfifo.h>
+
+atomic_t __log_seq_no = ATOMIC_INIT(0);
+
+#define SCHED_TRACE_NAME "litmus/log"
+
+/* Compute size of TRACE() buffer */
+#define LITMUS_TRACE_BUF_SIZE (1 << CONFIG_SCHED_DEBUG_TRACE_SHIFT)
+
+/* Max length of one read from the buffer */
+#define MAX_READ_LEN (64 * 1024)
+
+/* Max length for one write --- by TRACE() --- to the buffer. This is used to
+ * allocate a per-cpu buffer for printf() formatting. */
+#define MSG_SIZE 255
+
+
+static DEFINE_MUTEX(reader_mutex);
+static atomic_t reader_cnt = ATOMIC_INIT(0);
+static DEFINE_KFIFO(debug_buffer, char, LITMUS_TRACE_BUF_SIZE);
+
+
+static DEFINE_RAW_SPINLOCK(log_buffer_lock);
+static DEFINE_PER_CPU(char[MSG_SIZE], fmt_buffer);
+
+/*
+ * sched_trace_log_message - Write to the trace buffer (log_buffer)
+ *
+ * This is the only function accessing the log_buffer from inside the
+ * kernel for writing.
+ * Concurrent access to sched_trace_log_message must be serialized using
+ * log_buffer_lock
+ * The maximum length of a formatted message is 255
+ */
+void sched_trace_log_message(const char* fmt, ...)
+{
+        unsigned long   flags;
+        va_list         args;
+        size_t          len;
+        char*           buf;
+
+        if (!atomic_read(&reader_cnt))
+                /* early exit if nobody is listening */
+                return;
+
+        va_start(args, fmt);
+        local_irq_save(flags);
+
+        /* format message */
+        buf = this_cpu_ptr(fmt_buffer);
+        len = vscnprintf(buf, MSG_SIZE, fmt, args);
+
+        raw_spin_lock(&log_buffer_lock);
+        /* Don't copy the trailing null byte, we don't want null bytes in a
+         * text file.
+         */
+        kfifo_in(&debug_buffer, buf, len);
+        raw_spin_unlock(&log_buffer_lock);
+
+        local_irq_restore(flags);
+        va_end(args);
+}
+
+
+/*
+ * log_read - Read the trace buffer
+ *
+ * This function is called as a file operation from userspace.
+ * Readers can sleep. Access is serialized through reader_mutex
+ */
+static ssize_t log_read(struct file *filp,
+                        char __user *to, size_t len,
+                        loff_t *f_pos)
+{
+        /* we ignore f_pos, this is strictly sequential */
+
+        ssize_t error = -EINVAL;
+        char* mem;
+
+        if (mutex_lock_interruptible(&reader_mutex)) {
+                error = -ERESTARTSYS;
+                goto out;
+        }
+
+        if (len > MAX_READ_LEN)
+                len = MAX_READ_LEN;
+
+        mem = kmalloc(len, GFP_KERNEL);
+        if (!mem) {
+                error = -ENOMEM;
+                goto out_unlock;
+        }
+
+        error = kfifo_out(&debug_buffer, mem, len);
+        while (!error) {
+                set_current_state(TASK_INTERRUPTIBLE);
+                schedule_timeout(110);
+                if (signal_pending(current))
+                        error = -ERESTARTSYS;
+                else
+                        error = kfifo_out(&debug_buffer, mem, len);
+        }
+
+        if (error > 0 && copy_to_user(to, mem, error))
+                error = -EFAULT;
+
+        kfree(mem);
+ out_unlock:
+        mutex_unlock(&reader_mutex);
+ out:
+        return error;
+}
+
+/*
+ * Enable redirection of printk() messages to the trace buffer.
+ * Defined in kernel/printk.c
+ */
+extern int trace_override;
+extern int trace_recurse;
+
+/*
+ * log_open - open the global log message ring buffer.
+ */
+static int log_open(struct inode *in, struct file *filp)
+{
+        int error = -EINVAL;
+
+        if (mutex_lock_interruptible(&reader_mutex)) {
+                error = -ERESTARTSYS;
+                goto out;
+        }
+
+        atomic_inc(&reader_cnt);
+        error = 0;
+
+        printk(KERN_DEBUG
+               "sched_trace kfifo with buffer starting at: 0x%p\n",
+               debug_buffer.buf);
+
+        /* override printk() */
+        trace_override++;
+
+        mutex_unlock(&reader_mutex);
+ out:
+        return error;
+}
+
+static int log_release(struct inode *in, struct file *filp)
+{
+        int error = -EINVAL;
+
+        if (mutex_lock_interruptible(&reader_mutex)) {
+                error = -ERESTARTSYS;
+                goto out;
+        }
+
+        atomic_dec(&reader_cnt);
+
+        /* release printk() overriding */
+        trace_override--;
+
+        printk(KERN_DEBUG "sched_trace kfifo released\n");
+
+        mutex_unlock(&reader_mutex);
+ out:
+        return error;
+}
+
+/*
+ * log_fops  - The file operations for accessing the global LITMUS log message
+ *             buffer.
+ *
+ * Except for opening the device file it uses the same operations as trace_fops.
+ */
+static struct file_operations log_fops = {
+        .owner   = THIS_MODULE,
+        .open    = log_open,
+        .release = log_release,
+        .read    = log_read,
+};
+
+static struct miscdevice litmus_log_dev = {
+        .name    = SCHED_TRACE_NAME,
+        .minor   = MISC_DYNAMIC_MINOR,
+        .fops    = &log_fops,
+};
+
+#ifdef CONFIG_MAGIC_SYSRQ
+void dump_trace_buffer(int max)
+{
+        char line[80];
+        int len;
+        int count = 0;
+
+        /* potential, but very unlikely, race... */
+        trace_recurse = 1;
+        while ((max == 0 || count++ < max) &&
+               (len = kfifo_out(&debug_buffer, line, sizeof(line - 1))) > 0) {
+                line[len] = '\0';
+                printk("%s", line);
+        }
+        trace_recurse = 0;
+}
+
+static void sysrq_dump_trace_buffer(int key)
+{
+        dump_trace_buffer(100);
+}
+
+static struct sysrq_key_op sysrq_dump_trace_buffer_op = {
+        .handler        = sysrq_dump_trace_buffer,
+        .help_msg       = "dump-trace-buffer(Y)",
+        .action_msg     = "writing content of TRACE() buffer",
+};
+#endif
+
+static int __init init_sched_trace(void)
+{
+        printk("Initializing TRACE() device\n");
+
+#ifdef CONFIG_MAGIC_SYSRQ
+        /* offer some debugging help */
+        if (!register_sysrq_key('y', &sysrq_dump_trace_buffer_op))
+                printk("Registered dump-trace-buffer(Y) magic sysrq.\n");
+        else
+                printk("Could not register dump-trace-buffer(Y) magic sysrq.\n");
+#endif
+
+        return misc_register(&litmus_log_dev);
+}
+
+static void __exit exit_sched_trace(void)
+{
+        misc_deregister(&litmus_log_dev);
+}
+
+module_init(init_sched_trace);
+module_exit(exit_sched_trace);