Add walltime support for ring-buffer

Note:
It is only a prototype patch to for demostrate what is result looks like.
There still have many works to do(bug to fix) before apply.

Hello, Steven

It is a prototype code to make ftrace display walltime of events.

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

This code can run but need to be fixed, it only for demostrate what is result looks like.

I think display walltime is valuable for ftrace, it can provide more recognizable information to system manager that he can known "when" event happened.
And it is also helpful for flight-recorder we are doing now, we can get walltime of events after panic for analyse.

We can get following result on this patch:

 # cd /mnt/debugfs/tracing/
 # echo sched_switch > current_tracer
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-2457  [000]   214.895446:   2457:120:S   + [000]  2457:120:S bash
             bash-2457  [000]   214.898298:   2457:120:R   + [000]     5:115:S events/0
             bash-2457  [000]   214.898684:   2457:120:R ==> [000]     5:115:R events/0
         events/0-5     [000]   214.899458:      5:115:R   + [000]  2455:120:S sshd
         events/0-5     [000]   214.899495:      5:115:S ==> [000]  2455:120:R sshd
 ...
 # echo 1 > options/walltime
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#                  TIMESTAMP  FUNCTION
 #              | |       |                        |         |
           <idle>-0     [000] 2009-07-25 18:01:00.848468:      0:140:R ==> [000]     5:115:R events/0
         events/0-5     [000] 2009-07-25 18:01:00.848523:      5:115:S ==> [000]     0:140:R <idle>
           <idle>-0     [000] 2009-07-25 18:01:01.613479:      0:140:R   + [000]  2455:120:S sshd
           <idle>-0     [000] 2009-07-25 18:01:01.613678:      0:140:R ==> [000]  2455:120:R sshd
             sshd-2455  [000] 2009-07-25 18:01:01.614015:   2455:120:S   + [000]  2455:120:S sshd
 ...

This patch is prototype because we have following things to do:
1: function to get walltime is not near rb_time_stamp()
So walltime is not absolutely synchronize with trace time.
But if we place code to get walltime near rb_time_stamp(), it will be called on every reserve-event and will make system slow.
2: We can't call getnstimeofday() freely in ring-buffer's code, because
it is possibility already hold xtime_lock. Prototype code used a ugly way to get gid of this problem, maybe we need to ftrace_disable_cpu() before every write_seqlock() instead.
3: People maybe change walltime when tracing, but current ring-buffer page's
walltime can not reflect this change. We need to add tracepoints to watch this change, and add a walltime-change event(already reserved in ring-buffer.c) to record this change.

I'll continue to finish remain steps, what is your opinion on it?

Hi Zhaolei,

Could you not just save the wall time in some 64bit format within the current timestamp? Right now there's three clocks that can be used by ftrace. Two that you can really get two (I need to add access to the third). The default clock is sched_clock. But there's an option to get to global_clock:

debug/tracing/options/global-clock

# echo 1 > /debug/tracing/options/global-clock

Will enable the global clock. Perhaps we can add a "wall clock" version that will map the timestamps to the wall clock?

I really hate adding any more fields to the ring buffer headers. That takes away from the amount that you can record per page.

Hi Zhaolei,

Quoted 10 lines

Hi Zhaolei,

Could you not just save the wall time in some 64bit format within the current timestamp? Right now there's three clocks that can be used by ftrace. Two that you can really get two (I need to add access to the third). The default clock is sched_clock. But there's an option to get to global_clock:

debug/tracing/options/global-clock

Quoted 7 lines

# echo 1 > /debug/tracing/options/global-clock

Will enable the global clock. Perhaps we can add a "wall clock" version that will map the timestamps to the wall clock?

I really hate adding any more fields to the ring buffer headers. That takes away from the amount that you can record per page.

I think wall-time recording on every event is too slow. slower tracer isn't useful.
Instead, Can we make pseudo wall-time recording event periodically?

In nowadays, many workload run on cluster machine environment. Then We often need compare different machines tracing log. it mean TSC isn't sufficient. but nobody want performance reduce. Fortunatelly, ntp time adjustment is not happend so frequently. we don't need wall-time on _every_ event.

Thanks.

Quoted 8 lines

In nowadays, many workload run on cluster machine environment. Then We often need compare different machines tracing log. it mean TSC isn't sufficient. but nobody want performance reduce. Fortunatelly, ntp time adjustment is not happend so frequently. we don't need wall-time on _every_ event.

Thanks.

Yeah, that would really slow the tracing.

Can't we get a snapshot of the couple (walltime, cpu clock) once at startup.
Then we can retrieve the walltime when cpu_clock was 0 and compute the walltime for each traces at output time using the trace timestamp as a delta?

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

It needs to be applied on my patch of:
[PATCH v4 1/2] Add function to convert between calendar time and broken-down time for universal use and
[PATCH v2 2/2] ftrace: Unify effect of writing to trace_options and option/*

We can get following output:

 # cd /mnt/debugfs/tracing/
 # ls options/*clock
 options/global-clock  options/local-clock  options/walltime-clock
 # echo sched_switch > current_tracer
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-3560  [000]   694.242386:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.242476:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.242865:   3560:120:R   + [000]     5:115:S events/0
             bash-3560  [000]   694.242912:   3560:120:R ==> [000]     5:115:R events/0
         events/0-5     [000]   694.243015:      5:115:R   + [000]  3558:120:S sshd
         events/0-5     [000]   694.243040:      5:115:S ==> [000]  3560:120:R bash
             bash-3560  [000]   694.243312:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.243374:   3560:120:S ==> [000]  3558:120:R sshd
 ...
 # echo 1 > options/walltime-clock
 # echo > trace
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#           TIMESTAMP  FUNCTION
 #              | |       |                 |         |
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:R   + [000]     5:115:S events/0
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:R ==> [000]     5:115:R events/0
         events/0-5     [000] 2009-08-17 23:58:22      5:115:R   + [000]  3558:120:S sshd
         events/0-5     [000] 2009-08-17 23:58:22      5:115:S ==> [000]  3558:120:R sshd
             sshd-3558  [000] 2009-08-17 23:58:22   3558:120:S ==> [000]  3560:120:R bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
 ...

Note:
It is only a prototype patch to for demostrate what is result looks like. There still have many works to do(bug to fix) before apply. For example, we need to add a hook(tracepoint) of xtime change event, so we can update walltime's clock base then.
And maybe we need clear all events when changing clock-source, because old clock value can't displayed correctly in new clock's format.

Signed-off-by Zhao Lei <[email protected]>

---
 include/linux/trace_clock.h |    1 +
 kernel/trace/trace.c        |   55 ++++++++++++++++++++++++++++++------------
 kernel/trace/trace.h        |    6 +++-
 kernel/trace/trace_clock.c  |   47 ++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.c |   20 ++++++++++++---
 5 files changed, 107 insertions(+), 22 deletions(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +19 -8

index b7d873b..4474f7d 100644
@@ -263,8 +263,8 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);
 
 /* trace_flags holds trace_options default values */
 unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
