From f64b6a640bf955a554d09378b8f59a56ccdefaae Mon Sep 17 00:00:00 2001 From: tom_wei Date: Mon, 27 Mar 2023 15:41:05 +0800 Subject: [PATCH] Add timestamp for every record! It will output like below: trace_irqoff_latency: 8ms hardirq: softirq: cpu: 3 COMMAND: swapper/3 PID: 0 LATENCY: 9ms start_time: 53.802691s trace_irqoff_record+0x2a0/0x2f0 trace_irqoff_timer_handler+0x5c/0xa0 call_timer_fn+0xac/0x460 expire_timers+0x104/0x268 run_timer_softirq+0xbc/0x178 __do_softirq+0x12c/0x634 irq_exit+0xdc/0x120 __handle_domain_irq+0x6c/0xc0 gic_handle_irq+0x60/0xb0 el1_irq+0xb4/0x12c arch_cpu_idle+0x34/0x280 default_idle_call+0x28/0x44 do_idle+0x19c/0x250 cpu_startup_entry+0x28/0x30 secondary_start_kernel+0x114/0x120 --- trace_irqoff.c | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) diff --git a/trace_irqoff.c b/trace_irqoff.c index 0bfe735..86677f7 100644 --- a/trace_irqoff.c +++ b/trace_irqoff.c @@ -93,6 +93,7 @@ struct irqoff_trace { struct stack_trace_metadata { u64 last_timestamp; + u64 begin_timestamp[MAX_STACE_TRACE_ENTRIES]; unsigned long nr_irqoff_trace; struct irqoff_trace trace[MAX_STACE_TRACE_ENTRIES]; unsigned long nr_entries; @@ -121,6 +122,16 @@ struct per_cpu_stack_trace { }; static struct per_cpu_stack_trace __percpu *cpu_stack_trace; +static size_t time_to_sec(u64 ts, char *buf) +{ + unsigned long rem_nsec; + rem_nsec = do_div(ts, 1000000000); + if (!buf) + return snprintf(NULL, 0, "start_time:%7lu.%06lus ", (unsigned long)ts); + return sprintf(buf, "start_time:%7lu.%06lus", + (unsigned long)ts, rem_nsec / 1000); + +} #if LINUX_VERSION_CODE < KERNEL_VERSION(5, 1, 0) static void (*save_stack_trace_skip_hardirq)(struct pt_regs *regs, @@ -253,6 +264,8 @@ static bool save_trace(struct pt_regs *regs, bool hardirq, u64 latency) TASK_COMM_LEN); stack_trace->pids[nr_irqoff_trace] = current->pid; stack_trace->latency[nr_irqoff_trace].nsecs = latency; + stack_trace->begin_timestamp[nr_irqoff_trace] = \ + stack_trace->last_timestamp - latency; stack_trace->latency[nr_irqoff_trace].more = !hardirq && regs; trace = stack_trace->trace + nr_irqoff_trace; @@ -511,6 +524,7 @@ static ssize_t trace_latency_write(struct file *file, const char __user *buf, static void trace_latency_show_one(struct seq_file *m, void *v, bool hardirq) { int cpu; + char start_time[128]={0}; for_each_online_cpu(cpu) { int i; @@ -533,12 +547,14 @@ static void trace_latency_show_one(struct seq_file *m, void *v, bool hardirq) for (i = 0; i < nr_irqoff_trace; i++) { struct irqoff_trace *trace = stack_trace->trace + i; + memset(start_time,0,sizeof(start_time)); + time_to_sec(stack_trace->begin_timestamp[i],start_time); - seq_printf(m, "%*cCOMMAND: %s PID: %d LATENCY: %lu%s\n", - 5, ' ', stack_trace->comms[i], + seq_printf(m, "%*cCOMMAND: %s PID: %d LATENCY: %lu%s %s\n", + 6, ' ', 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].more ? "+ms" : "ms",start_time); seq_print_stack_trace(m, trace); seq_putc(m, '\n'); @@ -563,6 +579,7 @@ static int trace_latency_show(struct seq_file *m, void *v) return 0; } + static int trace_latency_open(struct inode *inode, struct file *file) { return single_open(file, trace_latency_show, inode->i_private);