From e089fc170eb4c33c8703bf09cacdff7323cf7575 Mon Sep 17 00:00:00 2001 From: Bjoern Brandenburg Date: Sun, 23 Jun 2013 14:40:52 +0200 Subject: 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. --- include/litmus/trace.h | 137 ++++++++++++++++++++++++ litmus/Kconfig | 25 +++++ litmus/Makefile | 1 + litmus/trace.c | 284 +++++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 447 insertions(+) create mode 100644 include/litmus/trace.h create mode 100644 litmus/trace.c 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 +#include + + +/*********************** 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 +#include +#include + +#include +#include + +/* 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); -- cgit v1.2.2