-	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_SLEEP_TIME |
-	TRACE_ITER_GRAPH_TIME;
+	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_LOCAL_CLK |
+	TRACE_ITER_SLEEP_TIME | TRACE_ITER_GRAPH_TIME;
 
 /**
  * trace_wake_up - wake up tasks waiting for trace input

@@ -324,6 +324,8 @@ static const char *trace_options[] = {
 	"context-info",
 	"latency-format",
 	"global-clock",
+	"local-clock",
+	"walltime-clock",
 	"sleep-time",
 	"graph-time",
 	NULL

@@ -1423,8 +1425,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_flags & TRACE_ITER_WALLTIME_CLK) {
+		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");
+	}
 }
 
 

@@ -2151,30 +2162,42 @@ static int set_tracer_option(struct tracer *trace, char *cmp, int neg)
 
 static void set_tracer_flags(unsigned int mask, int enabled)
 {
+	u64 (*clkfunc)(void) = NULL;
+
 	/* do nothing if flag is already set */
 	if (!!(trace_flags & mask) == !!enabled)
 		return;
 
-	if (enabled)
-		trace_flags |= mask;
-	else
-		trace_flags &= ~mask;
+	if (mask == TRACE_ITER_GLOBAL_CLK)
+		clkfunc = trace_clock_global;

Quoted 138 lines · Zhaolei

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

It needs to be applied on my patch of:
[PATCH v4 1/2] Add function to convert between calendar time and broken-down time for universal use and
[PATCH v2 2/2] ftrace: Unify effect of writing to trace_options and option/*

We can get following output:

 # cd /mnt/debugfs/tracing/
 # ls options/*clock
 options/global-clock  options/local-clock  options/walltime-clock
 # echo sched_switch > current_tracer
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-3560  [000]   694.242386:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.242476:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.242865:   3560:120:R   + [000]     5:115:S events/0
             bash-3560  [000]   694.242912:   3560:120:R ==> [000]     5:115:R events/0
         events/0-5     [000]   694.243015:      5:115:R   + [000]  3558:120:S sshd
         events/0-5     [000]   694.243040:      5:115:S ==> [000]  3560:120:R bash
             bash-3560  [000]   694.243312:   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000]   694.243374:   3560:120:S ==> [000]  3558:120:R sshd
 ...
 # echo 1 > options/walltime-clock
 # echo > trace
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#           TIMESTAMP  FUNCTION
 #              | |       |                 |         |
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:R   + [000]     5:115:S events/0
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:R ==> [000]     5:115:R events/0
         events/0-5     [000] 2009-08-17 23:58:22      5:115:R   + [000]  3558:120:S sshd
         events/0-5     [000] 2009-08-17 23:58:22      5:115:S ==> [000]  3558:120:R sshd
             sshd-3558  [000] 2009-08-17 23:58:22   3558:120:S ==> [000]  3560:120:R bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
             bash-3560  [000] 2009-08-17 23:58:22   3560:120:S   + [000]  3560:120:S bash
 ...

Note:
It is only a prototype patch to for demostrate what is result looks like. There still have many works to do(bug to fix) before apply. For example, we need to add a hook(tracepoint) of xtime change event, so we can update walltime's clock base then.
And maybe we need clear all events when changing clock-source, because old clock value can't displayed correctly in new clock's format.

Signed-off-by Zhao Lei <[email protected]>

---
 include/linux/trace_clock.h |    1 +
 kernel/trace/trace.c        |   55 ++++++++++++++++++++++++++++++------------
 kernel/trace/trace.h        |    6 +++-
 kernel/trace/trace_clock.c  |   47 ++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.c |   20 ++++++++++++---
 5 files changed, 107 insertions(+), 22 deletions(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +23 -8

index b7d873b..4474f7d 100644
@@ -263,8 +263,8 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);
 
 /* trace_flags holds trace_options default values */
 unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
-	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_SLEEP_TIME |
-	TRACE_ITER_GRAPH_TIME;
+	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_LOCAL_CLK |
+	TRACE_ITER_SLEEP_TIME | TRACE_ITER_GRAPH_TIME;
 
 /**
  * trace_wake_up - wake up tasks waiting for trace input

@@ -324,6 +324,8 @@ static const char *trace_options[] = {
 	"context-info",
 	"latency-format",
 	"global-clock",
+	"local-clock",
+	"walltime-clock",
 	"sleep-time",
 	"graph-time",
 	NULL

@@ -1423,8 +1425,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_flags & TRACE_ITER_WALLTIME_CLK) {
+		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");
+	}
 }
 
 

@@ -2151,30 +2162,42 @@ static int set_tracer_option(struct tracer *trace, char *cmp, int neg)
 
 static void set_tracer_flags(unsigned int mask, int enabled)
 {
+	u64 (*clkfunc)(void) = NULL;
+
 	/* do nothing if flag is already set */
 	if (!!(trace_flags & mask) == !!enabled)
 		return;
 
