[PATCH 3/3] ftrace: Add timer-source of walltime for ftrace

[Zhaolei <zhaolei@cn.fujitsu.com>]

We can add a timer-source for ftrace to support wall-time display.
It is based on Steven Rostedt <rostedt@goodmis.org>'s suggestion in:
http://lkml.org/lkml/2009/7/24/103

It need to applys on my patch of:
[PATCH v4 1/2] Add function to convert between calendar time and broken-down time for universal use

We can get following output:
 # cd /mnt/debugfs/tracing/
 # cat trace_clock
 [local] global walltime
 # echo sched_switch > current_tracer
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-3580  [000]  2916.188093:   3580:120:S   + [000]  3580:120:S bash
             bash-3580  [000]  2916.188205:   3580:120:S   + [000]  3580:120:S bash
             bash-3580  [000]  2916.188538:   3580:120:R   + [000]     5:115:S events/0
             bash-3580  [000]  2916.188599:   3580:120:R ==> [000]     5:115:R events/0
         events/0-5     [000]  2916.188669:      5:115:S ==> [000]  3580:120:R bash
 ...
 # echo walltime > trace_clock
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#           TIMESTAMP  FUNCTION
 #              | |       |                        |         |
             bash-3580  [000] 2009-08-24 18:03:16.500705:   3580:120:S   + [000]  3580:120:S bash
             bash-3580  [000] 2009-08-24 18:03:16.500815:   3580:120:S   + [000]  3580:120:S bash
             bash-3580  [000] 2009-08-24 18:03:16.500815:   3580:120:S   + [000]  3580:120:S bash
             bash-3580  [000] 2009-08-24 18:03:16.500815:   3580:120:S ==> [000]     5:115:R events/0
         events/0-5     [000] 2009-08-24 18:03:16.500815:      5:115:R   + [000]  3578:120:S sshd
 ...

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
---
 include/linux/trace_clock.h |    1 +
 kernel/trace/trace.c        |   24 ++++++++++++++++-----
 kernel/trace/trace.h        |    8 ++++++-
 kernel/trace/trace_clock.c  |   48 +++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.c |   21 +++++++++++++++---
 5 files changed, 91 insertions(+), 11 deletions(-)

diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h
index 7a81303..322707e 100644
--- a/include/linux/trace_clock.h
+++ b/include/linux/trace_clock.h
@@ -15,5 +15,6 @@
 extern u64 notrace trace_clock_local(void);
 extern u64 notrace trace_clock(void);
 extern u64 notrace trace_clock_global(void);
+extern u64 notrace trace_clock_walltime(void);
 
 #endif /* _LINUX_TRACE_CLOCK_H */
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 5af6f83..afb2c5a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -334,9 +334,10 @@ static struct {
 } trace_clocks[] = {
 	{ trace_clock_local,	"local" },
 	{ trace_clock_global,	"global" },
+	{ trace_clock_walltime,	"walltime" },
 };
 
-int trace_clock_id;
+enum TRACE_CLOCK_TYPE trace_clock_type = TRACE_CLOCK_LOCAL;
 
 /*
  * ftrace_max_lock is used to protect the swapping of buffers
@@ -1432,8 +1433,17 @@ static void print_lat_help_header(struct seq_file *m)
 
 static void print_func_help_header(struct seq_file *m)
 {
-	seq_puts(m, "#           TASK-PID    CPU#    TIMESTAMP  FUNCTION\n");
-	seq_puts(m, "#              | |       |          |         |\n");
+	if (trace_clock_type == TRACE_CLOCK_WALLTIME) {
+		seq_puts(m, "#           TASK-PID    CPU# "
+			"          TIMESTAMP  FUNCTION\n");
+		seq_puts(m, "#              | |       |   "
+			"                     |         |\n");
+	} else {
+		seq_puts(m, "#           TASK-PID    CPU# "
+			"   TIMESTAMP  FUNCTION\n");
+		seq_puts(m, "#              | |       |   "
+			"       |         |\n");
+	}
 }
 
 
@@ -3145,8 +3155,8 @@ static ssize_t tracing_clock_read(struct file *filp, char __user *ubuf,
 	for (i = 0; i < ARRAY_SIZE(trace_clocks); i++)
 		bufiter += snprintf(buf + bufiter, sizeof(buf) - bufiter,
 			"%s%s%s%s", i ? " " : "",
-			i == trace_clock_id ? "[" : "", trace_clocks[i].name,
-			i == trace_clock_id ? "]" : "");
+			i == trace_clock_type ? "[" : "", trace_clocks[i].name,
+			i == trace_clock_type ? "]" : "");
 	bufiter += snprintf(buf + bufiter, sizeof(buf) - bufiter, "\n");
 
 	return simple_read_from_buffer(ubuf, cnt, ppos, buf, bufiter);
@@ -3176,7 +3186,7 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf,
 	if (i == ARRAY_SIZE(trace_clocks))
 		return -EINVAL;
 
-	trace_clock_id = i;
+	trace_clock_type = i;
 
 	mutex_lock(&trace_types_lock);
 
@@ -3186,6 +3196,8 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf,
 
 	mutex_unlock(&trace_types_lock);
 
+	tracing_reset_online_cpus(&global_trace);
+
 	*fpos += cnt;
 
 	return cnt;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 0545c2b..2ce01b9 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -586,7 +586,13 @@ trace_vprintk(unsigned long ip, const char *fmt, va_list args);
 
 extern unsigned long trace_flags;
 
-extern int trace_clock_id;
+enum TRACE_CLOCK_TYPE {
+	TRACE_CLOCK_LOCAL,
+	TRACE_CLOCK_GLOBAL,
+	TRACE_CLOCK_WALLTIME,
+};
+
+extern enum TRACE_CLOCK_TYPE trace_clock_type;
 
 /* Standard output formatting function used for function return traces */
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
index b588fd8..2b23023 100644
--- a/kernel/trace/trace_clock.c
+++ b/kernel/trace/trace_clock.c
@@ -19,6 +19,7 @@
 #include <linux/sched.h>
 #include <linux/ktime.h>
 #include <linux/trace_clock.h>
