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

@@ -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);