-	if (enabled)
-		trace_flags |= mask;
-	else
-		trace_flags &= ~mask;
+	if (mask == TRACE_ITER_GLOBAL_CLK)
+		clkfunc = trace_clock_global;
+	if (mask == TRACE_ITER_LOCAL_CLK)
+		clkfunc = trace_clock_local;
+	if (mask == TRACE_ITER_WALLTIME_CLK)
+		clkfunc = trace_clock_walltime;
 

kernel/trace/trace.c static int set_tracer_option(struct tracer *trace, char *cmp, int neg) · line 2180

Quoted 5 lines

kernel/trace/trace.c +3 -2

-	if (mask == TRACE_ITER_GLOBAL_CLK) {
-		u64 (*func)(void);
+	if (clkfunc) {
+		if (!enabled)
+			return;

If the user set a clock option file to 0, then it means he was expecting something, probably reset the default clock which is clock_local.

But what if the user set 0 to the local_clock...hmm..

or make option like:

# echo wallclock > option/clock
# echo localclock > option/clock
is best way.
But it needs rewriting whole option source.

Maybe now, we can use a neutrality way as:

# echo 0 > option/wallclock  # reset to default clock(local clock)
# echo 0 > option/locakclock # no effect

kernel/trace/trace_clock.c u64 notrace trace_clock_global(void) · line 120

Quoted 7 lines

kernel/trace/trace_clock.c +7 -0

+u64 notrace trace_clock_walltime(void)
+{
+	u32 remainder;
+	return base_walltime.tv_sec + div_u64_rem(
+			trace_clock() + base_walltime.tv_nsec,
+			NSEC_PER_SEC, &remainder);
+}

Why do we need calculate walltime at ring-buffer recordng phase? IOW, Why can't we calculate this at displaing time?

Quoted 9 lines · KOSAKI Motohiro

kernel/trace/trace_clock.c u64 notrace trace_clock_global(void) · line 120

Quoted 7 lines

kernel/trace/trace_clock.c +7 -0

+u64 notrace trace_clock_walltime(void)
+{
+	u32 remainder;
+	return base_walltime.tv_sec + div_u64_rem(
+			trace_clock() + base_walltime.tv_nsec,
+			NSEC_PER_SEC, &remainder);
+}

Why do we need calculate walltime at ring-buffer recordng phase? IOW, Why can't we calculate this at displaing time?

Right! We should have something like this:

	return (u64)base_walltime.tv_sec * NSEC_PER_SEC +
		trace_clock() + base_walltime.tv_nsec;

And then we could divide it out later.

And then we could even show more fields in the output and not limit ourselves to seconds.

-- Steve

There are many clock source for tracing system but we can only enable/disable one bit by trace/options file.
We can move setting of clock-source out of options and add a separate file for it:

 # cat trace_clock
 [local] global
 # echo global > trace_clock
 # cat trace_clock
 local [global]

Signed-off-by Zhao Lei <[email protected]>

---
 kernel/trace/trace.c |   92 ++++++++++++++++++++++++++++++++++++++++---------
 kernel/trace/trace.h |    7 ++--
 2 files changed, 79 insertions(+), 20 deletions(-)

kernel/trace/trace.c +10 -17

index b7d873b..5af6f83 100644
@@ -323,12 +323,21 @@ static const char *trace_options[] = {
 	"printk-msg-only",
 	"context-info",
 	"latency-format",
-	"global-clock",
 	"sleep-time",
 	"graph-time",
 	NULL
 };
 
+static struct {
+	u64 (*func)(void);
+	const char *name;
+} trace_clocks[] = {
+	{ trace_clock_local,	"local" },
+	{ trace_clock_global,	"global" },
+};
+
+int trace_clock_id;
+
 /*
  * ftrace_max_lock is used to protect the swapping of buffers
  * when taking a max snapshot. The buffers themselves are

@@ -2159,22 +2168,6 @@ static void set_tracer_flags(unsigned int mask, int enabled)
 		trace_flags |= mask;
 	else
 		trace_flags &= ~mask;
-
-	if (mask == TRACE_ITER_GLOBAL_CLK) {
-		u64 (*func)(void);
-
-		if (enabled)
-			func = trace_clock_global;
-		else
-			func = trace_clock_local;
-
-		mutex_lock(&trace_types_lock);
-		ring_buffer_set_clock(global_trace.buffer, func);
-
-		if (max_tr.buffer)
-			ring_buffer_set_clock(max_tr.buffer, func);
-		mutex_unlock(&trace_types_lock);
-	}
 }
 
 static ssize_t

kernel/trace/trace.c +61 -0

+	int bufiter = 0;
+	int i;
+
+	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 ? "]" : "");
+	bufiter += snprintf(buf + bufiter, sizeof(buf) - bufiter, "\n");
+
+	return simple_read_from_buffer(ubuf, cnt, ppos, buf, bufiter);
+}
+
+static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf,
+				   size_t cnt, loff_t *fpos)
+{
+	char buf[64];
+	const char *clockstr;
+	int i;
+
+	if (cnt >= sizeof(buf))
+		return -EINVAL;
+
+	if (copy_from_user(&buf, ubuf, cnt))
+		return -EFAULT;
+
+	buf[cnt] = 0;
+
+	clockstr = strstrip(buf);
+
+	for (i = 0; i < ARRAY_SIZE(trace_clocks); i++) {
+		if (strcmp(trace_clocks[i].name, clockstr) == 0)
+			break;
+	}
+	if (i == ARRAY_SIZE(trace_clocks))
+		return -EINVAL;
+
+	trace_clock_id = i;
+
+	mutex_lock(&trace_types_lock);
+
+	ring_buffer_set_clock(global_trace.buffer, trace_clocks[i].func);
+	if (max_tr.buffer)
+		ring_buffer_set_clock(max_tr.buffer, trace_clocks[i].func);
+
+	mutex_unlock(&trace_types_lock);
+
+	*fpos += cnt;
+
+	return cnt;
+}
+
 static const struct file_operations tracing_max_lat_fops = {
 	.open		= tracing_open_generic,
 	.read		= tracing_max_lat_read,

@@ -3179,6 +3228,12 @@ static const struct file_operations tracing_mark_fops = {
 	.write		= tracing_mark_write,
 };
 
+static const struct file_operations trace_clock_fops = {
+	.open		= tracing_open_generic,
+	.read		= tracing_clock_read,
+	.write		= tracing_clock_write,
+};
+
 struct ftrace_buffer_info {
 	struct trace_array	*tr;
 	void			*spare;

@@ -3910,6 +3965,9 @@ static __init int tracer_init_debugfs(void)
 	trace_create_file("saved_cmdlines", 0444, d_tracer,
 			NULL, &tracing_saved_cmdlines_fops);
 
+	trace_create_file("trace_clock", 0644, d_tracer, NULL,
+			  &trace_clock_fops);
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 	trace_create_file("dyn_ftrace_total_info", 0444, d_tracer,
 			&ftrace_update_tot_cnt, &tracing_dyn_info_fops);

kernel/trace/trace.h +4 -3

index 606073c..0545c2b 100644
@@ -586,6 +586,8 @@ trace_vprintk(unsigned long ip, const char *fmt, va_list args);
 
 extern unsigned long trace_flags;
 
+extern int trace_clock_id;
+
 /* Standard output formatting function used for function return traces */
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 extern enum print_line_t print_graph_function(struct trace_iterator *iter);

@@ -674,9 +676,8 @@ enum trace_iterator_flags {
 	TRACE_ITER_PRINTK_MSGONLY	= 0x10000,
 	TRACE_ITER_CONTEXT_INFO		= 0x20000, /* Print pid/cpu/time */
 	TRACE_ITER_LATENCY_FMT		= 0x40000,
-	TRACE_ITER_GLOBAL_CLK		= 0x80000,
-	TRACE_ITER_SLEEP_TIME		= 0x100000,
-	TRACE_ITER_GRAPH_TIME		= 0x200000,
+	TRACE_ITER_SLEEP_TIME		= 0x80000,
+	TRACE_ITER_GRAPH_TIME		= 0x100000,
 };
 
 /*

Signature · 1 line

1.5.5.3

From: Xiao Guangrong <[email protected]>

This patch can trace current xtime and wall_to_monotonic. Then user can use ctime() to convert them to wall time which is easier to be understood, especially for flight-recorder which need to get trace event from a kernel dump file.

Example of ftrace output:

          <idle>-0     [000] 20118.489849: gtod_update_xtime: xtime=1243265589.999999824 wall_to_monotonic=3051713268.744158739
           <...>-4020  [001] 20118.489855: sys_open(filename: bf9e66e0, flags: 98800, mode: bf9e66e0)
           <...>-4020  [001] 20118.489873: sys_open -> 0xffffffec

ctime(1243265590) = date:Mon May 25 11:33:10 2009 So we can realize the task with pid 4020 open a file at Mon May 25 11:33:10 2009

Changelog:
v1->v2: Rebased by Zhao Lei <[email protected]>

Signed-off-by Zhao Lei <[email protected]>

Signed-off-by Xiao Guangrong <[email protected]>

---
 include/trace/events/xtime.h |   38 ++++++++++++++++++++++++++++++++++++++
 kernel/time/ntp.c            |    4 ++++
 kernel/time/timekeeping.c    |    6 ++++++
 3 files changed, 48 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/xtime.h

include/trace/events/xtime.h new file +38 -0

new file mode 100644
index 0000000..398e679
@@ -0,0 +1,38 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM xtime
+
+#if !defined(_TRACE_XTIME_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_XTIME_H
+
+#include <linux/time.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(gtod_update_xtime,
+
+	TP_PROTO(struct timespec *xtime, struct timespec *wall_to_monotonic),
+
+	TP_ARGS(xtime, wall_to_monotonic),
+
+	TP_STRUCT__entry(
+		__field(	long,	xtime_sec		)
+		__field(	long,	xtime_nsec		)
+		__field(	long,	wall_to_monotonic_sec	)
+		__field(	long,	wall_to_monotonic_nsec	)
+	),
+
+	TP_fast_assign(
+		__entry->xtime_sec		= xtime->tv_sec;
+		__entry->xtime_nsec		= xtime->tv_nsec;
+		__entry->wall_to_monotonic_sec	= wall_to_monotonic->tv_sec;
+		__entry->wall_to_monotonic_nsec	= wall_to_monotonic->tv_nsec;
+	),
+
+	TP_printk("xtime=%ld.%09ld wall_to_monotonic=%ld.%09ld",
+		  __entry->xtime_sec, __entry->xtime_nsec,
+		  __entry->wall_to_monotonic_sec, __entry->wall_to_monotonic_nsec)
+);
+
+#endif /* _TRACE_XTIME_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

kernel/time/ntp.c +4 -0

index 4800f93..fc2f13a 100644
@@ -15,6 +15,8 @@
 #include <linux/time.h>
 #include <linux/mm.h>
 
+#include <trace/events/xtime.h>
+
 /*
  * NTP timekeeping variables:
  */

@@ -218,6 +220,8 @@ static enum hrtimer_restart ntp_leap_second(struct hrtimer *timer)
 		break;
 	}
 
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+
 	write_sequnlock(&xtime_lock);
 
 	return res;

kernel/time/timekeeping.c +6 -0

index 03cbeb3..2e57a87 100644
@@ -20,6 +20,9 @@
 #include <linux/tick.h>
 #include <linux/stop_machine.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/xtime.h>
+
 /* Structure holding internal timekeeping values. */
 struct timekeeper {
 	/* Current clocksource used for timekeeping. */

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
 	update_vsyscall(&xtime, timekeeper.clock);
 
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 
 	/* signal hrtimers about time change */

@@ -811,6 +816,7 @@ void update_wall_time(void)
 
 	/* check to see if there is a new clocksource to use */
 	update_vsyscall(&xtime, timekeeper.clock);
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
 }
 
 /**

Signature · 1 line

1.5.5.3

Thomas,

This patch touches time keeping work. Can I get your ACK on it, or if it belongs to someone else, could you tell me who I need.

Thanks,

-- Steve

Quoted 129 lines · Zhaolei

From: Xiao Guangrong <[email protected]>

This patch can trace current xtime and wall_to_monotonic. Then user can use ctime() to convert them to wall time which is easier to be understood, especially for flight-recorder which need to get trace event from a kernel dump file.

Example of ftrace output:

          <idle>-0     [000] 20118.489849: gtod_update_xtime: xtime=1243265589.999999824 wall_to_monotonic=3051713268.744158739
           <...>-4020  [001] 20118.489855: sys_open(filename: bf9e66e0, flags: 98800, mode: bf9e66e0)
           <...>-4020  [001] 20118.489873: sys_open -> 0xffffffec

ctime(1243265590) = date:Mon May 25 11:33:10 2009 So we can realize the task with pid 4020 open a file at Mon May 25 11:33:10 2009

Changelog:
v1->v2: Rebased by Zhao Lei <[email protected]>

Signed-off-by Zhao Lei <[email protected]>

Signed-off-by Xiao Guangrong <[email protected]>

---
 include/trace/events/xtime.h |   38 ++++++++++++++++++++++++++++++++++++++
 kernel/time/ntp.c            |    4 ++++
 kernel/time/timekeeping.c    |    6 ++++++
 3 files changed, 48 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/xtime.h

include/trace/events/xtime.h new file +38 -0

new file mode 100644
index 0000000..398e679
@@ -0,0 +1,38 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM xtime
+
+#if !defined(_TRACE_XTIME_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_XTIME_H
+
+#include <linux/time.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(gtod_update_xtime,
+
+	TP_PROTO(struct timespec *xtime, struct timespec *wall_to_monotonic),
+
+	TP_ARGS(xtime, wall_to_monotonic),
+
+	TP_STRUCT__entry(
+		__field(	long,	xtime_sec		)
+		__field(	long,	xtime_nsec		)
+		__field(	long,	wall_to_monotonic_sec	)
+		__field(	long,	wall_to_monotonic_nsec	)
+	),
+
+	TP_fast_assign(
+		__entry->xtime_sec		= xtime->tv_sec;
+		__entry->xtime_nsec		= xtime->tv_nsec;
+		__entry->wall_to_monotonic_sec	= wall_to_monotonic->tv_sec;
+		__entry->wall_to_monotonic_nsec	= wall_to_monotonic->tv_nsec;
+	),
+
+	TP_printk("xtime=%ld.%09ld wall_to_monotonic=%ld.%09ld",
+		  __entry->xtime_sec, __entry->xtime_nsec,
+		  __entry->wall_to_monotonic_sec, __entry->wall_to_monotonic_nsec)
+);
+
+#endif /* _TRACE_XTIME_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

kernel/time/ntp.c +4 -0

index 4800f93..fc2f13a 100644
@@ -15,6 +15,8 @@
 #include <linux/time.h>
 #include <linux/mm.h>
 
+#include <trace/events/xtime.h>
+
 /*
  * NTP timekeeping variables:
  */

@@ -218,6 +220,8 @@ static enum hrtimer_restart ntp_leap_second(struct hrtimer *timer)
 		break;
 	}
 
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+
 	write_sequnlock(&xtime_lock);
 
 	return res;

