Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Enhance measuring accuracy #2

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Enhance measuring accuracy #2

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
9ccde77
Fix error handling in trace_irqoff_init()
cgxu519 Sep 6, 2020
6a2b480
Enhance measuring accuracy
cgxu519 Sep 6, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
112 changes: 41 additions & 71 deletions trace_irqoff.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@
#include <linux/seq_file.h>
#include <linux/sizes.h>
#include <linux/stacktrace.h>
#include <linux/timer.h>
#include <linux/interrupt.h>
#include <linux/uaccess.h>
#include <linux/version.h>
#include <asm/irq_regs.h>
Expand Down Expand Up @@ -94,7 +94,7 @@ struct stack_trace_metadata {
};

struct per_cpu_stack_trace {
struct timer_list timer;
struct tasklet_struct tasklet;
struct hrtimer hrtimer;
struct stack_trace_metadata hardirq_trace;
struct stack_trace_metadata softirq_trace;
Expand Down Expand Up @@ -251,6 +251,7 @@ static bool trace_irqoff_record(u64 delta, bool hardirq, bool skip)
static enum hrtimer_restart trace_irqoff_hrtimer_handler(struct hrtimer *hrtimer)
{
u64 now = local_clock(), delta;
struct tasklet_struct *tasklet;

delta = now - __this_cpu_read(cpu_stack_trace->hardirq_trace.last_timestamp);
__this_cpu_write(cpu_stack_trace->hardirq_trace.last_timestamp, now);
Expand All @@ -270,38 +271,14 @@ static enum hrtimer_restart trace_irqoff_hrtimer_handler(struct hrtimer *hrtimer
}
}

tasklet = per_cpu_ptr(&cpu_stack_trace->tasklet, smp_processor_id());
tasklet_schedule(tasklet);

hrtimer_forward_now(hrtimer, ns_to_ktime(sampling_period));

return HRTIMER_RESTART;
}

#if LINUX_VERSION_CODE < KERNEL_VERSION(4, 15, 0)
static void trace_irqoff_timer_handler(unsigned long data)
#else
static void trace_irqoff_timer_handler(struct timer_list *timer)
#endif
{
u64 now = local_clock(), delta;
#if LINUX_VERSION_CODE < KERNEL_VERSION(4, 15, 0)
struct timer_list *timer = (struct timer_list *)data;
#endif

delta = now - __this_cpu_read(cpu_stack_trace->softirq_trace.last_timestamp);
__this_cpu_write(cpu_stack_trace->softirq_trace.last_timestamp, now);

__this_cpu_write(cpu_stack_trace->softirq_delayed, false);

trace_irqoff_record(delta, false, false);

#if LINUX_VERSION_CODE < KERNEL_VERSION(4, 7, 0)
mod_timer_pinned(timer,
jiffies + msecs_to_jiffies(sampling_period / 1000000UL));
#else
mod_timer(timer,
jiffies + msecs_to_jiffies(sampling_period / 1000000UL));
#endif
}

static void smp_clear_stack_trace(void *info)
{
int i;
Expand All @@ -323,16 +300,12 @@ static void smp_timers_start(void *info)
u64 now = local_clock();
struct per_cpu_stack_trace *stack_trace = info;
struct hrtimer *hrtimer = &stack_trace->hrtimer;
struct timer_list *timer = &stack_trace->timer;

stack_trace->hardirq_trace.last_timestamp = now;
stack_trace->softirq_trace.last_timestamp = now;

hrtimer_start_range_ns(hrtimer, ns_to_ktime(sampling_period),
0, HRTIMER_MODE_REL_PINNED);

timer->expires = jiffies + msecs_to_jiffies(sampling_period / 1000000UL);
add_timer_on(timer, smp_processor_id());
}

#define NUMBER_CHARACTER 40
Expand All @@ -359,7 +332,7 @@ static bool histogram_show(struct seq_file *m, const char *header,
/* print header */
if (header)
seq_printf(m, "%s\n", header);
seq_printf(m, "%*c%s%*c : %-9s %s\n", 9, ' ', "msecs", 10, ' ', "count",
seq_printf(m, "%*c%s%*c : %-9s %s\n", 9, ' ', "usecs", 10, ' ', "count",
"distribution");

for (i = 0; i < zero_index; i++) {
Expand Down Expand Up @@ -402,7 +375,7 @@ static void distribute_show_one(struct seq_file *m, void *v, bool hardirq)

histogram_show(m, hardirq ? "hardirq-off:" : "softirq-off:",
latency_count, MAX_LATENCY_RECORD,
(sampling_period << 1) / (1000 * 1000UL));
(sampling_period << 1) / 1000UL);
}

static int distribute_show(struct seq_file *m, void *v)
Expand Down Expand Up @@ -442,10 +415,10 @@ static ssize_t trace_latency_write(struct file *file, const char __user *buf,
per_cpu_ptr(cpu_stack_trace, cpu),
true);
return count;
} else if (latency < (sampling_period << 1) / (1000 * 1000UL))
} else if (latency < (sampling_period << 1) / 1000UL)
return -EINVAL;

trace_irqoff_latency = latency * 1000 * 1000UL;
trace_irqoff_latency = latency * 1000UL;

return count;
}
Expand Down Expand Up @@ -479,8 +452,8 @@ static void trace_latency_show_one(struct seq_file *m, void *v, bool hardirq)
seq_printf(m, "%*cCOMMAND: %s PID: %d LATENCY: %lu%s\n",
5, ' ', stack_trace->comms[i],
stack_trace->pids[i],
stack_trace->latency[i].nsecs / (1000 * 1000UL),
stack_trace->latency[i].more ? "+ms" : "ms");
stack_trace->latency[i].nsecs / 1000UL,
stack_trace->latency[i].more ? "+us" : "us");
seq_print_stack_trace(m, trace);
seq_putc(m, '\n');

