* [PATCH 0/3] TSC trace_clock
@ 2012-09-12 2:41 David Sharp
2012-09-12 2:41 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp
` (3 more replies)
0 siblings, 4 replies; 37+ messages in thread
From: David Sharp @ 2012-09-12 2:41 UTC (permalink / raw)
To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu
As discussed at Plumbers, here are my patches to add a TSC clock to ftrace.
Also noticeable is that the formatting patch improves the output of the
"counter" clock.
David Sharp (3):
tracing,x86: add a TSC trace_clock; reset buffer on clock change
tracing: reset ring buffer when changing trace_clocks
tracing: format non-nanosec times from tsc clock without a decimal
point.
include/linux/ftrace_event.h | 6 +++
include/linux/trace_clock.h | 3 ++
kernel/trace/trace.c | 26 ++++++++++++--
kernel/trace/trace.h | 4 --
kernel/trace/trace_clock.c | 16 ++++++++
kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++++++-------------
6 files changed, 105 insertions(+), 32 deletions(-)
--
1.7.7.3
^ permalink raw reply [flat|nested] 37+ messages in thread* [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change 2012-09-12 2:41 [PATCH 0/3] TSC trace_clock David Sharp @ 2012-09-12 2:41 ` David Sharp 2012-09-12 3:48 ` Steven Rostedt 2012-09-12 2:41 ` [PATCH 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp ` (2 subsequent siblings) 3 siblings, 1 reply; 37+ messages in thread From: David Sharp @ 2012-09-12 2:41 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu In order to promote interoperability between userspace tracers and ftrace, add a trace_clock that reports raw TSC values which will then be recorded in the ring buffer. Userspace tracers that also record TSCs are then on exactly the same time base as the kernel and events can be unambiguously interlaced. Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large timestamp values. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> --- include/linux/trace_clock.h | 3 +++ kernel/trace/trace.c | 3 +++ kernel/trace/trace_clock.c | 16 ++++++++++++++++ 3 files changed, 22 insertions(+), 0 deletions(-) diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h index 4eb4902..b86c7363 100644 --- a/include/linux/trace_clock.h +++ b/include/linux/trace_clock.h @@ -16,5 +16,8 @@ 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_counter(void); +#ifdef CONFIG_X86_TSC +extern u64 notrace trace_clock_tsc(void); +#endif #endif /* _LINUX_TRACE_CLOCK_H */ diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 5c38c81..dc1f1fa 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -480,6 +480,9 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, +#ifdef CONFIG_X86_TSC + { trace_clock_tsc, "tsc" }, +#endif }; int trace_clock_id; diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c index 3947835..1770737 100644 --- a/kernel/trace/trace_clock.c +++ b/kernel/trace/trace_clock.c @@ -125,3 +125,19 @@ u64 notrace trace_clock_counter(void) { return atomic64_add_return(1, &trace_counter); } + +#ifdef CONFIG_X86_TSC +/* + * trace_clock_tsc(): A clock that is just the cycle counter. + * + * Unlike the other clocks, this is not in nanoseconds. + */ +u64 notrace trace_clock_tsc(void) +{ + u64 ret; + rdtsc_barrier(); + rdtscll(ret); + + return ret; +} +#endif -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change 2012-09-12 2:41 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp @ 2012-09-12 3:48 ` Steven Rostedt 2012-09-12 18:48 ` David Sharp 0 siblings, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-12 3:48 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Masami Hiramatsu On Tue, 2012-09-11 at 19:41 -0700, David Sharp wrote: > In order to promote interoperability between userspace tracers and ftrace, > add a trace_clock that reports raw TSC values which will then be recorded > in the ring buffer. Userspace tracers that also record TSCs are then on > exactly the same time base as the kernel and events can be unambiguously > interlaced. > > Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large > timestamp values. > > Google-Bug-Id: 6980623 > Signed-off-by: David Sharp <dhsharp@google.com> > --- > include/linux/trace_clock.h | 3 +++ > kernel/trace/trace.c | 3 +++ > kernel/trace/trace_clock.c | 16 ++++++++++++++++ > 3 files changed, 22 insertions(+), 0 deletions(-) > > diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h > index 4eb4902..b86c7363 100644 > --- a/include/linux/trace_clock.h > +++ b/include/linux/trace_clock.h > @@ -16,5 +16,8 @@ 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_counter(void); > +#ifdef CONFIG_X86_TSC > +extern u64 notrace trace_clock_tsc(void); > +#endif > > #endif /* _LINUX_TRACE_CLOCK_H */ > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 5c38c81..dc1f1fa 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -480,6 +480,9 @@ static struct { > { trace_clock_local, "local" }, > { trace_clock_global, "global" }, > { trace_clock_counter, "counter" }, > +#ifdef CONFIG_X86_TSC > + { trace_clock_tsc, "tsc" }, > +#endif > }; I really hate adding arch defs in generic code. Perhaps what we could do is add a define here. Something like: #ifndef ARCH_TRACE_CLOCKS # define ARCH_TRACE_CLOCKS #endif [...] { trace_clock_counter, "counter" }, ARCH_TRACE_CLOCKS }; and have ARCH_TRACE_CLOCKS defined somewhere in an arch specific header. Not sure what header we could use though :-/ That is, in a header have: #define ARCH_TRACE_CLOCKS \ { trace_clock_x86_tsc, "tsc" }, and also define trace_clock_x86_tsc in arch/x86/kernel... -- Steve > > int trace_clock_id; > diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c > index 3947835..1770737 100644 > --- a/kernel/trace/trace_clock.c > +++ b/kernel/trace/trace_clock.c > @@ -125,3 +125,19 @@ u64 notrace trace_clock_counter(void) > { > return atomic64_add_return(1, &trace_counter); > } > + > +#ifdef CONFIG_X86_TSC > +/* > + * trace_clock_tsc(): A clock that is just the cycle counter. > + * > + * Unlike the other clocks, this is not in nanoseconds. > + */ > +u64 notrace trace_clock_tsc(void) > +{ > + u64 ret; > + rdtsc_barrier(); > + rdtscll(ret); > + > + return ret; > +} > +#endif ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change 2012-09-12 3:48 ` Steven Rostedt @ 2012-09-12 18:48 ` David Sharp 0 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 18:48 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, Masami Hiramatsu On Tue, Sep 11, 2012 at 8:48 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Tue, 2012-09-11 at 19:41 -0700, David Sharp wrote: >> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c >> index 5c38c81..dc1f1fa 100644 >> --- a/kernel/trace/trace.c >> +++ b/kernel/trace/trace.c >> @@ -480,6 +480,9 @@ static struct { >> { trace_clock_local, "local" }, >> { trace_clock_global, "global" }, >> { trace_clock_counter, "counter" }, >> +#ifdef CONFIG_X86_TSC >> + { trace_clock_tsc, "tsc" }, >> +#endif >> }; > > I really hate adding arch defs in generic code. Perhaps what we could do > is add a define here. Something like: > > #ifndef ARCH_TRACE_CLOCKS > # define ARCH_TRACE_CLOCKS > #endif > > [...] > { trace_clock_counter, "counter" }, > ARCH_TRACE_CLOCKS > }; > > and have ARCH_TRACE_CLOCKS defined somewhere in an arch specific header. > Not sure what header we could use though :-/ > > That is, in a header have: > > #define ARCH_TRACE_CLOCKS \ > { trace_clock_x86_tsc, "tsc" }, > > and also define trace_clock_x86_tsc in arch/x86/kernel... Good point. I'll figure out somewhere better to put it... ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH 2/3] tracing: reset ring buffer when changing trace_clocks 2012-09-12 2:41 [PATCH 0/3] TSC trace_clock David Sharp 2012-09-12 2:41 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp @ 2012-09-12 2:41 ` David Sharp 2012-09-12 2:41 ` [PATCH 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 2:41 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu Because the "tsc" clock isn't in nanoseconds, the ring buffer must be reset when changing clocks so that incomparable timestamps don't end up in the same trace. Tested: Confirmed switching clocks resets the trace buffer. Signed-off-by: David Sharp <dhsharp@google.com> --- kernel/trace/trace.c | 8 ++++++++ 1 files changed, 8 insertions(+), 0 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index dc1f1fa..6911f35 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4014,6 +4014,14 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf, if (max_tr.buffer) ring_buffer_set_clock(max_tr.buffer, trace_clocks[i].func); + /* + * New clock may not be consistent with the previous clock. + * Reset the buffer so that it doesn't have incomparable timestamps. + */ + tracing_reset_online_cpus(&global_trace); + if (max_tr.buffer) + tracing_reset_online_cpus(&max_tr); + mutex_unlock(&trace_types_lock); *fpos += cnt; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-12 2:41 [PATCH 0/3] TSC trace_clock David Sharp 2012-09-12 2:41 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp 2012-09-12 2:41 ` [PATCH 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp @ 2012-09-12 2:41 ` David Sharp 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 2:41 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> --- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 17 +++++++-- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++++++------------- 4 files changed, 76 insertions(+), 33 deletions(-) diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 6911f35..4b78ce2 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,12 +476,13 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, #ifdef CONFIG_X86_TSC - { trace_clock_tsc, "tsc" }, + { trace_clock_tsc, "tsc", 0 }, #endif }; @@ -2427,6 +2428,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3326,6 +3331,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..c86d62a 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,57 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + int ret; + struct trace_seq *s = &iter->seq; + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + unsigned long mark_thresh; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + ret = trace_seq_printf( + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", + ns2usecs(iter->ts), + abs_ts / USEC_PER_MSEC, + abs_ts % USEC_PER_MSEC, + rel_ts / USEC_PER_MSEC, + rel_ts % USEC_PER_MSEC); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; + /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v2 0/3] TSC trace_clock 2012-09-12 2:41 [PATCH 0/3] TSC trace_clock David Sharp ` (2 preceding siblings ...) 2012-09-12 2:41 ` [PATCH 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp @ 2012-09-12 23:31 ` David Sharp 2012-09-12 23:31 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp ` (3 more replies) 3 siblings, 4 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 23:31 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu Updated to move arch-specific bits out of generic code. I did this by adding a new file in asm-generic because I couldn't think of a better place to put it, but I'm open to suggestions. David Sharp (3): tracing,x86: add a TSC trace_clock tracing: reset ring buffer when changing trace_clocks tracing: format non-nanosec times from tsc clock without a decimal point. arch/x86/include/asm/trace_clock.h | 16 +++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 20 +++++++++ include/asm-generic/trace_clock.h | 15 +++++++ include/linux/ftrace_event.h | 6 +++ include/linux/trace_clock.h | 2 + kernel/trace/trace.c | 24 +++++++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++----------- 9 files changed, 138 insertions(+), 32 deletions(-) create mode 100644 arch/x86/include/asm/trace_clock.h create mode 100644 arch/x86/kernel/trace_clock.c create mode 100644 include/asm-generic/trace_clock.h -- 1.7.7.3 ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp @ 2012-09-12 23:31 ` David Sharp 2012-09-12 23:31 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock David Sharp ` (2 subsequent siblings) 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 23:31 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu In order to promote interoperability between userspace tracers and ftrace, add a trace_clock that reports raw TSC values which will then be recorded in the ring buffer. Userspace tracers that also record TSCs are then on exactly the same time base as the kernel and events can be unambiguously interlaced. Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large timestamp values. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> --- include/linux/trace_clock.h | 3 +++ kernel/trace/trace.c | 3 +++ kernel/trace/trace_clock.c | 16 ++++++++++++++++ 3 files changed, 22 insertions(+), 0 deletions(-) diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h index 4eb4902..b86c7363 100644 --- a/include/linux/trace_clock.h +++ b/include/linux/trace_clock.h @@ -16,5 +16,8 @@ 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_counter(void); +#ifdef CONFIG_X86_TSC +extern u64 notrace trace_clock_tsc(void); +#endif #endif /* _LINUX_TRACE_CLOCK_H */ diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 5c38c81..dc1f1fa 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -480,6 +480,9 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, +#ifdef CONFIG_X86_TSC + { trace_clock_tsc, "tsc" }, +#endif }; int trace_clock_id; diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c index 3947835..1770737 100644 --- a/kernel/trace/trace_clock.c +++ b/kernel/trace/trace_clock.c @@ -125,3 +125,19 @@ u64 notrace trace_clock_counter(void) { return atomic64_add_return(1, &trace_counter); } + +#ifdef CONFIG_X86_TSC +/* + * trace_clock_tsc(): A clock that is just the cycle counter. + * + * Unlike the other clocks, this is not in nanoseconds. + */ +u64 notrace trace_clock_tsc(void) +{ + u64 ret; + rdtsc_barrier(); + rdtscll(ret); + + return ret; +} +#endif -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp 2012-09-12 23:31 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp @ 2012-09-12 23:31 ` David Sharp 2012-09-13 1:15 ` Masami Hiramatsu 2012-09-13 1:23 ` Steven Rostedt 2012-09-12 23:31 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-12 23:32 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 3 siblings, 2 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 23:31 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu In order to promote interoperability between userspace tracers and ftrace, add a trace_clock that reports raw TSC values which will then be recorded in the ring buffer. Userspace tracers that also record TSCs are then on exactly the same time base as the kernel and events can be unambiguously interlaced. Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large timestamp values. v2: Move arch-specific bits out of generic code. Google-Bug-Id: 6980623 --- arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ include/asm-generic/trace_clock.h | 15 +++++++++++++++ include/linux/trace_clock.h | 2 ++ kernel/trace/trace.c | 1 + 6 files changed, 55 insertions(+), 0 deletions(-) create mode 100644 arch/x86/include/asm/trace_clock.h create mode 100644 arch/x86/kernel/trace_clock.c create mode 100644 include/asm-generic/trace_clock.h diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h new file mode 100644 index 0000000..0b1f391 --- /dev/null +++ b/arch/x86/include/asm/trace_clock.h @@ -0,0 +1,16 @@ +#ifndef _ASM_X86_TRACE_CLOCK_H +#define _ASM_X86_TRACE_CLOCK_H + +#include <linux/compiler.h> +#include <linux/types.h> + +#ifdef CONFIG_X86_TSC + +extern u64 notrace trace_clock_x86_tsc(void); + +# define ARCH_TRACE_CLOCKS \ + { trace_clock_x86_tsc, "tsc" }, + +#endif + +#endif /* _ASM_X86_TRACE_CLOCK_H */ diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile index 8215e56..0ee9344 100644 --- a/arch/x86/kernel/Makefile +++ b/arch/x86/kernel/Makefile @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o +obj-$(CONFIG_X86_TSC) += trace_clock.o obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c new file mode 100644 index 0000000..b8959f8 --- /dev/null +++ b/arch/x86/kernel/trace_clock.c @@ -0,0 +1,20 @@ +/* + * X86 trace clocks + */ +#include <asm/trace_clock.h> +#include <asm/barrier.h> +#include <asm/msr.h> + +/* + * trace_clock_x86_tsc(): A clock that is just the cycle counter. + * + * Unlike the other clocks, this is not in nanoseconds. + */ +u64 notrace trace_clock_x86_tsc(void) +{ + u64 ret; + rdtsc_barrier(); + rdtscll(ret); + + return ret; +} diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h new file mode 100644 index 0000000..648cdcd --- /dev/null +++ b/include/asm-generic/trace_clock.h @@ -0,0 +1,15 @@ +/* + * Arch-specific trace clocks. + */ +#ifndef _ASM_GENERIC_TRACE_CLOCK_H +#define _ASM_GENERIC_TRACE_CLOCK_H + +/* + * Additional trace clocks added to the trace_clocks + * array in kernel/trace/trace.c + */ +#ifndef ARCH_TRACE_CLOCKS +# define ARCH_TRACE_CLOCKS +#endif + +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h index 4eb4902..d563f37 100644 --- a/include/linux/trace_clock.h +++ b/include/linux/trace_clock.h @@ -12,6 +12,8 @@ #include <linux/compiler.h> #include <linux/types.h> +#include <asm/trace_clock.h> + extern u64 notrace trace_clock_local(void); extern u64 notrace trace_clock(void); extern u64 notrace trace_clock_global(void); diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 5c38c81..92fb08e 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -480,6 +480,7 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, + ARCH_TRACE_CLOCKS }; int trace_clock_id; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-12 23:31 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock David Sharp @ 2012-09-13 1:15 ` Masami Hiramatsu 2012-09-13 1:23 ` Steven Rostedt 1 sibling, 0 replies; 37+ messages in thread From: Masami Hiramatsu @ 2012-09-13 1:15 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Steven Rostedt (2012/09/13 8:31), David Sharp wrote: > In order to promote interoperability between userspace tracers and ftrace, > add a trace_clock that reports raw TSC values which will then be recorded > in the ring buffer. Userspace tracers that also record TSCs are then on > exactly the same time base as the kernel and events can be unambiguously > interlaced. > > Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large > timestamp values. Yeah, this is what I need! BTW, could you add your signed-off-by signature to your patches? Thank you, > > v2: > Move arch-specific bits out of generic code. > > Google-Bug-Id: 6980623 > --- > arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ > arch/x86/kernel/Makefile | 1 + > arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ > include/asm-generic/trace_clock.h | 15 +++++++++++++++ > include/linux/trace_clock.h | 2 ++ > kernel/trace/trace.c | 1 + > 6 files changed, 55 insertions(+), 0 deletions(-) > create mode 100644 arch/x86/include/asm/trace_clock.h > create mode 100644 arch/x86/kernel/trace_clock.c > create mode 100644 include/asm-generic/trace_clock.h > > diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h > new file mode 100644 > index 0000000..0b1f391 > --- /dev/null > +++ b/arch/x86/include/asm/trace_clock.h > @@ -0,0 +1,16 @@ > +#ifndef _ASM_X86_TRACE_CLOCK_H > +#define _ASM_X86_TRACE_CLOCK_H > + > +#include <linux/compiler.h> > +#include <linux/types.h> > + > +#ifdef CONFIG_X86_TSC > + > +extern u64 notrace trace_clock_x86_tsc(void); > + > +# define ARCH_TRACE_CLOCKS \ > + { trace_clock_x86_tsc, "tsc" }, > + > +#endif > + > +#endif /* _ASM_X86_TRACE_CLOCK_H */ > diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile > index 8215e56..0ee9344 100644 > --- a/arch/x86/kernel/Makefile > +++ b/arch/x86/kernel/Makefile > @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o > obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o > obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o > obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o > +obj-$(CONFIG_X86_TSC) += trace_clock.o > obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o > obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o > obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o > diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c > new file mode 100644 > index 0000000..b8959f8 > --- /dev/null > +++ b/arch/x86/kernel/trace_clock.c > @@ -0,0 +1,20 @@ > +/* > + * X86 trace clocks > + */ > +#include <asm/trace_clock.h> > +#include <asm/barrier.h> > +#include <asm/msr.h> > + > +/* > + * trace_clock_x86_tsc(): A clock that is just the cycle counter. > + * > + * Unlike the other clocks, this is not in nanoseconds. > + */ > +u64 notrace trace_clock_x86_tsc(void) > +{ > + u64 ret; > + rdtsc_barrier(); > + rdtscll(ret); > + > + return ret; > +} > diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h > new file mode 100644 > index 0000000..648cdcd > --- /dev/null > +++ b/include/asm-generic/trace_clock.h > @@ -0,0 +1,15 @@ > +/* > + * Arch-specific trace clocks. > + */ > +#ifndef _ASM_GENERIC_TRACE_CLOCK_H > +#define _ASM_GENERIC_TRACE_CLOCK_H > + > +/* > + * Additional trace clocks added to the trace_clocks > + * array in kernel/trace/trace.c > + */ > +#ifndef ARCH_TRACE_CLOCKS > +# define ARCH_TRACE_CLOCKS > +#endif > + > +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ > diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h > index 4eb4902..d563f37 100644 > --- a/include/linux/trace_clock.h > +++ b/include/linux/trace_clock.h > @@ -12,6 +12,8 @@ > #include <linux/compiler.h> > #include <linux/types.h> > > +#include <asm/trace_clock.h> > + > extern u64 notrace trace_clock_local(void); > extern u64 notrace trace_clock(void); > extern u64 notrace trace_clock_global(void); > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 5c38c81..92fb08e 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -480,6 +480,7 @@ static struct { > { trace_clock_local, "local" }, > { trace_clock_global, "global" }, > { trace_clock_counter, "counter" }, > + ARCH_TRACE_CLOCKS > }; > > int trace_clock_id; > -- Masami HIRAMATSU Software Platform Research Dept. Linux Technology Center Hitachi, Ltd., Yokohama Research Laboratory E-mail: masami.hiramatsu.pt@hitachi.com ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-12 23:31 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock David Sharp 2012-09-13 1:15 ` Masami Hiramatsu @ 2012-09-13 1:23 ` Steven Rostedt 2012-09-18 21:37 ` David Sharp 2012-09-18 21:46 ` David Sharp 1 sibling, 2 replies; 37+ messages in thread From: Steven Rostedt @ 2012-09-13 1:23 UTC (permalink / raw) To: David Sharp Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin This change will require an ack from one of the x86 maintainers. For reference to this patch, please see this thread: https://lkml.org/lkml/2012/9/11/572 On Wed, 2012-09-12 at 16:31 -0700, David Sharp wrote: > In order to promote interoperability between userspace tracers and ftrace, > add a trace_clock that reports raw TSC values which will then be recorded > in the ring buffer. Userspace tracers that also record TSCs are then on > exactly the same time base as the kernel and events can be unambiguously > interlaced. > > Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large > timestamp values. > > v2: > Move arch-specific bits out of generic code. As Masami pointed out, please add a SOB to your patches. Thanks, -- Steve > > Google-Bug-Id: 6980623 > --- > arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ > arch/x86/kernel/Makefile | 1 + > arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ > include/asm-generic/trace_clock.h | 15 +++++++++++++++ > include/linux/trace_clock.h | 2 ++ > kernel/trace/trace.c | 1 + > 6 files changed, 55 insertions(+), 0 deletions(-) > create mode 100644 arch/x86/include/asm/trace_clock.h > create mode 100644 arch/x86/kernel/trace_clock.c > create mode 100644 include/asm-generic/trace_clock.h > > diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h > new file mode 100644 > index 0000000..0b1f391 > --- /dev/null > +++ b/arch/x86/include/asm/trace_clock.h > @@ -0,0 +1,16 @@ > +#ifndef _ASM_X86_TRACE_CLOCK_H > +#define _ASM_X86_TRACE_CLOCK_H > + > +#include <linux/compiler.h> > +#include <linux/types.h> > + > +#ifdef CONFIG_X86_TSC > + > +extern u64 notrace trace_clock_x86_tsc(void); > + > +# define ARCH_TRACE_CLOCKS \ > + { trace_clock_x86_tsc, "tsc" }, > + > +#endif > + > +#endif /* _ASM_X86_TRACE_CLOCK_H */ > diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile > index 8215e56..0ee9344 100644 > --- a/arch/x86/kernel/Makefile > +++ b/arch/x86/kernel/Makefile > @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o > obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o > obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o > obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o > +obj-$(CONFIG_X86_TSC) += trace_clock.o > obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o > obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o > obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o > diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c > new file mode 100644 > index 0000000..b8959f8 > --- /dev/null > +++ b/arch/x86/kernel/trace_clock.c > @@ -0,0 +1,20 @@ > +/* > + * X86 trace clocks > + */ > +#include <asm/trace_clock.h> > +#include <asm/barrier.h> > +#include <asm/msr.h> > + > +/* > + * trace_clock_x86_tsc(): A clock that is just the cycle counter. > + * > + * Unlike the other clocks, this is not in nanoseconds. > + */ > +u64 notrace trace_clock_x86_tsc(void) > +{ > + u64 ret; > + rdtsc_barrier(); > + rdtscll(ret); > + > + return ret; > +} > diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h > new file mode 100644 > index 0000000..648cdcd > --- /dev/null > +++ b/include/asm-generic/trace_clock.h > @@ -0,0 +1,15 @@ > +/* > + * Arch-specific trace clocks. > + */ > +#ifndef _ASM_GENERIC_TRACE_CLOCK_H > +#define _ASM_GENERIC_TRACE_CLOCK_H > + > +/* > + * Additional trace clocks added to the trace_clocks > + * array in kernel/trace/trace.c > + */ > +#ifndef ARCH_TRACE_CLOCKS > +# define ARCH_TRACE_CLOCKS > +#endif > + > +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ > diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h > index 4eb4902..d563f37 100644 > --- a/include/linux/trace_clock.h > +++ b/include/linux/trace_clock.h > @@ -12,6 +12,8 @@ > #include <linux/compiler.h> > #include <linux/types.h> > > +#include <asm/trace_clock.h> > + > extern u64 notrace trace_clock_local(void); > extern u64 notrace trace_clock(void); > extern u64 notrace trace_clock_global(void); > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 5c38c81..92fb08e 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -480,6 +480,7 @@ static struct { > { trace_clock_local, "local" }, > { trace_clock_global, "global" }, > { trace_clock_counter, "counter" }, > + ARCH_TRACE_CLOCKS > }; > > int trace_clock_id; ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-13 1:23 ` Steven Rostedt @ 2012-09-18 21:37 ` David Sharp 2012-09-18 21:37 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp ` (3 more replies) 2012-09-18 21:46 ` David Sharp 1 sibling, 4 replies; 37+ messages in thread From: David Sharp @ 2012-09-18 21:37 UTC (permalink / raw) To: linux-kernel Cc: David Sharp, Steven Rostedt, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin In order to promote interoperability between userspace tracers and ftrace, add a trace_clock that reports raw TSC values which will then be recorded in the ring buffer. Userspace tracers that also record TSCs are then on exactly the same time base as the kernel and events can be unambiguously interlaced. Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large timestamp values. v2: Move arch-specific bits out of generic code. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: "H. Peter Anvin" <hpa@linux.intel.com> --- arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ include/asm-generic/trace_clock.h | 15 +++++++++++++++ include/linux/trace_clock.h | 2 ++ kernel/trace/trace.c | 1 + 6 files changed, 55 insertions(+), 0 deletions(-) create mode 100644 arch/x86/include/asm/trace_clock.h create mode 100644 arch/x86/kernel/trace_clock.c create mode 100644 include/asm-generic/trace_clock.h diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h new file mode 100644 index 0000000..0b1f391 --- /dev/null +++ b/arch/x86/include/asm/trace_clock.h @@ -0,0 +1,16 @@ +#ifndef _ASM_X86_TRACE_CLOCK_H +#define _ASM_X86_TRACE_CLOCK_H + +#include <linux/compiler.h> +#include <linux/types.h> + +#ifdef CONFIG_X86_TSC + +extern u64 notrace trace_clock_x86_tsc(void); + +# define ARCH_TRACE_CLOCKS \ + { trace_clock_x86_tsc, "tsc" }, + +#endif + +#endif /* _ASM_X86_TRACE_CLOCK_H */ diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile index 8215e56..0ee9344 100644 --- a/arch/x86/kernel/Makefile +++ b/arch/x86/kernel/Makefile @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o +obj-$(CONFIG_X86_TSC) += trace_clock.o obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c new file mode 100644 index 0000000..b8959f8 --- /dev/null +++ b/arch/x86/kernel/trace_clock.c @@ -0,0 +1,20 @@ +/* + * X86 trace clocks + */ +#include <asm/trace_clock.h> +#include <asm/barrier.h> +#include <asm/msr.h> + +/* + * trace_clock_x86_tsc(): A clock that is just the cycle counter. + * + * Unlike the other clocks, this is not in nanoseconds. + */ +u64 notrace trace_clock_x86_tsc(void) +{ + u64 ret; + rdtsc_barrier(); + rdtscll(ret); + + return ret; +} diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h new file mode 100644 index 0000000..648cdcd --- /dev/null +++ b/include/asm-generic/trace_clock.h @@ -0,0 +1,15 @@ +/* + * Arch-specific trace clocks. + */ +#ifndef _ASM_GENERIC_TRACE_CLOCK_H +#define _ASM_GENERIC_TRACE_CLOCK_H + +/* + * Additional trace clocks added to the trace_clocks + * array in kernel/trace/trace.c + */ +#ifndef ARCH_TRACE_CLOCKS +# define ARCH_TRACE_CLOCKS +#endif + +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h index 4eb4902..d563f37 100644 --- a/include/linux/trace_clock.h +++ b/include/linux/trace_clock.h @@ -12,6 +12,8 @@ #include <linux/compiler.h> #include <linux/types.h> +#include <asm/trace_clock.h> + extern u64 notrace trace_clock_local(void); extern u64 notrace trace_clock(void); extern u64 notrace trace_clock_global(void); diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 5c38c81..92fb08e 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -480,6 +480,7 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, + ARCH_TRACE_CLOCKS }; int trace_clock_id; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks 2012-09-18 21:37 ` David Sharp @ 2012-09-18 21:37 ` David Sharp 2012-09-18 21:37 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp ` (2 subsequent siblings) 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-18 21:37 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu Because the "tsc" clock isn't in nanoseconds, the ring buffer must be reset when changing clocks so that incomparable timestamps don't end up in the same trace. Tested: Confirmed switching clocks resets the trace buffer. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- kernel/trace/trace.c | 8 ++++++++ 1 files changed, 8 insertions(+), 0 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 92fb08e..4e26df3 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4012,6 +4012,14 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf, if (max_tr.buffer) ring_buffer_set_clock(max_tr.buffer, trace_clocks[i].func); + /* + * New clock may not be consistent with the previous clock. + * Reset the buffer so that it doesn't have incomparable timestamps. + */ + tracing_reset_online_cpus(&global_trace); + if (max_tr.buffer) + tracing_reset_online_cpus(&max_tr); + mutex_unlock(&trace_types_lock); *fpos += cnt; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-18 21:37 ` David Sharp 2012-09-18 21:37 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp @ 2012-09-18 21:37 ` David Sharp 2012-09-19 2:10 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt 2012-09-20 8:55 ` Ingo Molnar 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-18 21:37 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... v2: Move arch-specific bits out of generic code. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- arch/x86/include/asm/trace_clock.h | 2 +- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 15 +++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++----------- 5 files changed, 76 insertions(+), 33 deletions(-) diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 0b1f391..4af2eb7 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h @@ -9,7 +9,7 @@ extern u64 notrace trace_clock_x86_tsc(void); # define ARCH_TRACE_CLOCKS \ - { trace_clock_x86_tsc, "tsc" }, + { trace_clock_x86_tsc, "tsc", .in_ns = 0 }, #endif diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 4e26df3..3fe4c5b 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,10 +476,11 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, ARCH_TRACE_CLOCKS }; @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..c86d62a 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,57 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + int ret; + struct trace_seq *s = &iter->seq; + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + unsigned long mark_thresh; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + ret = trace_seq_printf( + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", + ns2usecs(iter->ts), + abs_ts / USEC_PER_MSEC, + abs_ts % USEC_PER_MSEC, + rel_ts / USEC_PER_MSEC, + rel_ts % USEC_PER_MSEC); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; + /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-18 21:37 ` David Sharp 2012-09-18 21:37 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-18 21:37 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp @ 2012-09-19 2:10 ` Steven Rostedt 2012-09-20 8:55 ` Ingo Molnar 3 siblings, 0 replies; 37+ messages in thread From: Steven Rostedt @ 2012-09-19 2:10 UTC (permalink / raw) To: David Sharp Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin On Tue, 2012-09-18 at 14:37 -0700, David Sharp wrote: > In order to promote interoperability between userspace tracers and ftrace, > add a trace_clock that reports raw TSC values which will then be recorded > in the ring buffer. Userspace tracers that also record TSCs are then on > exactly the same time base as the kernel and events can be unambiguously > interlaced. > > Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large > timestamp values. > > v2: > Move arch-specific bits out of generic code. > > Google-Bug-Id: 6980623 > Signed-off-by: David Sharp <dhsharp@google.com> > Cc: Steven Rostedt <rostedt@goodmis.org> > Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> > Cc: Ingo Molnar <mingo@kernel.org> > Cc: Thomas Gleixner <tglx@linutronix.de> > Cc: "H. Peter Anvin" <hpa@linux.intel.com> Again this needs an Acked-by from one of the above. -- Steve > --- > arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ > arch/x86/kernel/Makefile | 1 + > arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ > include/asm-generic/trace_clock.h | 15 +++++++++++++++ > include/linux/trace_clock.h | 2 ++ > kernel/trace/trace.c | 1 + > 6 files changed, 55 insertions(+), 0 deletions(-) > create mode 100644 arch/x86/include/asm/trace_clock.h > create mode 100644 arch/x86/kernel/trace_clock.c > create mode 100644 include/asm-generic/trace_clock.h > > diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h > new file mode 100644 > index 0000000..0b1f391 > --- /dev/null > +++ b/arch/x86/include/asm/trace_clock.h > @@ -0,0 +1,16 @@ > +#ifndef _ASM_X86_TRACE_CLOCK_H > +#define _ASM_X86_TRACE_CLOCK_H > + > +#include <linux/compiler.h> > +#include <linux/types.h> > + > +#ifdef CONFIG_X86_TSC > + > +extern u64 notrace trace_clock_x86_tsc(void); > + > +# define ARCH_TRACE_CLOCKS \ > + { trace_clock_x86_tsc, "tsc" }, > + > +#endif > + > +#endif /* _ASM_X86_TRACE_CLOCK_H */ > diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile > index 8215e56..0ee9344 100644 > --- a/arch/x86/kernel/Makefile > +++ b/arch/x86/kernel/Makefile > @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o > obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o > obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o > obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o > +obj-$(CONFIG_X86_TSC) += trace_clock.o > obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o > obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o > obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o > diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c > new file mode 100644 > index 0000000..b8959f8 > --- /dev/null > +++ b/arch/x86/kernel/trace_clock.c > @@ -0,0 +1,20 @@ > +/* > + * X86 trace clocks > + */ > +#include <asm/trace_clock.h> > +#include <asm/barrier.h> > +#include <asm/msr.h> > + > +/* > + * trace_clock_x86_tsc(): A clock that is just the cycle counter. > + * > + * Unlike the other clocks, this is not in nanoseconds. > + */ > +u64 notrace trace_clock_x86_tsc(void) > +{ > + u64 ret; > + rdtsc_barrier(); > + rdtscll(ret); > + > + return ret; > +} > diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h > new file mode 100644 > index 0000000..648cdcd > --- /dev/null > +++ b/include/asm-generic/trace_clock.h > @@ -0,0 +1,15 @@ > +/* > + * Arch-specific trace clocks. > + */ > +#ifndef _ASM_GENERIC_TRACE_CLOCK_H > +#define _ASM_GENERIC_TRACE_CLOCK_H > + > +/* > + * Additional trace clocks added to the trace_clocks > + * array in kernel/trace/trace.c > + */ > +#ifndef ARCH_TRACE_CLOCKS > +# define ARCH_TRACE_CLOCKS > +#endif > + > +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ > diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h > index 4eb4902..d563f37 100644 > --- a/include/linux/trace_clock.h > +++ b/include/linux/trace_clock.h > @@ -12,6 +12,8 @@ > #include <linux/compiler.h> > #include <linux/types.h> > > +#include <asm/trace_clock.h> > + > extern u64 notrace trace_clock_local(void); > extern u64 notrace trace_clock(void); > extern u64 notrace trace_clock_global(void); > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 5c38c81..92fb08e 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -480,6 +480,7 @@ static struct { > { trace_clock_local, "local" }, > { trace_clock_global, "global" }, > { trace_clock_counter, "counter" }, > + ARCH_TRACE_CLOCKS > }; > > int trace_clock_id; ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-18 21:37 ` David Sharp ` (2 preceding siblings ...) 2012-09-19 2:10 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt @ 2012-09-20 8:55 ` Ingo Molnar 2012-09-20 13:34 ` Steven Rostedt 2012-09-20 22:53 ` [PATCH v2 " David Sharp 3 siblings, 2 replies; 37+ messages in thread From: Ingo Molnar @ 2012-09-20 8:55 UTC (permalink / raw) To: David Sharp Cc: linux-kernel, Steven Rostedt, Masami Hiramatsu, Thomas Gleixner, H. Peter Anvin * David Sharp <dhsharp@google.com> wrote: > In order to promote interoperability between userspace tracers and ftrace, > add a trace_clock that reports raw TSC values which will then be recorded > in the ring buffer. Userspace tracers that also record TSCs are then on > exactly the same time base as the kernel and events can be unambiguously > interlaced. > > Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large > timestamp values. > > v2: > Move arch-specific bits out of generic code. > > Google-Bug-Id: 6980623 > Signed-off-by: David Sharp <dhsharp@google.com> > Cc: Steven Rostedt <rostedt@goodmis.org> > Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> > Cc: Ingo Molnar <mingo@kernel.org> > Cc: Thomas Gleixner <tglx@linutronix.de> > Cc: "H. Peter Anvin" <hpa@linux.intel.com> > --- > arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ > arch/x86/kernel/Makefile | 1 + > arch/x86/kernel/trace_clock.c | 20 ++++++++++++++++++++ > include/asm-generic/trace_clock.h | 15 +++++++++++++++ > include/linux/trace_clock.h | 2 ++ > kernel/trace/trace.c | 1 + > 6 files changed, 55 insertions(+), 0 deletions(-) > create mode 100644 arch/x86/include/asm/trace_clock.h > create mode 100644 arch/x86/kernel/trace_clock.c > create mode 100644 include/asm-generic/trace_clock.h > > diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h > new file mode 100644 > index 0000000..0b1f391 > --- /dev/null > +++ b/arch/x86/include/asm/trace_clock.h > @@ -0,0 +1,16 @@ > +#ifndef _ASM_X86_TRACE_CLOCK_H > +#define _ASM_X86_TRACE_CLOCK_H > + > +#include <linux/compiler.h> > +#include <linux/types.h> > + > +#ifdef CONFIG_X86_TSC > + > +extern u64 notrace trace_clock_x86_tsc(void); > + > +# define ARCH_TRACE_CLOCKS \ > + { trace_clock_x86_tsc, "tsc" }, I'd name it "x86-tsc", to make sure the naming is unique. That will also enable the addition of other hw clocks, should the need arise. > + > +#endif > + > +#endif /* _ASM_X86_TRACE_CLOCK_H */ > diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile > index 8215e56..0ee9344 100644 > --- a/arch/x86/kernel/Makefile > +++ b/arch/x86/kernel/Makefile > @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o > obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o > obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o > obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o > +obj-$(CONFIG_X86_TSC) += trace_clock.o > obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o > obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o > obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o > diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c > new file mode 100644 > index 0000000..b8959f8 > --- /dev/null > +++ b/arch/x86/kernel/trace_clock.c > @@ -0,0 +1,20 @@ > +/* > + * X86 trace clocks > + */ > +#include <asm/trace_clock.h> > +#include <asm/barrier.h> > +#include <asm/msr.h> > + > +/* > + * trace_clock_x86_tsc(): A clock that is just the cycle counter. > + * > + * Unlike the other clocks, this is not in nanoseconds. > + */ > +u64 notrace trace_clock_x86_tsc(void) > +{ > + u64 ret; > + rdtsc_barrier(); Missing newline. > + rdtscll(ret); > + > + return ret; > +} > diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h > new file mode 100644 > index 0000000..648cdcd > --- /dev/null > +++ b/include/asm-generic/trace_clock.h > @@ -0,0 +1,15 @@ > +/* > + * Arch-specific trace clocks. > + */ > +#ifndef _ASM_GENERIC_TRACE_CLOCK_H > +#define _ASM_GENERIC_TRACE_CLOCK_H We typically put header guards to the first and last lines of the file, that way it can be ignored easily. > + > +/* > + * Additional trace clocks added to the trace_clocks > + * array in kernel/trace/trace.c I'd add: "None if the architecture has not defined it." > + */ > +#ifndef ARCH_TRACE_CLOCKS > +# define ARCH_TRACE_CLOCKS > +#endif > + > +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ > diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h > index 4eb4902..d563f37 100644 > --- a/include/linux/trace_clock.h > +++ b/include/linux/trace_clock.h > @@ -12,6 +12,8 @@ > #include <linux/compiler.h> > #include <linux/types.h> > > +#include <asm/trace_clock.h> > + > extern u64 notrace trace_clock_local(void); > extern u64 notrace trace_clock(void); > extern u64 notrace trace_clock_global(void); > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 5c38c81..92fb08e 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -480,6 +480,7 @@ static struct { > { trace_clock_local, "local" }, > { trace_clock_global, "global" }, > { trace_clock_counter, "counter" }, > + ARCH_TRACE_CLOCKS > }; > Looks useful and good otherwise: Acked-by: Ingo Molnar <mingo@kernel.org> Thanks, Ingo ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-20 8:55 ` Ingo Molnar @ 2012-09-20 13:34 ` Steven Rostedt 2012-09-20 22:52 ` [PATCH v3 " David Sharp 2012-09-20 22:53 ` [PATCH v2 " David Sharp 1 sibling, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-20 13:34 UTC (permalink / raw) To: Ingo Molnar Cc: David Sharp, linux-kernel, Masami Hiramatsu, Thomas Gleixner, H. Peter Anvin On Thu, 2012-09-20 at 10:55 +0200, Ingo Molnar wrote: > Looks useful and good otherwise: > > Acked-by: Ingo Molnar <mingo@kernel.org> > David, Please submit a v3 with Ingo's updates and I'll go ahead and start testing it. Thanks! -- Steve ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH v3 1/3] tracing,x86: add a TSC trace_clock 2012-09-20 13:34 ` Steven Rostedt @ 2012-09-20 22:52 ` David Sharp 2012-09-20 22:52 ` [PATCH v3 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp ` (2 more replies) 0 siblings, 3 replies; 37+ messages in thread From: David Sharp @ 2012-09-20 22:52 UTC (permalink / raw) To: linux-kernel Cc: David Sharp, Steven Rostedt, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin In order to promote interoperability between userspace tracers and ftrace, add a trace_clock that reports raw TSC values which will then be recorded in the ring buffer. Userspace tracers that also record TSCs are then on exactly the same time base as the kernel and events can be unambiguously interlaced. Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large timestamp values. v2: Move arch-specific bits out of generic code. v3: Rename "x86-tsc", cleanups Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: "H. Peter Anvin" <hpa@linux.intel.com> Acked-by: Ingo Molnar <mingo@kernel.org> --- arch/x86/include/asm/trace_clock.h | 16 ++++++++++++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 21 +++++++++++++++++++++ include/asm-generic/trace_clock.h | 16 ++++++++++++++++ include/linux/trace_clock.h | 2 ++ kernel/trace/trace.c | 1 + 6 files changed, 57 insertions(+), 0 deletions(-) create mode 100644 arch/x86/include/asm/trace_clock.h create mode 100644 arch/x86/kernel/trace_clock.c create mode 100644 include/asm-generic/trace_clock.h diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h new file mode 100644 index 0000000..7ee0d8c --- /dev/null +++ b/arch/x86/include/asm/trace_clock.h @@ -0,0 +1,16 @@ +#ifndef _ASM_X86_TRACE_CLOCK_H +#define _ASM_X86_TRACE_CLOCK_H + +#include <linux/compiler.h> +#include <linux/types.h> + +#ifdef CONFIG_X86_TSC + +extern u64 notrace trace_clock_x86_tsc(void); + +# define ARCH_TRACE_CLOCKS \ + { trace_clock_x86_tsc, "x86-tsc" }, + +#endif + +#endif /* _ASM_X86_TRACE_CLOCK_H */ diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile index 8215e56..0ee9344 100644 --- a/arch/x86/kernel/Makefile +++ b/arch/x86/kernel/Makefile @@ -62,6 +62,7 @@ obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o obj-$(CONFIG_FTRACE_SYSCALLS) += ftrace.o +obj-$(CONFIG_X86_TSC) += trace_clock.o obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o diff --git a/arch/x86/kernel/trace_clock.c b/arch/x86/kernel/trace_clock.c new file mode 100644 index 0000000..25b9937 --- /dev/null +++ b/arch/x86/kernel/trace_clock.c @@ -0,0 +1,21 @@ +/* + * X86 trace clocks + */ +#include <asm/trace_clock.h> +#include <asm/barrier.h> +#include <asm/msr.h> + +/* + * trace_clock_x86_tsc(): A clock that is just the cycle counter. + * + * Unlike the other clocks, this is not in nanoseconds. + */ +u64 notrace trace_clock_x86_tsc(void) +{ + u64 ret; + + rdtsc_barrier(); + rdtscll(ret); + + return ret; +} diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h new file mode 100644 index 0000000..6726f1b --- /dev/null +++ b/include/asm-generic/trace_clock.h @@ -0,0 +1,16 @@ +#ifndef _ASM_GENERIC_TRACE_CLOCK_H +#define _ASM_GENERIC_TRACE_CLOCK_H +/* + * Arch-specific trace clocks. + */ + +/* + * Additional trace clocks added to the trace_clocks + * array in kernel/trace/trace.c + * None if the architecture has not defined it. + */ +#ifndef ARCH_TRACE_CLOCKS +# define ARCH_TRACE_CLOCKS +#endif + +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h index 4eb4902..d563f37 100644 --- a/include/linux/trace_clock.h +++ b/include/linux/trace_clock.h @@ -12,6 +12,8 @@ #include <linux/compiler.h> #include <linux/types.h> +#include <asm/trace_clock.h> + extern u64 notrace trace_clock_local(void); extern u64 notrace trace_clock(void); extern u64 notrace trace_clock_global(void); diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 5c38c81..92fb08e 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -480,6 +480,7 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, + ARCH_TRACE_CLOCKS }; int trace_clock_id; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v3 2/3] tracing: reset ring buffer when changing trace_clocks 2012-09-20 22:52 ` [PATCH v3 " David Sharp @ 2012-09-20 22:52 ` David Sharp 2012-09-20 22:52 ` [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 2012-09-29 3:15 ` [PATCH v3 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt 2 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-20 22:52 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu Because the "tsc" clock isn't in nanoseconds, the ring buffer must be reset when changing clocks so that incomparable timestamps don't end up in the same trace. Tested: Confirmed switching clocks resets the trace buffer. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- kernel/trace/trace.c | 8 ++++++++ 1 files changed, 8 insertions(+), 0 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 92fb08e..4e26df3 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4012,6 +4012,14 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf, if (max_tr.buffer) ring_buffer_set_clock(max_tr.buffer, trace_clocks[i].func); + /* + * New clock may not be consistent with the previous clock. + * Reset the buffer so that it doesn't have incomparable timestamps. + */ + tracing_reset_online_cpus(&global_trace); + if (max_tr.buffer) + tracing_reset_online_cpus(&max_tr); + mutex_unlock(&trace_types_lock); *fpos += cnt; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-20 22:52 ` [PATCH v3 " David Sharp 2012-09-20 22:52 ` [PATCH v3 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp @ 2012-09-20 22:52 ` David Sharp 2012-09-25 3:27 ` Steven Rostedt 2012-09-29 3:15 ` [PATCH v3 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt 2 siblings, 1 reply; 37+ messages in thread From: David Sharp @ 2012-09-20 22:52 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... v2: Move arch-specific bits out of generic code. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- arch/x86/include/asm/trace_clock.h | 2 +- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 15 +++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++----------- 5 files changed, 76 insertions(+), 33 deletions(-) diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 7ee0d8c..45e17f5 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h @@ -9,7 +9,7 @@ extern u64 notrace trace_clock_x86_tsc(void); # define ARCH_TRACE_CLOCKS \ - { trace_clock_x86_tsc, "x86-tsc" }, + { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, #endif diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 4e26df3..3fe4c5b 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,10 +476,11 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, ARCH_TRACE_CLOCKS }; @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..c86d62a 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,57 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + int ret; + struct trace_seq *s = &iter->seq; + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + unsigned long mark_thresh; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + ret = trace_seq_printf( + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", + ns2usecs(iter->ts), + abs_ts / USEC_PER_MSEC, + abs_ts % USEC_PER_MSEC, + rel_ts / USEC_PER_MSEC, + rel_ts % USEC_PER_MSEC); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; + /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-20 22:52 ` [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp @ 2012-09-25 3:27 ` Steven Rostedt 2012-09-25 20:48 ` David Sharp 0 siblings, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-25 3:27 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Masami Hiramatsu On Thu, 2012-09-20 at 15:52 -0700, David Sharp wrote: > With the addition of the "tsc" clock, formatting timestamps to look like > fractional seconds is misleading. Mark clocks as either in nanoseconds or > not, and format non-nanosecond timestamps as decimal integers. I got this: /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' when building for x86_32. > + int ret; > + struct trace_seq *s = &iter->seq; > + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; > + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; > + unsigned long long abs_ts = iter->ts - iter->tr->time_start; > + unsigned long long rel_ts = next_ts - iter->ts; > + unsigned long mark_thresh; > + > + if (in_ns) { > + abs_ts = ns2usecs(abs_ts); > + rel_ts = ns2usecs(rel_ts); > + mark_thresh = preempt_mark_thresh_us; > + } else > + mark_thresh = preempt_mark_thresh_cycles; > + > + if (verbose && in_ns) { > + ret = trace_seq_printf( > + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", > + ns2usecs(iter->ts), > + abs_ts / USEC_PER_MSEC, > + abs_ts % USEC_PER_MSEC, > + rel_ts / USEC_PER_MSEC, You can't divide 64 bit numbers in the kernel. It breaks on 32bit archs. -- Steve > + rel_ts % USEC_PER_MSEC); > + } else if (verbose && !in_ns) { > + ret = trace_seq_printf( > + s, "[%016llx] %lld (+%lld): ", > + iter->ts, abs_ts, rel_ts); > + } else { /* !verbose */ > + ret = trace_seq_printf( > + s, " %4lld%s%c: ", > + abs_ts, > + in_ns ? "us" : "", > + rel_ts > mark_thresh ? '!' : > + rel_ts > 1 ? '+' : ' '); > + } > + return ret; > } > > 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; > + unsigned long long t; > + unsigned long secs, usec_rem; > char comm[TASK_COMM_LEN]; > int ret; > > @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) > return 0; > } > > - return trace_seq_printf(s, " %5lu.%06lu: ", > - secs, usec_rem); > + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { > + t = ns2usecs(iter->ts); > + usec_rem = do_div(t, USEC_PER_SEC); > + secs = (unsigned long)t; > + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); > + } else > + return trace_seq_printf(s, "%12llu: ", iter->ts); > } > > int trace_print_lat_context(struct trace_iterator *iter) > @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) > *next_entry = trace_find_next_entry(iter, NULL, > &next_ts); > unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); > - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); > - unsigned long rel_usecs; > + > > /* Restore the original ent_size */ > iter->ent_size = ent_size; > > if (!next_entry) > next_ts = iter->ts; > - rel_usecs = ns2usecs(next_ts - iter->ts); > > if (verbose) { > char comm[TASK_COMM_LEN]; > > trace_find_cmdline(entry->pid, comm); > > - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" > - " %ld.%03ldms (+%ld.%03ldms): ", comm, > - entry->pid, iter->cpu, entry->flags, > - entry->preempt_count, iter->idx, > - ns2usecs(iter->ts), > - abs_usecs / USEC_PER_MSEC, > - abs_usecs % USEC_PER_MSEC, > - rel_usecs / USEC_PER_MSEC, > - rel_usecs % USEC_PER_MSEC); > + ret = trace_seq_printf( > + s, "%16s %5d %3d %d %08x %08lx ", > + comm, entry->pid, iter->cpu, entry->flags, > + entry->preempt_count, iter->idx); > } else { > ret = lat_print_generic(s, entry, iter->cpu); > - if (ret) > - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); > } > > + if (ret) > + ret = lat_print_timestamp(iter, next_ts); > + > return ret; > } > ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 3:27 ` Steven Rostedt @ 2012-09-25 20:48 ` David Sharp 2012-09-25 20:49 ` [PATCH v4 " David Sharp 0 siblings, 1 reply; 37+ messages in thread From: David Sharp @ 2012-09-25 20:48 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, Masami Hiramatsu On Mon, Sep 24, 2012 at 8:27 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Thu, 2012-09-20 at 15:52 -0700, David Sharp wrote: >> With the addition of the "tsc" clock, formatting timestamps to look like >> fractional seconds is misleading. Mark clocks as either in nanoseconds or >> not, and format non-nanosecond timestamps as decimal integers. > > I got this: > > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3' > /work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3' > > when building for x86_32. > >> + int ret; >> + struct trace_seq *s = &iter->seq; >> + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; >> + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; >> + unsigned long long abs_ts = iter->ts - iter->tr->time_start; >> + unsigned long long rel_ts = next_ts - iter->ts; >> + unsigned long mark_thresh; >> + >> + if (in_ns) { >> + abs_ts = ns2usecs(abs_ts); >> + rel_ts = ns2usecs(rel_ts); >> + mark_thresh = preempt_mark_thresh_us; >> + } else >> + mark_thresh = preempt_mark_thresh_cycles; >> + >> + if (verbose && in_ns) { >> + ret = trace_seq_printf( >> + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", >> + ns2usecs(iter->ts), >> + abs_ts / USEC_PER_MSEC, >> + abs_ts % USEC_PER_MSEC, >> + rel_ts / USEC_PER_MSEC, > > You can't divide 64 bit numbers in the kernel. It breaks on 32bit archs. I didn't realize that. Sorry. Not sure why I changed them to long long in the first place. Although, that does mean that it is currently overflowing every 4.29 seconds. I may as well fix that. > > -- Steve > >> + rel_ts % USEC_PER_MSEC); >> + } else if (verbose && !in_ns) { >> + ret = trace_seq_printf( >> + s, "[%016llx] %lld (+%lld): ", >> + iter->ts, abs_ts, rel_ts); >> + } else { /* !verbose */ >> + ret = trace_seq_printf( >> + s, " %4lld%s%c: ", >> + abs_ts, >> + in_ns ? "us" : "", >> + rel_ts > mark_thresh ? '!' : >> + rel_ts > 1 ? '+' : ' '); >> + } >> + return ret; >> } >> >> 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; >> + unsigned long long t; >> + unsigned long secs, usec_rem; >> char comm[TASK_COMM_LEN]; >> int ret; >> >> @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) >> return 0; >> } >> >> - return trace_seq_printf(s, " %5lu.%06lu: ", >> - secs, usec_rem); >> + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { >> + t = ns2usecs(iter->ts); >> + usec_rem = do_div(t, USEC_PER_SEC); >> + secs = (unsigned long)t; >> + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); >> + } else >> + return trace_seq_printf(s, "%12llu: ", iter->ts); >> } >> >> int trace_print_lat_context(struct trace_iterator *iter) >> @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) >> *next_entry = trace_find_next_entry(iter, NULL, >> &next_ts); >> unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); >> - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); >> - unsigned long rel_usecs; >> + >> >> /* Restore the original ent_size */ >> iter->ent_size = ent_size; >> >> if (!next_entry) >> next_ts = iter->ts; >> - rel_usecs = ns2usecs(next_ts - iter->ts); >> >> if (verbose) { >> char comm[TASK_COMM_LEN]; >> >> trace_find_cmdline(entry->pid, comm); >> >> - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" >> - " %ld.%03ldms (+%ld.%03ldms): ", comm, >> - entry->pid, iter->cpu, entry->flags, >> - entry->preempt_count, iter->idx, >> - ns2usecs(iter->ts), >> - abs_usecs / USEC_PER_MSEC, >> - abs_usecs % USEC_PER_MSEC, >> - rel_usecs / USEC_PER_MSEC, >> - rel_usecs % USEC_PER_MSEC); >> + ret = trace_seq_printf( >> + s, "%16s %5d %3d %d %08x %08lx ", >> + comm, entry->pid, iter->cpu, entry->flags, >> + entry->preempt_count, iter->idx); >> } else { >> ret = lat_print_generic(s, entry, iter->cpu); >> - if (ret) >> - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); >> } >> >> + if (ret) >> + ret = lat_print_timestamp(iter, next_ts); >> + >> return ret; >> } >> > > ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 20:48 ` David Sharp @ 2012-09-25 20:49 ` David Sharp 2012-09-25 21:42 ` Steven Rostedt 0 siblings, 1 reply; 37+ messages in thread From: David Sharp @ 2012-09-25 20:49 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... v2: Move arch-specific bits out of generic code. v4: Fix x86_32 build due to 64-bit division. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- arch/x86/include/asm/trace_clock.h | 2 +- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 15 +++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 84 +++++++++++++++++++++++++----------- 5 files changed, 78 insertions(+), 33 deletions(-) diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 7ee0d8c..45e17f5 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h @@ -9,7 +9,7 @@ extern u64 notrace trace_clock_x86_tsc(void); # define ARCH_TRACE_CLOCKS \ - { trace_clock_x86_tsc, "x86-tsc" }, + { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, #endif diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 4e26df3..3fe4c5b 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,10 +476,11 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, ARCH_TRACE_CLOCKS }; @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..ca640ff 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,59 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + int ret; + struct trace_seq *s = &iter->seq; + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + unsigned long mark_thresh; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + unsigned long abs_msec = abs_ts; + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); + unsigned long rel_msec = rel_ts; + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); + ret = trace_seq_printf( + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", + ns2usecs(iter->ts), + abs_msec, abs_usec, + rel_msec, rel_usec); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +679,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +699,30 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; + /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 20:49 ` [PATCH v4 " David Sharp @ 2012-09-25 21:42 ` Steven Rostedt 2012-09-25 22:29 ` David Sharp 0 siblings, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-25 21:42 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Masami Hiramatsu Sorry, I should have been more picky before. I haven't totally tested this yet. On Tue, 2012-09-25 at 13:49 -0700, David Sharp wrote: > With the addition of the "tsc" clock, formatting timestamps to look like > fractional seconds is misleading. Mark clocks as either in nanoseconds or > not, and format non-nanosecond timestamps as decimal integers. > > Tested: > $ cd /sys/kernel/debug/tracing/ > $ cat trace_clock > [local] global tsc > $ echo sched_switch > set_event > $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled > $ cat trace > <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 > sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 > ... > $ echo 1 > options/latency-format > $ cat trace > <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 > sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 > ... > $ echo tsc > trace_clock > $ cat trace > $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled > $ echo 0 > options/latency-format > $ cat trace > <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 > sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 > ... > echo 1 > options/latency-format > $ cat trace > <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 > sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 > ... > > v2: > Move arch-specific bits out of generic code. > v4: > Fix x86_32 build due to 64-bit division. > > Google-Bug-Id: 6980623 > Signed-off-by: David Sharp <dhsharp@google.com> > Cc: Steven Rostedt <rostedt@goodmis.org> > Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> > --- > arch/x86/include/asm/trace_clock.h | 2 +- > include/linux/ftrace_event.h | 6 +++ > kernel/trace/trace.c | 15 +++++- > kernel/trace/trace.h | 4 -- > kernel/trace/trace_output.c | 84 +++++++++++++++++++++++++----------- > 5 files changed, 78 insertions(+), 33 deletions(-) > > diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h > index 7ee0d8c..45e17f5 100644 > --- a/arch/x86/include/asm/trace_clock.h > +++ b/arch/x86/include/asm/trace_clock.h > @@ -9,7 +9,7 @@ > extern u64 notrace trace_clock_x86_tsc(void); > > # define ARCH_TRACE_CLOCKS \ > - { trace_clock_x86_tsc, "x86-tsc" }, > + { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, > > #endif > > diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h > index 642928c..c760670 100644 > --- a/include/linux/ftrace_event.h > +++ b/include/linux/ftrace_event.h > @@ -86,6 +86,12 @@ struct trace_iterator { > cpumask_var_t started; > }; > > +enum trace_iter_flags { > + TRACE_FILE_LAT_FMT = 1, > + TRACE_FILE_ANNOTATE = 2, > + TRACE_FILE_TIME_IN_NS = 4, > +}; > + > > struct trace_event; > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 4e26df3..3fe4c5b 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -476,10 +476,11 @@ static const char *trace_options[] = { > static struct { > u64 (*func)(void); > const char *name; > + int in_ns; /* is this clock in nanoseconds? */ Add a few tabs between the ns; and /* > } trace_clocks[] = { > - { trace_clock_local, "local" }, > - { trace_clock_global, "global" }, > - { trace_clock_counter, "counter" }, > + { trace_clock_local, "local", 1 }, > + { trace_clock_global, "global", 1 }, > + { trace_clock_counter, "counter", 0 }, > ARCH_TRACE_CLOCKS > }; > > @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) > if (ring_buffer_overruns(iter->tr->buffer)) > iter->iter_flags |= TRACE_FILE_ANNOTATE; > > + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ > + if (trace_clocks[trace_clock_id].in_ns) > + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; > + > /* stop the trace while dumping */ > tracing_stop(); > > @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) > if (trace_flags & TRACE_ITER_LATENCY_FMT) > iter->iter_flags |= TRACE_FILE_LAT_FMT; > > + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ > + if (trace_clocks[trace_clock_id].in_ns) > + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; > + > iter->cpu_file = cpu_file; > iter->tr = &global_trace; > mutex_init(&iter->mutex); > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h > index 55e1f7f..84fefed 100644 > --- a/kernel/trace/trace.h > +++ b/kernel/trace/trace.h > @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); > int register_tracer(struct tracer *type); > void unregister_tracer(struct tracer *type); > int is_tracing_stopped(void); > -enum trace_file_type { > - TRACE_FILE_LAT_FMT = 1, > - TRACE_FILE_ANNOTATE = 2, > -}; > > extern cpumask_var_t __read_mostly tracing_buffer_mask; > > diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c > index 123b189..ca640ff 100644 > --- a/kernel/trace/trace_output.c > +++ b/kernel/trace/trace_output.c > @@ -610,24 +610,59 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) > return trace_print_lat_fmt(s, entry); > } > > -static unsigned long preempt_mark_thresh = 100; > +static unsigned long preempt_mark_thresh_us = 100; > +/* roughly the same at 2.0GHz: */ > +static unsigned long preempt_mark_thresh_cycles = 200000; > > static int > -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, > - unsigned long rel_usecs) > +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) > { > - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, > - rel_usecs > preempt_mark_thresh ? '!' : > - rel_usecs > 1 ? '+' : ' '); > + int ret; > + struct trace_seq *s = &iter->seq; Move the above down below, to give a nicer aesthetic look. > + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; > + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; > + unsigned long long abs_ts = iter->ts - iter->tr->time_start; > + unsigned long long rel_ts = next_ts - iter->ts; struct trace_seq *s = &iter->seq; > + unsigned long mark_thresh; int ret; > + > + if (in_ns) { > + abs_ts = ns2usecs(abs_ts); > + rel_ts = ns2usecs(rel_ts); > + mark_thresh = preempt_mark_thresh_us; > + } else > + mark_thresh = preempt_mark_thresh_cycles; > + > + if (verbose && in_ns) { > + unsigned long abs_msec = abs_ts; > + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); > + unsigned long rel_msec = rel_ts; > + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); Either add a space here, or move the declarations to the top of the function and keep the code part here. > + ret = trace_seq_printf( > + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", > + ns2usecs(iter->ts), > + abs_msec, abs_usec, > + rel_msec, rel_usec); > + } else if (verbose && !in_ns) { > + ret = trace_seq_printf( > + s, "[%016llx] %lld (+%lld): ", > + iter->ts, abs_ts, rel_ts); > + } else { /* !verbose */ > + ret = trace_seq_printf( > + s, " %4lld%s%c: ", > + abs_ts, > + in_ns ? "us" : "", > + rel_ts > mark_thresh ? '!' : > + rel_ts > 1 ? '+' : ' '); > + } > + return ret; > } > > 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; > + unsigned long long t; > + unsigned long secs, usec_rem; > char comm[TASK_COMM_LEN]; > int ret; > > @@ -644,8 +679,13 @@ int trace_print_context(struct trace_iterator *iter) > return 0; > } > > - return trace_seq_printf(s, " %5lu.%06lu: ", > - secs, usec_rem); > + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { > + t = ns2usecs(iter->ts); > + usec_rem = do_div(t, USEC_PER_SEC); > + secs = (unsigned long)t; > + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); > + } else > + return trace_seq_printf(s, "%12llu: ", iter->ts); > } > > int trace_print_lat_context(struct trace_iterator *iter) > @@ -659,36 +699,30 @@ int trace_print_lat_context(struct trace_iterator *iter) > *next_entry = trace_find_next_entry(iter, NULL, > &next_ts); > unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); > - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); > - unsigned long rel_usecs; > + Is this adding an extra newline? -- Steve > > /* Restore the original ent_size */ > iter->ent_size = ent_size; > > if (!next_entry) > next_ts = iter->ts; > - rel_usecs = ns2usecs(next_ts - iter->ts); > > if (verbose) { > char comm[TASK_COMM_LEN]; > > trace_find_cmdline(entry->pid, comm); > > - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" > - " %ld.%03ldms (+%ld.%03ldms): ", comm, > - entry->pid, iter->cpu, entry->flags, > - entry->preempt_count, iter->idx, > - ns2usecs(iter->ts), > - abs_usecs / USEC_PER_MSEC, > - abs_usecs % USEC_PER_MSEC, > - rel_usecs / USEC_PER_MSEC, > - rel_usecs % USEC_PER_MSEC); > + ret = trace_seq_printf( > + s, "%16s %5d %3d %d %08x %08lx ", > + comm, entry->pid, iter->cpu, entry->flags, > + entry->preempt_count, iter->idx); > } else { > ret = lat_print_generic(s, entry, iter->cpu); > - if (ret) > - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); > } > > + if (ret) > + ret = lat_print_timestamp(iter, next_ts); > + > return ret; > } > ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 21:42 ` Steven Rostedt @ 2012-09-25 22:29 ` David Sharp 2012-09-25 22:29 ` David Sharp 2012-09-25 23:36 ` Steven Rostedt 0 siblings, 2 replies; 37+ messages in thread From: David Sharp @ 2012-09-25 22:29 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, Masami Hiramatsu On Tue, Sep 25, 2012 at 2:42 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > Sorry, I should have been more picky before. I haven't totally tested > this yet. > > On Tue, 2012-09-25 at 13:49 -0700, David Sharp wrote: >> With the addition of the "tsc" clock, formatting timestamps to look like >> fractional seconds is misleading. Mark clocks as either in nanoseconds or >> not, and format non-nanosecond timestamps as decimal integers. >> >> Tested: >> $ cd /sys/kernel/debug/tracing/ >> $ cat trace_clock >> [local] global tsc >> $ echo sched_switch > set_event >> $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled >> $ cat trace >> <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 >> sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 >> ... >> $ echo 1 > options/latency-format >> $ cat trace >> <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 >> sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 >> ... >> $ echo tsc > trace_clock >> $ cat trace >> $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled >> $ echo 0 > options/latency-format >> $ cat trace >> <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 >> sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 >> ... >> echo 1 > options/latency-format >> $ cat trace >> <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 >> sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 >> ... >> >> v2: >> Move arch-specific bits out of generic code. >> v4: >> Fix x86_32 build due to 64-bit division. >> >> Google-Bug-Id: 6980623 >> Signed-off-by: David Sharp <dhsharp@google.com> >> Cc: Steven Rostedt <rostedt@goodmis.org> >> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> >> --- >> arch/x86/include/asm/trace_clock.h | 2 +- >> include/linux/ftrace_event.h | 6 +++ >> kernel/trace/trace.c | 15 +++++- >> kernel/trace/trace.h | 4 -- >> kernel/trace/trace_output.c | 84 +++++++++++++++++++++++++----------- >> 5 files changed, 78 insertions(+), 33 deletions(-) >> >> diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h >> index 7ee0d8c..45e17f5 100644 >> --- a/arch/x86/include/asm/trace_clock.h >> +++ b/arch/x86/include/asm/trace_clock.h >> @@ -9,7 +9,7 @@ >> extern u64 notrace trace_clock_x86_tsc(void); >> >> # define ARCH_TRACE_CLOCKS \ >> - { trace_clock_x86_tsc, "x86-tsc" }, >> + { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, >> >> #endif >> >> diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h >> index 642928c..c760670 100644 >> --- a/include/linux/ftrace_event.h >> +++ b/include/linux/ftrace_event.h >> @@ -86,6 +86,12 @@ struct trace_iterator { >> cpumask_var_t started; >> }; >> >> +enum trace_iter_flags { >> + TRACE_FILE_LAT_FMT = 1, >> + TRACE_FILE_ANNOTATE = 2, >> + TRACE_FILE_TIME_IN_NS = 4, >> +}; >> + >> >> struct trace_event; >> >> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c >> index 4e26df3..3fe4c5b 100644 >> --- a/kernel/trace/trace.c >> +++ b/kernel/trace/trace.c >> @@ -476,10 +476,11 @@ static const char *trace_options[] = { >> static struct { >> u64 (*func)(void); >> const char *name; >> + int in_ns; /* is this clock in nanoseconds? */ > > Add a few tabs between the ns; and /* Done. > > >> } trace_clocks[] = { >> - { trace_clock_local, "local" }, >> - { trace_clock_global, "global" }, >> - { trace_clock_counter, "counter" }, >> + { trace_clock_local, "local", 1 }, >> + { trace_clock_global, "global", 1 }, >> + { trace_clock_counter, "counter", 0 }, >> ARCH_TRACE_CLOCKS >> }; >> >> @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) >> if (ring_buffer_overruns(iter->tr->buffer)) >> iter->iter_flags |= TRACE_FILE_ANNOTATE; >> >> + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ >> + if (trace_clocks[trace_clock_id].in_ns) >> + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; >> + >> /* stop the trace while dumping */ >> tracing_stop(); >> >> @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) >> if (trace_flags & TRACE_ITER_LATENCY_FMT) >> iter->iter_flags |= TRACE_FILE_LAT_FMT; >> >> + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ >> + if (trace_clocks[trace_clock_id].in_ns) >> + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; >> + >> iter->cpu_file = cpu_file; >> iter->tr = &global_trace; >> mutex_init(&iter->mutex); >> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h >> index 55e1f7f..84fefed 100644 >> --- a/kernel/trace/trace.h >> +++ b/kernel/trace/trace.h >> @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); >> int register_tracer(struct tracer *type); >> void unregister_tracer(struct tracer *type); >> int is_tracing_stopped(void); >> -enum trace_file_type { >> - TRACE_FILE_LAT_FMT = 1, >> - TRACE_FILE_ANNOTATE = 2, >> -}; >> >> extern cpumask_var_t __read_mostly tracing_buffer_mask; >> >> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c >> index 123b189..ca640ff 100644 >> --- a/kernel/trace/trace_output.c >> +++ b/kernel/trace/trace_output.c >> @@ -610,24 +610,59 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) >> return trace_print_lat_fmt(s, entry); >> } >> >> -static unsigned long preempt_mark_thresh = 100; >> +static unsigned long preempt_mark_thresh_us = 100; >> +/* roughly the same at 2.0GHz: */ >> +static unsigned long preempt_mark_thresh_cycles = 200000; >> >> static int >> -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, >> - unsigned long rel_usecs) >> +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) >> { >> - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, >> - rel_usecs > preempt_mark_thresh ? '!' : >> - rel_usecs > 1 ? '+' : ' '); >> + int ret; >> + struct trace_seq *s = &iter->seq; > > Move the above down below, to give a nicer aesthetic look. Well, that's a matter of opinion... you're the maintainer. :) Done. > >> + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; >> + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; >> + unsigned long long abs_ts = iter->ts - iter->tr->time_start; >> + unsigned long long rel_ts = next_ts - iter->ts; > struct trace_seq *s = &iter->seq; >> + unsigned long mark_thresh; > int ret; > >> + >> + if (in_ns) { >> + abs_ts = ns2usecs(abs_ts); >> + rel_ts = ns2usecs(rel_ts); >> + mark_thresh = preempt_mark_thresh_us; >> + } else >> + mark_thresh = preempt_mark_thresh_cycles; >> + >> + if (verbose && in_ns) { >> + unsigned long abs_msec = abs_ts; >> + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); >> + unsigned long rel_msec = rel_ts; >> + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); > > Either add a space here, or move the declarations to the top of the > function and keep the code part here. Done. > >> + ret = trace_seq_printf( >> + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", >> + ns2usecs(iter->ts), >> + abs_msec, abs_usec, >> + rel_msec, rel_usec); >> + } else if (verbose && !in_ns) { >> + ret = trace_seq_printf( >> + s, "[%016llx] %lld (+%lld): ", >> + iter->ts, abs_ts, rel_ts); >> + } else { /* !verbose */ >> + ret = trace_seq_printf( >> + s, " %4lld%s%c: ", >> + abs_ts, >> + in_ns ? "us" : "", >> + rel_ts > mark_thresh ? '!' : >> + rel_ts > 1 ? '+' : ' '); I just noticed something about this: with x86-tsc clock, this will always print a '+'. Does it matter? Also, is the 200k cycle threshold for '!' okay? I guess the counter clock will always end up with rel_ts == 1, so marks should never appear. >> + } >> + return ret; >> } >> >> 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; >> + unsigned long long t; >> + unsigned long secs, usec_rem; >> char comm[TASK_COMM_LEN]; >> int ret; >> >> @@ -644,8 +679,13 @@ int trace_print_context(struct trace_iterator *iter) >> return 0; >> } >> >> - return trace_seq_printf(s, " %5lu.%06lu: ", >> - secs, usec_rem); >> + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { >> + t = ns2usecs(iter->ts); >> + usec_rem = do_div(t, USEC_PER_SEC); >> + secs = (unsigned long)t; >> + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); >> + } else >> + return trace_seq_printf(s, "%12llu: ", iter->ts); >> } >> >> int trace_print_lat_context(struct trace_iterator *iter) >> @@ -659,36 +699,30 @@ int trace_print_lat_context(struct trace_iterator *iter) >> *next_entry = trace_find_next_entry(iter, NULL, >> &next_ts); >> unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); >> - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); >> - unsigned long rel_usecs; >> + > > Is this adding an extra newline? Yup. Fixed. > > -- Steve > >> >> /* Restore the original ent_size */ >> iter->ent_size = ent_size; >> >> if (!next_entry) >> next_ts = iter->ts; >> - rel_usecs = ns2usecs(next_ts - iter->ts); >> >> if (verbose) { >> char comm[TASK_COMM_LEN]; >> >> trace_find_cmdline(entry->pid, comm); >> >> - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" >> - " %ld.%03ldms (+%ld.%03ldms): ", comm, >> - entry->pid, iter->cpu, entry->flags, >> - entry->preempt_count, iter->idx, >> - ns2usecs(iter->ts), >> - abs_usecs / USEC_PER_MSEC, >> - abs_usecs % USEC_PER_MSEC, >> - rel_usecs / USEC_PER_MSEC, >> - rel_usecs % USEC_PER_MSEC); >> + ret = trace_seq_printf( >> + s, "%16s %5d %3d %d %08x %08lx ", >> + comm, entry->pid, iter->cpu, entry->flags, >> + entry->preempt_count, iter->idx); >> } else { >> ret = lat_print_generic(s, entry, iter->cpu); >> - if (ret) >> - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); >> } >> >> + if (ret) >> + ret = lat_print_timestamp(iter, next_ts); >> + >> return ret; >> } >> > > ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 22:29 ` David Sharp @ 2012-09-25 22:29 ` David Sharp 2012-09-26 18:30 ` Steven Rostedt 2012-09-25 23:36 ` Steven Rostedt 1 sibling, 1 reply; 37+ messages in thread From: David Sharp @ 2012-09-25 22:29 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... v2: Move arch-specific bits out of generic code. v4: Fix x86_32 build due to 64-bit division. Google-Bug-Id: 6980623 Signed-off-by: David Sharp <dhsharp@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> --- arch/x86/include/asm/trace_clock.h | 2 +- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 15 +++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 84 +++++++++++++++++++++++++----------- 5 files changed, 78 insertions(+), 33 deletions(-) diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 7ee0d8c..45e17f5 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h @@ -9,7 +9,7 @@ extern u64 notrace trace_clock_x86_tsc(void); # define ARCH_TRACE_CLOCKS \ - { trace_clock_x86_tsc, "x86-tsc" }, + { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, #endif diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 4e26df3..cff3427 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,10 +476,11 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, ARCH_TRACE_CLOCKS }; @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..a759896 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,60 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + struct trace_seq *s = &iter->seq; + unsigned long mark_thresh; + int ret; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + unsigned long abs_msec = abs_ts; + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); + unsigned long rel_msec = rel_ts; + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); + + ret = trace_seq_printf( + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", + ns2usecs(iter->ts), + abs_msec, abs_usec, + rel_msec, rel_usec); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +680,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +700,29 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 22:29 ` David Sharp @ 2012-09-26 18:30 ` Steven Rostedt 2012-09-26 21:03 ` David Sharp 0 siblings, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-26 18:30 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Masami Hiramatsu On Tue, 2012-09-25 at 15:29 -0700, David Sharp wrote: > static int > -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, > - unsigned long rel_usecs) > +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) > { > - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, > - rel_usecs > preempt_mark_thresh ? '!' : > - rel_usecs > 1 ? '+' : ' '); > + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; > + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; > + unsigned long long abs_ts = iter->ts - iter->tr->time_start; > + unsigned long long rel_ts = next_ts - iter->ts; > + struct trace_seq *s = &iter->seq; > + unsigned long mark_thresh; > + int ret; > + > + if (in_ns) { > + abs_ts = ns2usecs(abs_ts); > + rel_ts = ns2usecs(rel_ts); > + mark_thresh = preempt_mark_thresh_us; > + } else > + mark_thresh = preempt_mark_thresh_cycles; > + > + if (verbose && in_ns) { > + unsigned long abs_msec = abs_ts; > + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); > + unsigned long rel_msec = rel_ts; > + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); > + > + ret = trace_seq_printf( > + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", > + ns2usecs(iter->ts), > + abs_msec, abs_usec, > + rel_msec, rel_usec); > + } else if (verbose && !in_ns) { > + ret = trace_seq_printf( > + s, "[%016llx] %lld (+%lld): ", > + iter->ts, abs_ts, rel_ts); > + } else { /* !verbose */ > + ret = trace_seq_printf( > + s, " %4lld%s%c: ", > + abs_ts, > + in_ns ? "us" : "", > + rel_ts > mark_thresh ? '!' : > + rel_ts > 1 ? '+' : ' '); I still think the annotations are meaningless for counters. Even if the counter is a timer like the tsc, as it does not coincide with real time (us), I say just don't print it for counters. This is not helpful: <idle>-0 0d..1 168+: trace_hardirqs_off_thunk <-apic_timer_interrupt <idle>-0 0d..1 672+: smp_apic_timer_interrupt <-apic_timer_interrupt <idle>-0 0d..1 1224+: irq_enter <-smp_apic_timer_interrupt <idle>-0 0d..1 1720+: rcu_irq_enter <-irq_enter <idle>-0 0d..1 2328+: rcu_idle_exit_common.isra.38 <-rcu_irq_enter <idle>-0 0d..1 3016+: local_bh_disable <-irq_enter <idle>-0 0d..1 3512+: __local_bh_disable <-irq_enter <idle>-0 0d.s1 4120+: tick_check_idle <-irq_enter <idle>-0 0d.s1 4632+: tick_check_oneshot_broadcast <-tick_check_idle <idle>-0 0d.s1 5296+: ktime_get <-tick_check_idle <idle>-0 0d.s1 6104+: tick_nohz_stop_idle <-tick_check_idle <idle>-0 0d.s1 6616+: update_ts_time_stats <-tick_nohz_stop_idle <idle>-0 0d.s1 7144+: nr_iowait_cpu <-update_ts_time_stats <idle>-0 0d.s1 7720+: ktime_get <-sched_clock_tick <idle>-0 0d.s1 8480+: touch_softlockup_watchdog <-tick_check_idle <idle>-0 0d.s1 9120+: tick_do_update_jiffies64 <-tick_check_idle <idle>-0 0d.s1 9648+: _raw_spin_lock <-tick_do_update_jiffies64 > + } > + return ret; > } > > 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; > + unsigned long long t; > + unsigned long secs, usec_rem; > char comm[TASK_COMM_LEN]; > int ret; > > @@ -644,8 +680,13 @@ int trace_print_context(struct trace_iterator *iter) > return 0; > } > > - return trace_seq_printf(s, " %5lu.%06lu: ", > - secs, usec_rem); > + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { > + t = ns2usecs(iter->ts); > + usec_rem = do_div(t, USEC_PER_SEC); > + secs = (unsigned long)t; > + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); You took away the space before %5. > + } else > + return trace_seq_printf(s, "%12llu: ", iter->ts); here too. We end up with this: <idle>-0 [002] d.h11968173392984: _raw_spin_lock_irqsave <-try_to_wake_up <idle>-0 [002] d.h11968173393704: add_preempt_count <-_raw_spin_lock_irqsave <idle>-0 [002] d.h21968173394568: task_waking_fair <-try_to_wake_up <idle>-0 [002] d.h21968173395488: select_task_rq_fair <-select_task_rq <idle>-0 [002] d.h21968173396240: __rcu_read_lock <-select_task_rq_fair <idle>-0 [002] d.h21968173397136: idle_cpu <-select_task_rq_fair <idle>-0 [002] d.h21968173397816: __rcu_read_unlock <-select_task_rq_fair <idle>-0 [002] d.h21968173398608: cpus_share_cache <-try_to_wake_up <idle>-0 [002] d.h21968173399272: _raw_spin_lock <-try_to_wake_up <idle>-0 [002] d.h21968173399888: add_preempt_count <-_raw_spin_lock <idle>-0 [002] d.h31968173400608: ttwu_do_activate.constprop.87 <-try_to_wake_up <idle>-0 [002] d.h31968173401272: activate_task <-ttwu_do_activate.constprop.87 <idle>-0 [002] d.h31968173401912: enqueue_task <-ttwu_do_activate.constprop.87 -- Steve > } > > int trace_print_lat_context(struct trace_iterator *iter) > @@ -659,36 +700,29 @@ int trace_print_lat_context(struct trace_iterator *iter) > *next_entry = trace_find_next_entry(iter, NULL, > &next_ts); > unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); > - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); > - unsigned long rel_usecs; > > /* Restore the original ent_size */ > iter->ent_size = ent_size; > > if (!next_entry) > next_ts = iter->ts; > - rel_usecs = ns2usecs(next_ts - iter->ts); ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-26 18:30 ` Steven Rostedt @ 2012-09-26 21:03 ` David Sharp 0 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-26 21:03 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, Masami Hiramatsu On Wed, Sep 26, 2012 at 11:30 AM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Tue, 2012-09-25 at 15:29 -0700, David Sharp wrote: > >> static int >> -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, >> - unsigned long rel_usecs) >> +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) >> { >> - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, >> - rel_usecs > preempt_mark_thresh ? '!' : >> - rel_usecs > 1 ? '+' : ' '); >> + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; >> + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; >> + unsigned long long abs_ts = iter->ts - iter->tr->time_start; >> + unsigned long long rel_ts = next_ts - iter->ts; >> + struct trace_seq *s = &iter->seq; >> + unsigned long mark_thresh; >> + int ret; >> + >> + if (in_ns) { >> + abs_ts = ns2usecs(abs_ts); >> + rel_ts = ns2usecs(rel_ts); >> + mark_thresh = preempt_mark_thresh_us; >> + } else >> + mark_thresh = preempt_mark_thresh_cycles; >> + >> + if (verbose && in_ns) { >> + unsigned long abs_msec = abs_ts; >> + unsigned long abs_usec = do_div(abs_msec, USEC_PER_MSEC); >> + unsigned long rel_msec = rel_ts; >> + unsigned long rel_usec = do_div(rel_msec, USEC_PER_MSEC); >> + >> + ret = trace_seq_printf( >> + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", >> + ns2usecs(iter->ts), >> + abs_msec, abs_usec, >> + rel_msec, rel_usec); >> + } else if (verbose && !in_ns) { >> + ret = trace_seq_printf( >> + s, "[%016llx] %lld (+%lld): ", >> + iter->ts, abs_ts, rel_ts); >> + } else { /* !verbose */ >> + ret = trace_seq_printf( >> + s, " %4lld%s%c: ", >> + abs_ts, >> + in_ns ? "us" : "", >> + rel_ts > mark_thresh ? '!' : >> + rel_ts > 1 ? '+' : ' '); > > I still think the annotations are meaningless for counters. Even if the > counter is a timer like the tsc, as it does not coincide with real time > (us), I say just don't print it for counters. Sounds fine to me, as that's the easiest modification anyway. Done. > > This is not helpful: > > <snip> Agreed. The other way to fix it would have been to change the "+" threshold from 1 to ~2000. > > >> + } >> + return ret; >> } >> >> 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; >> + unsigned long long t; >> + unsigned long secs, usec_rem; >> char comm[TASK_COMM_LEN]; >> int ret; >> >> @@ -644,8 +680,13 @@ int trace_print_context(struct trace_iterator *iter) >> return 0; >> } >> >> - return trace_seq_printf(s, " %5lu.%06lu: ", >> - secs, usec_rem); >> + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { >> + t = ns2usecs(iter->ts); >> + usec_rem = do_div(t, USEC_PER_SEC); >> + secs = (unsigned long)t; >> + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); > > You took away the space before %5. > >> + } else >> + return trace_seq_printf(s, "%12llu: ", iter->ts); > > here too. Don't know why I would have changed that... Fixed. >> } >> >> int trace_print_lat_context(struct trace_iterator *iter) >> @@ -659,36 +700,29 @@ int trace_print_lat_context(struct trace_iterator *iter) >> *next_entry = trace_find_next_entry(iter, NULL, >> &next_ts); >> unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); >> - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); >> - unsigned long rel_usecs; >> >> /* Restore the original ent_size */ >> iter->ent_size = ent_size; >> >> if (!next_entry) >> next_ts = iter->ts; >> - rel_usecs = ns2usecs(next_ts - iter->ts); > > ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 22:29 ` David Sharp 2012-09-25 22:29 ` David Sharp @ 2012-09-25 23:36 ` Steven Rostedt 2012-09-26 0:32 ` David Sharp 1 sibling, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-25 23:36 UTC (permalink / raw) To: David Sharp; +Cc: linux-kernel, Masami Hiramatsu On Tue, 2012-09-25 at 15:29 -0700, David Sharp wrote: > >> + ret = trace_seq_printf( > >> + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", > >> + ns2usecs(iter->ts), > >> + abs_msec, abs_usec, > >> + rel_msec, rel_usec); > >> + } else if (verbose && !in_ns) { > >> + ret = trace_seq_printf( > >> + s, "[%016llx] %lld (+%lld): ", > >> + iter->ts, abs_ts, rel_ts); > >> + } else { /* !verbose */ > >> + ret = trace_seq_printf( > >> + s, " %4lld%s%c: ", > >> + abs_ts, > >> + in_ns ? "us" : "", > >> + rel_ts > mark_thresh ? '!' : > >> + rel_ts > 1 ? '+' : ' '); > > I just noticed something about this: with x86-tsc clock, this will > always print a '+'. Does it matter? Also, is the 200k cycle threshold > for '!' okay? I guess the counter clock will always end up with rel_ts > == 1, so marks should never appear. > Actually, I'm thinking that counters should not add those annotations. As it just doesn't make sense. -- Steve ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v4 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-25 23:36 ` Steven Rostedt @ 2012-09-26 0:32 ` David Sharp 0 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-26 0:32 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, Masami Hiramatsu On Tue, Sep 25, 2012 at 4:36 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Tue, 2012-09-25 at 15:29 -0700, David Sharp wrote: > > >> >> + ret = trace_seq_printf( >> >> + s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", >> >> + ns2usecs(iter->ts), >> >> + abs_msec, abs_usec, >> >> + rel_msec, rel_usec); >> >> + } else if (verbose && !in_ns) { >> >> + ret = trace_seq_printf( >> >> + s, "[%016llx] %lld (+%lld): ", >> >> + iter->ts, abs_ts, rel_ts); >> >> + } else { /* !verbose */ >> >> + ret = trace_seq_printf( >> >> + s, " %4lld%s%c: ", >> >> + abs_ts, >> >> + in_ns ? "us" : "", >> >> + rel_ts > mark_thresh ? '!' : >> >> + rel_ts > 1 ? '+' : ' '); >> >> I just noticed something about this: with x86-tsc clock, this will >> always print a '+'. Does it matter? Also, is the 200k cycle threshold >> for '!' okay? I guess the counter clock will always end up with rel_ts >> == 1, so marks should never appear. >> > > Actually, I'm thinking that counters should not add those annotations. > As it just doesn't make sense. Right. But they won't appear anyway, since the delta will always be 1. wait, by "counters" are you including TSC? Surely that makes sense, since it is a measurement of time. Eh... sorry I brought it up. I don't really want to change it. I never use the latency tracer, so I mostly just don't want to break it. ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v3 1/3] tracing,x86: add a TSC trace_clock 2012-09-20 22:52 ` [PATCH v3 " David Sharp 2012-09-20 22:52 ` [PATCH v3 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-20 22:52 ` [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp @ 2012-09-29 3:15 ` Steven Rostedt 2012-10-02 0:33 ` David Sharp 2 siblings, 1 reply; 37+ messages in thread From: Steven Rostedt @ 2012-09-29 3:15 UTC (permalink / raw) To: David Sharp Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin On Thu, 2012-09-20 at 15:52 -0700, David Sharp wrote: > diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h > new file mode 100644 > index 0000000..6726f1b > --- /dev/null > +++ b/include/asm-generic/trace_clock.h > @@ -0,0 +1,16 @@ > +#ifndef _ASM_GENERIC_TRACE_CLOCK_H > +#define _ASM_GENERIC_TRACE_CLOCK_H > +/* > + * Arch-specific trace clocks. > + */ > + > +/* > + * Additional trace clocks added to the trace_clocks > + * array in kernel/trace/trace.c > + * None if the architecture has not defined it. > + */ > +#ifndef ARCH_TRACE_CLOCKS > +# define ARCH_TRACE_CLOCKS > +#endif > + > +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ Unfortunately this isn't enough. You need to add a stub in all arch/*/include/asm/ directories. That has: --- trace_clock.h: #ifndef _ASM_TRACE_CLOCK_H #define _ASM_TRACE_CLOCK_H #include <asm-generic/trace_clock.h> #endif --- Because running this against my cross-compile test, failed on all archs but x86. -- Steve ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v3 1/3] tracing,x86: add a TSC trace_clock 2012-09-29 3:15 ` [PATCH v3 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt @ 2012-10-02 0:33 ` David Sharp 2012-10-02 0:43 ` Steven Rostedt 0 siblings, 1 reply; 37+ messages in thread From: David Sharp @ 2012-10-02 0:33 UTC (permalink / raw) To: Steven Rostedt Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin On Fri, Sep 28, 2012 at 8:15 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Thu, 2012-09-20 at 15:52 -0700, David Sharp wrote: > >> diff --git a/include/asm-generic/trace_clock.h b/include/asm-generic/trace_clock.h >> new file mode 100644 >> index 0000000..6726f1b >> --- /dev/null >> +++ b/include/asm-generic/trace_clock.h >> @@ -0,0 +1,16 @@ >> +#ifndef _ASM_GENERIC_TRACE_CLOCK_H >> +#define _ASM_GENERIC_TRACE_CLOCK_H >> +/* >> + * Arch-specific trace clocks. >> + */ >> + >> +/* >> + * Additional trace clocks added to the trace_clocks >> + * array in kernel/trace/trace.c >> + * None if the architecture has not defined it. >> + */ >> +#ifndef ARCH_TRACE_CLOCKS >> +# define ARCH_TRACE_CLOCKS >> +#endif >> + >> +#endif /* _ASM_GENERIC_TRACE_CLOCK_H */ > > Unfortunately this isn't enough. You need to add a stub in all > arch/*/include/asm/ directories. That has: Oh really? Okay. Sorry, I really don't know the mechanics of the arch trees. I'll work on that now, and then send you a new series since I forgot to send out my last update. > > --- trace_clock.h: > #ifndef _ASM_TRACE_CLOCK_H > #define _ASM_TRACE_CLOCK_H > > #include <asm-generic/trace_clock.h> > > #endif > --- > > > Because running this against my cross-compile test, failed on all archs > but x86. > > -- Steve > > ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v3 1/3] tracing,x86: add a TSC trace_clock 2012-10-02 0:33 ` David Sharp @ 2012-10-02 0:43 ` Steven Rostedt 0 siblings, 0 replies; 37+ messages in thread From: Steven Rostedt @ 2012-10-02 0:43 UTC (permalink / raw) To: David Sharp Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin On Mon, 2012-10-01 at 17:33 -0700, David Sharp wrote: > > Unfortunately this isn't enough. You need to add a stub in all > > arch/*/include/asm/ directories. That has: > > Oh really? Okay. Sorry, I really don't know the mechanics of the arch > trees. I'll work on that now, and then send you a new series since I > forgot to send out my last update. It's a good idea to cross compile archs, especially if you make any change that affects archs (like this one did). Just use ktest.pl. You can download the cross tools at: http://kernel.org/pub/tools/crosstool/files/bin/x86_64/ And you can use the example config file in: tools/testing/ktest/examples/crosstests.conf That's basically the test I use to test cross compiling of other archs. -- Steve ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-20 8:55 ` Ingo Molnar 2012-09-20 13:34 ` Steven Rostedt @ 2012-09-20 22:53 ` David Sharp 1 sibling, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-20 22:53 UTC (permalink / raw) To: Ingo Molnar Cc: linux-kernel, Steven Rostedt, Masami Hiramatsu, Thomas Gleixner, H. Peter Anvin On Thu, Sep 20, 2012 at 1:55 AM, Ingo Molnar <mingo@kernel.org> wrote: > Looks useful and good otherwise: > > Acked-by: Ingo Molnar <mingo@kernel.org> Thanks! Updated with all your comments. ^ permalink raw reply [flat|nested] 37+ messages in thread
* Re: [PATCH v2 1/3] tracing,x86: add a TSC trace_clock 2012-09-13 1:23 ` Steven Rostedt 2012-09-18 21:37 ` David Sharp @ 2012-09-18 21:46 ` David Sharp 1 sibling, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-18 21:46 UTC (permalink / raw) To: Steven Rostedt Cc: linux-kernel, Masami Hiramatsu, Ingo Molnar, Thomas Gleixner, H. Peter Anvin On Wed, Sep 12, 2012 at 6:23 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > This change will require an ack from one of the x86 maintainers. > > For reference to this patch, please see this thread: > > https://lkml.org/lkml/2012/9/11/572 > > On Wed, 2012-09-12 at 16:31 -0700, David Sharp wrote: >> In order to promote interoperability between userspace tracers and ftrace, >> add a trace_clock that reports raw TSC values which will then be recorded >> in the ring buffer. Userspace tracers that also record TSCs are then on >> exactly the same time base as the kernel and events can be unambiguously >> interlaced. >> >> Tested: Enabled a tracepoint and the "tsc" trace_clock and saw very large >> timestamp values. >> >> v2: >> Move arch-specific bits out of generic code. > > As Masami pointed out, please add a SOB to your patches. Sorry about that. I guess that's what happens when I rush before going on vacation. Apparently I did `git format-patch --signoff` the first time instead of in the commit. ^ permalink raw reply [flat|nested] 37+ messages in thread
* [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp 2012-09-12 23:31 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp 2012-09-12 23:31 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock David Sharp @ 2012-09-12 23:31 ` David Sharp 2012-09-12 23:32 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 23:31 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu Because the "tsc" clock isn't in nanoseconds, the ring buffer must be reset when changing clocks so that incomparable timestamps don't end up in the same trace. Tested: Confirmed switching clocks resets the trace buffer. --- kernel/trace/trace.c | 8 ++++++++ 1 files changed, 8 insertions(+), 0 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 92fb08e..4e26df3 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4012,6 +4012,14 @@ static ssize_t tracing_clock_write(struct file *filp, const char __user *ubuf, if (max_tr.buffer) ring_buffer_set_clock(max_tr.buffer, trace_clocks[i].func); + /* + * New clock may not be consistent with the previous clock. + * Reset the buffer so that it doesn't have incomparable timestamps. + */ + tracing_reset_online_cpus(&global_trace); + if (max_tr.buffer) + tracing_reset_online_cpus(&max_tr); + mutex_unlock(&trace_types_lock); *fpos += cnt; -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
* [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point. 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp ` (2 preceding siblings ...) 2012-09-12 23:31 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp @ 2012-09-12 23:32 ` David Sharp 3 siblings, 0 replies; 37+ messages in thread From: David Sharp @ 2012-09-12 23:32 UTC (permalink / raw) To: linux-kernel; +Cc: David Sharp, Steven Rostedt, Masami Hiramatsu With the addition of the "tsc" clock, formatting timestamps to look like fractional seconds is misleading. Mark clocks as either in nanoseconds or not, and format non-nanosecond timestamps as decimal integers. Tested: $ cd /sys/kernel/debug/tracing/ $ cat trace_clock [local] global tsc $ echo sched_switch > set_event $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ cat trace <idle>-0 [000] 6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 [000] 6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo 1 > options/latency-format $ cat trace <idle>-0 0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120 sleep-29964 0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... $ echo tsc > trace_clock $ cat trace $ echo 1 > tracing_enabled ; sleep 0.0005 ; echo 0 > tracing_enabled $ echo 0 > options/latency-format $ cat trace <idle>-0 [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... echo 1 > options/latency-format $ cat trace <idle>-0 0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120 sleep-31128 0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120 ... v2: Move arch-specific bits out of generic code. Google-Bug-Id: 6980623 --- arch/x86/include/asm/trace_clock.h | 2 +- include/linux/ftrace_event.h | 6 +++ kernel/trace/trace.c | 15 +++++- kernel/trace/trace.h | 4 -- kernel/trace/trace_output.c | 82 +++++++++++++++++++++++++----------- 5 files changed, 76 insertions(+), 33 deletions(-) diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 0b1f391..4af2eb7 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h @@ -9,7 +9,7 @@ extern u64 notrace trace_clock_x86_tsc(void); # define ARCH_TRACE_CLOCKS \ - { trace_clock_x86_tsc, "tsc" }, + { trace_clock_x86_tsc, "tsc", .in_ns = 0 }, #endif diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index 642928c..c760670 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h @@ -86,6 +86,12 @@ struct trace_iterator { cpumask_var_t started; }; +enum trace_iter_flags { + TRACE_FILE_LAT_FMT = 1, + TRACE_FILE_ANNOTATE = 2, + TRACE_FILE_TIME_IN_NS = 4, +}; + struct trace_event; diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 4e26df3..3fe4c5b 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -476,10 +476,11 @@ static const char *trace_options[] = { static struct { u64 (*func)(void); const char *name; + int in_ns; /* is this clock in nanoseconds? */ } trace_clocks[] = { - { trace_clock_local, "local" }, - { trace_clock_global, "global" }, - { trace_clock_counter, "counter" }, + { trace_clock_local, "local", 1 }, + { trace_clock_global, "global", 1 }, + { trace_clock_counter, "counter", 0 }, ARCH_TRACE_CLOCKS }; @@ -2425,6 +2426,10 @@ __tracing_open(struct inode *inode, struct file *file) if (ring_buffer_overruns(iter->tr->buffer)) iter->iter_flags |= TRACE_FILE_ANNOTATE; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + /* stop the trace while dumping */ tracing_stop(); @@ -3324,6 +3329,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) if (trace_flags & TRACE_ITER_LATENCY_FMT) iter->iter_flags |= TRACE_FILE_LAT_FMT; + /* Output in nanoseconds only if we are using a clock in nanoseconds. */ + if (trace_clocks[trace_clock_id].in_ns) + iter->iter_flags |= TRACE_FILE_TIME_IN_NS; + iter->cpu_file = cpu_file; iter->tr = &global_trace; mutex_init(&iter->mutex); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55e1f7f..84fefed 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -409,10 +409,6 @@ void tracing_start_sched_switch_record(void); int register_tracer(struct tracer *type); void unregister_tracer(struct tracer *type); int is_tracing_stopped(void); -enum trace_file_type { - TRACE_FILE_LAT_FMT = 1, - TRACE_FILE_ANNOTATE = 2, -}; extern cpumask_var_t __read_mostly tracing_buffer_mask; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189..c86d62a 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -610,24 +610,57 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) return trace_print_lat_fmt(s, entry); } -static unsigned long preempt_mark_thresh = 100; +static unsigned long preempt_mark_thresh_us = 100; +/* roughly the same at 2.0GHz: */ +static unsigned long preempt_mark_thresh_cycles = 200000; static int -lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, - unsigned long rel_usecs) +lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) { - return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, - rel_usecs > preempt_mark_thresh ? '!' : - rel_usecs > 1 ? '+' : ' '); + int ret; + struct trace_seq *s = &iter->seq; + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; + unsigned long long abs_ts = iter->ts - iter->tr->time_start; + unsigned long long rel_ts = next_ts - iter->ts; + unsigned long mark_thresh; + + if (in_ns) { + abs_ts = ns2usecs(abs_ts); + rel_ts = ns2usecs(rel_ts); + mark_thresh = preempt_mark_thresh_us; + } else + mark_thresh = preempt_mark_thresh_cycles; + + if (verbose && in_ns) { + ret = trace_seq_printf( + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ", + ns2usecs(iter->ts), + abs_ts / USEC_PER_MSEC, + abs_ts % USEC_PER_MSEC, + rel_ts / USEC_PER_MSEC, + rel_ts % USEC_PER_MSEC); + } else if (verbose && !in_ns) { + ret = trace_seq_printf( + s, "[%016llx] %lld (+%lld): ", + iter->ts, abs_ts, rel_ts); + } else { /* !verbose */ + ret = trace_seq_printf( + s, " %4lld%s%c: ", + abs_ts, + in_ns ? "us" : "", + rel_ts > mark_thresh ? '!' : + rel_ts > 1 ? '+' : ' '); + } + return ret; } 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; + unsigned long long t; + unsigned long secs, usec_rem; char comm[TASK_COMM_LEN]; int ret; @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter) return 0; } - return trace_seq_printf(s, " %5lu.%06lu: ", - secs, usec_rem); + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { + t = ns2usecs(iter->ts); + usec_rem = do_div(t, USEC_PER_SEC); + secs = (unsigned long)t; + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem); + } else + return trace_seq_printf(s, "%12llu: ", iter->ts); } int trace_print_lat_context(struct trace_iterator *iter) @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter) *next_entry = trace_find_next_entry(iter, NULL, &next_ts); unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); - unsigned long rel_usecs; + /* Restore the original ent_size */ iter->ent_size = ent_size; if (!next_entry) next_ts = iter->ts; - rel_usecs = ns2usecs(next_ts - iter->ts); if (verbose) { char comm[TASK_COMM_LEN]; trace_find_cmdline(entry->pid, comm); - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" - " %ld.%03ldms (+%ld.%03ldms): ", comm, - entry->pid, iter->cpu, entry->flags, - entry->preempt_count, iter->idx, - ns2usecs(iter->ts), - abs_usecs / USEC_PER_MSEC, - abs_usecs % USEC_PER_MSEC, - rel_usecs / USEC_PER_MSEC, - rel_usecs % USEC_PER_MSEC); + ret = trace_seq_printf( + s, "%16s %5d %3d %d %08x %08lx ", + comm, entry->pid, iter->cpu, entry->flags, + entry->preempt_count, iter->idx); } else { ret = lat_print_generic(s, entry, iter->cpu); - if (ret) - ret = lat_print_timestamp(s, abs_usecs, rel_usecs); } + if (ret) + ret = lat_print_timestamp(iter, next_ts); + return ret; } -- 1.7.7.3 ^ permalink raw reply related [flat|nested] 37+ messages in thread
end of thread, other threads:[~2012-10-02 0:43 UTC | newest] Thread overview: 37+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2012-09-12 2:41 [PATCH 0/3] TSC trace_clock David Sharp 2012-09-12 2:41 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp 2012-09-12 3:48 ` Steven Rostedt 2012-09-12 18:48 ` David Sharp 2012-09-12 2:41 ` [PATCH 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-12 2:41 ` [PATCH 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 2012-09-12 23:31 ` [PATCH v2 0/3] TSC trace_clock David Sharp 2012-09-12 23:31 ` [PATCH 1/3] tracing,x86: add a TSC trace_clock; reset buffer on clock change David Sharp 2012-09-12 23:31 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock David Sharp 2012-09-13 1:15 ` Masami Hiramatsu 2012-09-13 1:23 ` Steven Rostedt 2012-09-18 21:37 ` David Sharp 2012-09-18 21:37 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-18 21:37 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 2012-09-19 2:10 ` [PATCH v2 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt 2012-09-20 8:55 ` Ingo Molnar 2012-09-20 13:34 ` Steven Rostedt 2012-09-20 22:52 ` [PATCH v3 " David Sharp 2012-09-20 22:52 ` [PATCH v3 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-20 22:52 ` [PATCH v3 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp 2012-09-25 3:27 ` Steven Rostedt 2012-09-25 20:48 ` David Sharp 2012-09-25 20:49 ` [PATCH v4 " David Sharp 2012-09-25 21:42 ` Steven Rostedt 2012-09-25 22:29 ` David Sharp 2012-09-25 22:29 ` David Sharp 2012-09-26 18:30 ` Steven Rostedt 2012-09-26 21:03 ` David Sharp 2012-09-25 23:36 ` Steven Rostedt 2012-09-26 0:32 ` David Sharp 2012-09-29 3:15 ` [PATCH v3 1/3] tracing,x86: add a TSC trace_clock Steven Rostedt 2012-10-02 0:33 ` David Sharp 2012-10-02 0:43 ` Steven Rostedt 2012-09-20 22:53 ` [PATCH v2 " David Sharp 2012-09-18 21:46 ` David Sharp 2012-09-12 23:31 ` [PATCH v2 2/3] tracing: reset ring buffer when changing trace_clocks David Sharp 2012-09-12 23:32 ` [PATCH v2 3/3] tracing: format non-nanosec times from tsc clock without a decimal point David Sharp
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).