kernel/time/timekeeping.c +6 -0

index 03cbeb3..2e57a87 100644
@@ -20,6 +20,9 @@
 #include <linux/tick.h>
 #include <linux/stop_machine.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/xtime.h>
+
 /* Structure holding internal timekeeping values. */
 struct timekeeper {
 	/* Current clocksource used for timekeeping. */

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
 	update_vsyscall(&xtime, timekeeper.clock);
 
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 
 	/* signal hrtimers about time change */

@@ -811,6 +816,7 @@ void update_wall_time(void)
 
 	/* check to see if there is a new clocksource to use */
 	update_vsyscall(&xtime, timekeeper.clock);
+	trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
 }
 
 /**

Signature · 1 line

1.5.5.3

From: Xiao Guangrong <[email protected]>

This patch can trace current xtime and wall_to_monotonic. Then user can use ctime() to convert them to wall time which is easier to be understood, especially for flight-recorder which need to get trace event from a kernel dump file.

Example of ftrace output:
         <idle>-0     [000] 20118.489849: gtod_update_xtime: xtime=1243265589.999999824 wall_to_monotonic=3051713268.744158739 <...>-4020  [001] 20118.489855: sys_open(filename: bf9e66e0, flags: 98800, mode: bf9e66e0) <...>-4020  [001] 20118.489873: sys_open -> 0xffffffec

ctime(1243265590) = date:Mon May 25 11:33:10 2009 So we can realize the task with pid 4020 open a file at Mon May 25 11:33:10 2009

Changelog:
v1->v2: Rebased by Zhao Lei <[email protected]>

Signed-off-by Zhao Lei <[email protected]>

Signed-off-by Xiao Guangrong <[email protected]>

---
 include/trace/events/xtime.h |   38 ++++++++++++++++++++++++++++++++++++++ kernel/time/ntp.c            |    4 ++++ kernel/time/timekeeping.c    |    6 ++++++

 3 files changed, 48 insertions(+), 0 deletions(-)

 create mode 100644 include/trace/events/xtime.h

include/trace/events/xtime.h new file +38 -0

new file mode 100644
index 0000000..398e679
@@ -0,0 +1,38 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM xtime
+
+#if !defined(_TRACE_XTIME_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_XTIME_H
+
+#include <linux/time.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(gtod_update_xtime,
+
+       TP_PROTO(struct timespec *xtime, struct timespec *wall_to_monotonic),
+
+       TP_ARGS(xtime, wall_to_monotonic),
+
+       TP_STRUCT__entry(
+               __field(        long,   xtime_sec               )
+               __field(        long,   xtime_nsec              )
+               __field(        long,   wall_to_monotonic_sec   )
+               __field(        long,   wall_to_monotonic_nsec  )
+       ),
+
+       TP_fast_assign(
+               __entry->xtime_sec              = xtime->tv_sec;
+               __entry->xtime_nsec             = xtime->tv_nsec;
+               __entry->wall_to_monotonic_sec  = wall_to_monotonic->tv_sec;
+               __entry->wall_to_monotonic_nsec = wall_to_monotonic->tv_nsec;
+       ),
+
+       TP_printk("xtime=%ld.%09ld wall_to_monotonic=%ld.%09ld",
+                 __entry->xtime_sec, __entry->xtime_nsec,
+                 __entry->wall_to_monotonic_sec, __entry->wall_to_monotonic_nsec)
+);
+
+#endif /* _TRACE_XTIME_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

kernel/time/ntp.c +4 -0

index 4800f93..fc2f13a 100644
@@ -15,6 +15,8 @@
  #include <linux/time.h>
  #include <linux/mm.h>
 
+#include <trace/events/xtime.h>
+
  /*
  * NTP timekeeping variables:
  */