Expand All @@ -491,8 +464,8 @@ static void trace_latency_show_one(struct seq_file *m, void *v, bool hardirq)

static int trace_latency_show(struct seq_file *m, void *v)
{
seq_printf(m, "trace_irqoff_latency: %llums\n\n",
trace_irqoff_latency / (1000 * 1000UL));
seq_printf(m, "trace_irqoff_latency: %lluus\n\n",
trace_irqoff_latency / 1000UL);

seq_puts(m, " hardirq:\n");
trace_latency_show_one(m, v, true);
Expand Down Expand Up @@ -531,30 +504,30 @@ static int enable_open(struct inode *inode, struct file *file)
return single_open(file, enable_show, inode->i_private);
}

void trace_irqoff_tasklet_handler(unsigned long unused)
{
u64 now = local_clock(), delta;

delta = now - __this_cpu_read(cpu_stack_trace->softirq_trace.last_timestamp);
__this_cpu_write(cpu_stack_trace->softirq_trace.last_timestamp, now);
__this_cpu_write(cpu_stack_trace->softirq_delayed, false);
trace_irqoff_record(delta, false, false);
}

static void trace_irqoff_start_timers(void)
{
int cpu;

for_each_online_cpu(cpu) {
struct hrtimer *hrtimer;
struct timer_list *timer;
struct tasklet_struct *tasklet;

hrtimer = per_cpu_ptr(&cpu_stack_trace->hrtimer, cpu);
hrtimer_init(hrtimer, CLOCK_MONOTONIC, HRTIMER_MODE_PINNED);
hrtimer->function = trace_irqoff_hrtimer_handler;

timer = per_cpu_ptr(&cpu_stack_trace->timer, cpu);
#if LINUX_VERSION_CODE < KERNEL_VERSION(4, 7, 0)
__setup_timer(timer, trace_irqoff_timer_handler,
(unsigned long)timer, TIMER_IRQSAFE);
#elif LINUX_VERSION_CODE < KERNEL_VERSION(4, 15, 0)
timer->flags = TIMER_PINNED | TIMER_IRQSAFE;
setup_timer(timer, trace_irqoff_timer_handler,
(unsigned long)timer);
#else
timer_setup(timer, trace_irqoff_timer_handler,
TIMER_PINNED | TIMER_IRQSAFE);
#endif
tasklet = per_cpu_ptr(&cpu_stack_trace->tasklet, cpu);
tasklet_init(tasklet, trace_irqoff_tasklet_handler, 0);

smp_call_function_single(cpu, smp_timers_start,
per_cpu_ptr(cpu_stack_trace, cpu),
Expand All @@ -568,13 +541,13 @@ static void trace_irqoff_cancel_timers(void)

for_each_online_cpu(cpu) {
struct hrtimer *hrtimer;
struct timer_list *timer;
struct tasklet_struct *tasklet;

hrtimer = per_cpu_ptr(&cpu_stack_trace->hrtimer, cpu);
hrtimer_cancel(hrtimer);

timer = per_cpu_ptr(&cpu_stack_trace->timer, cpu);
del_timer_sync(timer);
tasklet = per_cpu_ptr(&cpu_stack_trace->tasklet, cpu);
tasklet_kill(tasklet);
}
}

Expand Down Expand Up @@ -625,7 +598,7 @@ static const struct file_operations enable_fops = {

static int sampling_period_show(struct seq_file *m, void *ptr)
{
seq_printf(m, "%llums\n", sampling_period / (1000 * 1000UL));
seq_printf(m, "%lluus\n", sampling_period / 1000UL);

return 0;
}
Expand All @@ -646,7 +619,7 @@ static ssize_t sampling_period_write(struct file *file, const char __user *buf,
if (kstrtoul_from_user(buf, count, 0, &period))
return -EINVAL;

period *= 1000 * 1000UL;
period *= 1000UL;
if (period > (trace_irqoff_latency >> 1))
trace_irqoff_latency = period << 1;

Expand Down Expand Up @@ -678,30 +651,26 @@ static int __init trace_irqoff_init(void)
goto free_percpu;

if (!proc_create("distribute", S_IRUSR, parent_dir, &distribute_fops))
goto remove_trace_irqoff;
goto remove_proc;

if (!proc_create("trace_latency", S_IRUSR | S_IWUSR, parent_dir,
&trace_latency_fops))
goto remove_distribute;
goto remove_proc;

if (!proc_create("enable", S_IRUSR | S_IWUSR, parent_dir, &enable_fops))
goto remove_trace_latency;
goto remove_proc;

if (!proc_create("sampling_period", S_IRUSR | S_IWUSR, parent_dir,
&sampling_period_fops))
goto remove_enable;
goto remove_proc;

pr_info("trace_irqoff init successfuly!\n");
return 0;

remove_proc:
remove_proc_subtree("trace_irqoff", NULL);
free_percpu:
free_percpu(cpu_stack_trace);
remove_enable:
remove_proc_entry("enable", parent_dir);
remove_trace_latency:
remove_proc_entry("trace_latency", parent_dir);
remove_distribute:
remove_proc_entry("distribute", parent_dir);
remove_trace_irqoff:
proc_remove(parent_dir);

return -ENOMEM;
}
Expand All @@ -712,6 +681,7 @@ static void __exit trace_irqoff_exit(void)
trace_irqoff_cancel_timers();
remove_proc_subtree("trace_irqoff", NULL);
free_percpu(cpu_stack_trace);
pr_info("trace_irqoff exit successfuly!\n");
}

module_init(trace_irqoff_init);
Expand Down