+#include <trace/events/xtime.h>
 
 /*
  * trace_clock_local(): the simplest and least coherent tracing clock.
@@ -107,3 +108,50 @@ u64 notrace trace_clock_global(void)
 
 	return now;
 }
+
+/*
+ * the number of nanoseconds from 1970-1-1 00:00:00 to
+ * machine boots (trace_clock()==0)
+ */
+static u64 base_walltime;
+
+static void sync_base_walltime(struct timespec *ts, u64 traceclock)
+{
+	base_walltime = (u64)ts->tv_sec * NSEC_PER_SEC + ts->tv_nsec -
+			traceclock;
+}
+
+static void probe_gtod_update_xtime(struct timespec *xtime,
+				    struct timespec *wall_to_monotonic)
+{
+	unsigned long flags;
+	u64 traceclock;
+
+	local_irq_save(flags);
+	traceclock = trace_clock();
+	sync_base_walltime(xtime, traceclock);
+	local_irq_restore(flags);
+}
+
+static int __init walltime_init(void)
+{
+	unsigned long flags;
+	struct timespec ts;
+	u64 traceclock;
+
+	local_irq_save(flags);
+	getnstimeofday(&ts);
+	traceclock = trace_clock();
+	sync_base_walltime(&ts, traceclock);
+	local_irq_restore(flags);
+
+	register_trace_gtod_update_xtime(probe_gtod_update_xtime);
+
+	return 0;
+}
+device_initcall_sync(walltime_init);
+
+u64 notrace trace_clock_walltime(void)
+{
+	return base_walltime + trace_clock();
+}
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index e0c2545..405e37d 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -501,15 +501,28 @@ int trace_print_context(struct trace_iterator *iter)
 {
 	struct trace_seq *s = &iter->seq;
 	struct trace_entry *entry = iter->ent;
-	unsigned long long t = ns2usecs(iter->ts);
-	unsigned long usec_rem = do_div(t, USEC_PER_SEC);
-	unsigned long secs = (unsigned long)t;
 	char comm[TASK_COMM_LEN];
 
 	trace_find_cmdline(entry->pid, comm);
 
-	return trace_seq_printf(s, "%16s-%-5d [%03d] %5lu.%06lu: ",
+	if (trace_clock_type == TRACE_CLOCK_WALLTIME) {
+		struct tm tm;
+		u32 remainder;
+		time_to_tm(div_u64_rem(iter->ts, NSEC_PER_SEC, &remainder),
+				-sys_tz.tz_minuteswest * 60, &tm);
+		return trace_seq_printf(s, "%16s-%-5d [%03d] "
+				"%04ld-%02d-%02d %02d:%02d:%02d.%06llu: ",
+				comm, entry->pid, iter->cpu,
+				tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+				tm.tm_hour, tm.tm_min, tm.tm_sec,
+				ns2usecs(remainder));
+	} else {
+		unsigned long long t = ns2usecs(iter->ts);
+		unsigned long usec_rem = do_div(t, USEC_PER_SEC);
+		unsigned long secs = (unsigned long)t;
+		return trace_seq_printf(s, "%16s-%-5d [%03d] %5lu.%06lu: ",
 				comm, entry->pid, iter->cpu, secs, usec_rem);
+	}
 }
 
 int trace_print_lat_context(struct trace_iterator *iter)
-- 
1.5.5.3