@@ -218,6 +220,8 @@ static enum hrtimer_restart ntp_leap_second(struct hrtimer *timer)
                break;
        }
 
+       trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+
        write_sequnlock(&xtime_lock);
 
        return res;

kernel/time/timekeeping.c +3 -0

index 03cbeb3..2e57a87 100644
@@ -20,6 +20,9 @@
  #include <linux/tick.h>
  #include <linux/stop_machine.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/xtime.h>
+
  /* Structure holding internal timekeeping values. */
  struct timekeeper {
        /* Current clocksource used for timekeeping. */

kernel/time/timekeeping.c int do_settimeofday(struct timespec *tv) · line 345

Quoted 10 lines · Zhaolei

From: Xiao Guangrong <[email protected]> /* Structure holding internal timekeeping values. */ struct timekeeper {
       /* Current clocksource used for timekeeping. */

kernel/time/timekeeping.c +2 -0

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
        update_vsyscall(&xtime, timekeeper.clock);
 
+       trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+

So the only thing to watch out on here is that xtime doesn't hold the current time, but the accumulated time. There is some unaccumulated time still kept in the clocksource structure.

You probably want (assuming you only need tick granularity time) to use current_kernel_time().

As an aside, is there a reason you have to have update callbacks and duplicate the time storage instead of using the existing interfaces? (ie: Is this due to locking or something else?)

Quoted 16 lines · john stultz

kernel/time/timekeeping.c int do_settimeofday(struct timespec *tv) · line 345

Quoted 10 lines · Zhaolei

From: Xiao Guangrong <[email protected]>
/* Structure holding internal timekeeping values. */

 struct timekeeper {
       /* Current clocksource used for timekeeping. */

kernel/time/timekeeping.c +2 -0

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
       update_vsyscall(&xtime, timekeeper.clock);
 
+       trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+

So the only thing to watch out on here is that xtime doesn't hold the current time, but the accumulated time. There is some unaccumulated time still kept in the clocksource structure.

Quoted 6 lines

You probably want (assuming you only need tick granularity time) to use current_kernel_time().

As an aside, is there a reason you have to have update callbacks and duplicate the time storage instead of using the existing interfaces? (ie: Is this due to locking or something else?)

Doh. Sorry, you're actually tracing the timekeeping code. Not using this to assist tracing. Got this confused.

So yea, I think this should be ok, plus or minus determining if you really want xtime or xtime_cache.

Quoted 24 lines · john stultz

Quoted 16 lines · john stultz

kernel/time/timekeeping.c int do_settimeofday(struct timespec *tv) · line 345

Quoted 10 lines · Zhaolei

From: Xiao Guangrong <[email protected]>
/* Structure holding internal timekeeping values. */

 struct timekeeper {
       /* Current clocksource used for timekeeping. */

kernel/time/timekeeping.c +2 -0

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
       update_vsyscall(&xtime, timekeeper.clock);
 
+       trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+

So the only thing to watch out on here is that xtime doesn't hold the current time, but the accumulated time. There is some unaccumulated time still kept in the clocksource structure.

Quoted 6 lines

You probably want (assuming you only need tick granularity time) to use current_kernel_time().

As an aside, is there a reason you have to have update callbacks and duplicate the time storage instead of using the existing interfaces? (ie: Is this due to locking or something else?)

Quoted 5 lines

Doh. Sorry, you're actually tracing the timekeeping code. Not using this to assist tracing. Got this confused.

So yea, I think this should be ok, plus or minus determining if you really want xtime or xtime_cache.

Well this may be a real concern. It's not about tracing timekeeping (although it adds that functionality). His second patch (I didn't Cc you on that one) hooks to these tracepoints to update time accordingly.

What is being done is a way to have a "wall time" value being added to the ring buffer. But this needs to be very carefully done, because the all tracers use this, including the function tracer in NMI code. So the clock source can not take locks or do anything fancy.

What the idea is, is to have a semi clock that is read with some kind of fast increment, and then at clock ticks, this clock is synced up.

Quoted 37 lines · Steven Rostedt

Quoted 19 lines · john stultz

Quoted 18 lines · john stultz

kernel/time/timekeeping.c int do_settimeofday(struct timespec *tv) · line 345

Quoted 10 lines · Zhaolei

From: Xiao Guangrong <[email protected]>
/* Structure holding internal timekeeping values. */

 struct timekeeper {
       /* Current clocksource used for timekeeping. */

kernel/time/timekeeping.c +2 -0

@@ -338,6 +341,8 @@ int do_settimeofday(struct timespec *tv)
 
       update_vsyscall(&xtime, timekeeper.clock);
 
+       trace_gtod_update_xtime(&xtime, &wall_to_monotonic);
+

So the only thing to watch out on here is that xtime doesn't hold the current time, but the accumulated time. There is some unaccumulated time still kept in the clocksource structure.

You probably want (assuming you only need tick granularity time) to use current_kernel_time().

Quoted 8 lines

Quoted 3 lines

As an aside, is there a reason you have to have update callbacks and duplicate the time storage instead of using the existing interfaces? (ie: Is this due to locking or something else?)

Doh. Sorry, you're actually tracing the timekeeping code. Not using this to assist tracing. Got this confused.

So yea, I think this should be ok, plus or minus determining if you really want xtime or xtime_cache.

Well this may be a real concern. It's not about tracing timekeeping (although it adds that functionality). His second patch (I didn't Cc you on that one) hooks to these tracepoints to update time accordingly.

What is being done is a way to have a "wall time" value being added to the ring buffer. But this needs to be very carefully done, because the all tracers use this, including the function tracer in NMI code. So the clock source can not take locks or do anything fancy.

Quoted 2 lines

What the idea is, is to have a semi clock that is read with some kind of fast increment, and then at clock ticks, this clock is synced up.

Hmm.. Yea, if that's the case, then I'm not a big fan of this approach.

It sounds like what's really needed is a lock-free variant of current_kernel_time() or something close to the CLOCK_MONOTONIC_COARSE functionality currently queued.

Doing it without locks might have some downsides, and I guess that's the point of the callback method (updates happen at prescribed times and likely under locks that the trace code understands so it avoids races and deadlocks).

-john

We can add a timer-source for ftrace to support wall-time display. It is based on Steven Rostedt <[email protected]>'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 <[email protected]>

kernel/trace/trace_clock.c +4 -0

+
+static int __init walltime_init(void)
+{
+	unsigned long flags;

kernel/trace/trace_clock.c +9 -0

+
+	return 0;
+}
+device_initcall_sync(walltime_init);
+
+u64 notrace trace_clock_walltime(void)
+{
+	return base_walltime + trace_clock();
+}

From: Xiao Guangrong <[email protected]>

This patch can trace current xtime and wall_to_monotonic. Then user can use ctime() to convert them to wall time which is easier to be understood, especially for flight-recorder which need to get trace event from a kernel dump file.

Example of ftrace output:

          <idle>-0     [000] 20118.489849: gtod_update_xtime: xtime=1243265589.999999824 wall_to_monotonic=3051713268.744158739
           <...>-4020  [001] 20118.489855: sys_open(filename: bf9e66e0, flags: 98800, mode: bf9e66e0)
           <...>-4020  [001] 20118.489873: sys_open -> 0xffffffec

ctime(1243265590) = date:Mon May 25 11:33:10 2009 So we can realize the task with pid 4020 open a file at Mon May 25 11:33:10 2009

Changelog:
v1->v2: Rebased by Zhao Lei <[email protected]>

Signed-off-by Xiao Guangrong <[email protected]>

Signed-off-by Zhao Lei <[email protected]>

---
 include/trace/events/xtime.h |   38 ++++++++++++++++++++++++++++++++++++++
 kernel/time/ntp.c            |    4 ++++
 kernel/time/timekeeping.c    |    6 ++++++

We can add a timer-source for ftrace to support wall-time display. It is based on Steven Rostedt <[email protected]>'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

...

Changelog:
v1->v2: Rebase to top of tip tree.

Signed-off-by Zhao Lei <[email protected]>

---
 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(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +0 -0

index fd52a19..160b6a8 100644

kernel/trace/trace.c +16 -5

 /*
  * trace_parser_get_init - gets the buffer for trace parser

@@ -1653,8 +1654,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");
+	}
 }
 
 

@@ -3387,8 +3397,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);

@@ -3418,7 +3428,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);
 

@@ -3428,6 +3438,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;

kernel/trace/trace.h +7 -1

index e747162..afee4de 100644
@@ -475,7 +475,13 @@ int trace_array_printk(struct trace_array *tr,
 
 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

kernel/trace/trace_clock.c +15 -0

index b588fd8..2b23023 100644
@@ -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,

kernel/trace/trace_clock.c +23 -0

+
+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();
+}

kernel/trace/trace_output.c +17 -4

index f572f44..2116c5f 100644
@@ -527,15 +527,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)

Signature · 1 line

1.5.5.3

Quoted 7 lines · Zhaolei

We can add a timer-source for ftrace to support wall-time display. It is based on Steven Rostedt <[email protected]>'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

Quoted 14 lines

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

Quoted 8 lines

         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
 #              | |       |                        |         |

The headers seem a bit broken. Is it a copy paste effect or?

Quoted 9 lines

             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

...

But nice result :)

Quoted 34 lines

Changelog:
v1->v2: Rebase to top of tip tree.

Signed-off-by Zhao Lei <[email protected]>

---
 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(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +1 -0

index fd52a19..160b6a8 100644
@@ -335,9 +335,10 @@ static struct {
 } trace_clocks[] = {
 	{ trace_clock_local,	"local" },
 	{ trace_clock_global,	"global" },
+	{ trace_clock_walltime,	"walltime" },
 };
 

kernel/trace/trace.c static struct { · line 341

Quoted 2 lines

kernel/trace/trace.c +1 -1

-int trace_clock_id;
+enum TRACE_CLOCK_TYPE trace_clock_type = TRACE_CLOCK_LOCAL;

Uppercase names are usually reserved for CPP macros.

Quoted 8 lines · Frederic Weisbecker

Quoted 7 lines · Zhaolei

We can add a timer-source for ftrace to support wall-time display. It is based on Steven Rostedt <[email protected]>'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

Hello, Frederic

Thanks for your review.

Quoted 26 lines

Quoted 14 lines

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

Quoted 8 lines

         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
 #              | |       |                        |         |

Quoted 1 line

The headers seem a bit broken. Is it a copy paste effect or?

No, it is a format bug of patch.
I'll fix it.

Quoted 48 lines

Quoted 9 lines

             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

...

But nice result :)

Quoted 34 lines

Changelog:
v1->v2: Rebase to top of tip tree.

Signed-off-by Zhao Lei <[email protected]>

---
 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(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +1 -0

index fd52a19..160b6a8 100644
@@ -335,9 +335,10 @@ static struct {
 } trace_clocks[] = {
 	{ trace_clock_local,	"local" },
 	{ trace_clock_global,	"global" },
+	{ trace_clock_walltime,	"walltime" },
 };
 

Quoted 6 lines

kernel/trace/trace.c static struct { · line 341

Quoted 2 lines

kernel/trace/trace.c +1 -1

-int trace_clock_id;
+enum TRACE_CLOCK_TYPE trace_clock_type = TRACE_CLOCK_LOCAL;

Uppercase names are usually reserved for CPP macros.

I'll rename it.

Quoted 93 lines · Zhaolei

Quoted 8 lines · Frederic Weisbecker

Quoted 7 lines · Zhaolei

We can add a timer-source for ftrace to support wall-time display. It is based on Steven Rostedt <[email protected]>'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

Hello, Frederic

Thanks for your review.

Quoted 25 lines

Quoted 14 lines

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

Quoted 8 lines

         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
 #              | |       |                        |         |

Quoted 1 line

The headers seem a bit broken. Is it a copy paste effect or?

No, it is a format bug of patch.
I'll fix it.

Quoted 51 lines

Quoted 8 lines

             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

...

But nice result :)

Quoted 28 lines

Changelog:
v1->v2: Rebase to top of tip tree.

Signed-off-by Zhao Lei <[email protected]>

---
 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(-)

include/linux/trace_clock.h +1 -0

index 7a81303..322707e 100644
@@ -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 */

kernel/trace/trace.c +0 -0

index fd52a19..160b6a8 100644

kernel/trace/trace.c static struct { · line 341

Quoted 8 lines

kernel/trace/trace.c +2 -1

@@ -335,9 +335,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;

Uppercase names are usually reserved for CPP macros.

Quoted 1 line

I'll rename it.

After the fixes that Frederic suggested, and the required timekeeping ACKS, I'll queue up your next version for v2.6.33. Looking forward to your new patches.

Quoted 24 lines

Hi Zhaolei,

Quoted 10 lines

Hi Zhaolei,

Could you not just save the wall time in some 64bit format within the current timestamp? Right now there's three clocks that can be used by ftrace. Two that you can really get two (I need to add access to the third). The default clock is sched_clock. But there's an option to get to global_clock:

debug/tracing/options/global-clock

Quoted 7 lines

# echo 1 > /debug/tracing/options/global-clock

Will enable the global clock. Perhaps we can add a "wall clock" version that will map the timestamps to the wall clock?

I really hate adding any more fields to the ring buffer headers. That takes away from the amount that you can record per page.

I think wall-time recording on every event is too slow. slower tracer isn't useful.
Instead, Can we make pseudo wall-time recording event periodically?

Quoted 7 lines

In nowadays, many workload run on cluster machine environment. Then We often need compare different machines tracing log. it mean TSC isn't sufficient. but nobody want performance reduce. Fortunatelly, ntp time adjustment is not happend so frequently. we don't need wall-time on _every_ event.

Thanks.

Yeah, that would really slow the tracing.

Can't we get a snapshot of the couple (walltime, cpu clock) once at startup.
Then we can retrieve the walltime when cpu_clock was 0 and compute the walltime for each traces at output time using the trace timestamp as a delta?

It can. but I don't think it is sufficient. On flight recorder use-case, The tracing run more than one year. And, Administrator only see last N sec log. (previous logs were overwritten by ring-buffer go-around)

Quoted 5 lines

It can. but I don't think it is sufficient. On flight recorder use-case, The tracing run more than one year. And, Administrator only see last N sec log. (previous logs were overwritten by ring-buffer go-around)

That's definitely something we want to enable ASAP.

I'm wondering why a single u64 timestamp is not enough to express the full, absolute range of time elapsed since bootup, in nanoseconds.

That would make walltime a matter of pretty-printing only - we'd have to convert the u64 nsec timestamp into a walltime format, right?

In fact we could change all the timestamps to be standardized along 'nanoseconds elapsed since 1970' or so - not nanoseconds since the last bootup. That still fits just fine within 64 bits - u64 nanoseconds has a scope of 500+ years.

Quoted 18 lines · KOSAKI Motohiro

Quoted 5 lines

It can. but I don't think it is sufficient. On flight recorder use-case, The tracing run more than one year. And, Administrator only see last N sec log. (previous logs were overwritten by ring-buffer go-around)

That's definitely something we want to enable ASAP.

I'm wondering why a single u64 timestamp is not enough to express the full, absolute range of time elapsed since bootup, in nanoseconds.

That would make walltime a matter of pretty-printing only - we'd have to convert the u64 nsec timestamp into a walltime format, right?

Quoted 4 lines

In fact we could change all the timestamps to be standardized along 'nanoseconds elapsed since 1970' or so - not nanoseconds since the last bootup. That still fits just fine within 64 bits - u64 nanoseconds has a scope of 500+ years.

Ah, you are right. thanks correct me. but I think ntp updating time storing is necessary too.