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

From: Zhaolei
Date: Tue Aug 25 2009 - 04:12:23 EST

We can add a timer-source for ftrace to support wall-time display.
It is based on Steven Rostedt <rostedt@xxxxxxxxxxx>'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@xxxxxxxxxxxxxx>
---
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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/