tracing,x86: Add a TSC trace_clock
Subsystems (19)
PATCH v9 1/3 tracing,x86: Add a TSC trace_clock
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
v7:
Generic arch bits in Kbuild.
Google-Bug-Id: 6980623
--- arch/alpha/include/asm/Kbuild | 1 + arch/arm/include/asm/Kbuild | 1 + arch/arm64/include/asm/Kbuild | 1 + arch/avr32/include/asm/Kbuild | 1 + arch/blackfin/include/asm/Kbuild | 1 + arch/c6x/include/asm/Kbuild | 1 + arch/cris/include/asm/Kbuild | 1 + arch/frv/include/asm/Kbuild | 1 + arch/h8300/include/asm/Kbuild | 1 + arch/hexagon/include/asm/Kbuild | 1 + arch/ia64/include/asm/Kbuild | 1 + arch/m32r/include/asm/Kbuild | 1 + arch/m68k/include/asm/Kbuild | 1 + arch/microblaze/include/asm/Kbuild | 1 + arch/mips/include/asm/Kbuild | 1 + arch/mn10300/include/asm/Kbuild | 1 + arch/openrisc/include/asm/Kbuild | 1 + arch/parisc/include/asm/Kbuild | 1 + arch/powerpc/include/asm/Kbuild | 1 + arch/s390/include/asm/Kbuild | 1 + arch/score/include/asm/Kbuild | 1 + arch/sh/include/asm/Kbuild | 1 + arch/sparc/include/asm/Kbuild | 1 + arch/tile/include/asm/Kbuild | 1 + arch/um/include/asm/Kbuild | 1 + arch/unicore32/include/asm/Kbuild | 1 + arch/x86/include/asm/trace_clock.h | 20 ++++++++++++++++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 21 +++++++++++++++++++++ arch/xtensa/include/asm/Kbuild | 1 + include/asm-generic/trace_clock.h | 16 ++++++++++++++++ include/linux/trace_clock.h | 2 ++ kernel/trace/trace.c | 1 + 33 files changed, 88 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
arch/alpha/include/asm/Kbuild +1 -0
@@ -11,3 +11,4 @@ header-y += reg.h header-y += regdef.h header-y += sysinfo.h generic-y += exec.h +generic-y += trace_clock.h
arch/arm/include/asm/Kbuild +1 -0
@@ -31,5 +31,6 @@ generic-y += sockios.h generic-y += termbits.h generic-y += termios.h generic-y += timex.h +generic-y += trace_clock.h generic-y += types.h generic-y += unaligned.h
arch/arm64/include/asm/Kbuild +1 -0
@@ -43,6 +43,7 @@ generic-y += swab.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += unaligned.h generic-y += user.h
arch/avr32/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/blackfin/include/asm/Kbuild +1 -0
@@ -38,6 +38,7 @@ generic-y += statfs.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/c6x/include/asm/Kbuild +1 -0
@@ -49,6 +49,7 @@ generic-y += termbits.h generic-y += termios.h generic-y += tlbflush.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += user.h
arch/cris/include/asm/Kbuild +1 -0
@@ -11,3 +11,4 @@ header-y += sync_serial.h generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/frv/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/h8300/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/hexagon/include/asm/Kbuild +1 -0
@@ -48,6 +48,7 @@ generic-y += stat.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/ia64/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += clkdev.h generic-y += exec.h generic-y += kvm_para.h +generic-y += trace_clock.h
arch/m32r/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/m68k/include/asm/Kbuild +1 -0
@@ -24,6 +24,7 @@ generic-y += sections.h generic-y += siginfo.h generic-y += statfs.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += word-at-a-time.h generic-y += xor.h
arch/microblaze/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm header-y += elf.h generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/mips/include/asm/Kbuild +1 -0
@@ -1 +1,2 @@ # MIPS headers +generic-y += trace_clock.h
arch/mn10300/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/openrisc/include/asm/Kbuild +1 -0
@@ -60,6 +60,7 @@ generic-y += swab.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += user.h
arch/parisc/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ generic-y += word-at-a-time.h auxvec.h user.h cputime.h emergency-restart.h \ segment.h topology.h vga.h device.h percpu.h hw_irq.h mutex.h \ div64.h irq_regs.h kdebug.h kvm_para.h local64.h local.h param.h \ poll.h xor.h clkdev.h exec.h +generic-y += trace_clock.h
arch/powerpc/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += clkdev.h generic-y += rwsem.h +generic-y += trace_clock.h
arch/s390/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h +generic-y += trace_clock.h
arch/score/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm header-y += generic-y += clkdev.h +generic-y += trace_clock.h
arch/sh/include/asm/Kbuild +1 -0
@@ -31,5 +31,6 @@ generic-y += socket.h generic-y += statfs.h generic-y += termbits.h generic-y += termios.h +generic-y += trace_clock.h generic-y += ucontext.h generic-y += xor.h
arch/sparc/include/asm/Kbuild +1 -0
@@ -8,4 +8,5 @@ generic-y += local64.h generic-y += irq_regs.h generic-y += local.h generic-y += module.h +generic-y += trace_clock.h generic-y += word-at-a-time.h
arch/tile/include/asm/Kbuild +1 -0
@@ -34,5 +34,6 @@ generic-y += sockios.h generic-y += statfs.h generic-y += termbits.h generic-y += termios.h +generic-y += trace_clock.h generic-y += types.h generic-y += xor.h
arch/um/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += bug.h cputime.h device.h emergency-restart.h futex.h hardirq.h generic-y += hw_irq.h irq_regs.h kdebug.h percpu.h sections.h topology.h xor.h generic-y += ftrace.h pci.h io.h param.h delay.h mutex.h current.h exec.h generic-y += switch_to.h clkdev.h +generic-y += trace_clock.h
arch/unicore32/include/asm/Kbuild +1 -0
@@ -54,6 +54,7 @@ generic-y += syscalls.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/x86/include/asm/trace_clock.h new file +20 -0
@@ -0,0 +1,20 @@ +#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" }, + +#else /* !CONFIG_X86_TSC */ + +#define ARCH_TRACE_CLOCKS + +#endif + +#endif /* _ASM_X86_TRACE_CLOCK_H */
arch/x86/kernel/Makefile +1 -0
@@ -61,6 +61,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
arch/x86/kernel/trace_clock.c new file +21 -0
@@ -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; +}
arch/xtensa/include/asm/Kbuild +1 -0
@@ -25,4 +25,5 @@ generic-y += siginfo.h generic-y += statfs.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += xor.h
include/asm-generic/trace_clock.h new file +16 -0
@@ -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 */
include/linux/trace_clock.h +2 -0
@@ -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);
kernel/trace/trace.c +1 -0
@@ -488,6 +488,7 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, + ARCH_TRACE_CLOCKS };int trace_clock_id;
Signature · 1 line
1.7.7.3
PATCH v9 2/3 tracing: Format non-nanosec times from tsc clock without a decimal point.
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_on ; sleep 0.0005 ; echo 0 > tracing_on
$ 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_on ; sleep 0.0005 ; echo 0 > tracing_on
$ 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
--- 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 | 78 ++++++++++++++++++++++++----------- 5 files changed, 72 insertions(+), 33 deletions(-)
arch/x86/include/asm/trace_clock.h +1 -1
@@ -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 },#else /* !CONFIG_X86_TSC */
include/linux/ftrace_event.h +6 -0
@@ -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 ;
kernel/trace/trace.c +12 -3
@@ -484,10 +484,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 };
@@ -2478,6 +2479,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 ();
@@ -3339,6 +3344,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);
kernel/trace/trace.h +0 -4
@@ -406,10 +406,6 @@ void tracing_stop_sched_switch_record(void);void tracing_start_sched_switch_record (void );int register_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;
kernel/trace/trace_output.c +53 -25
121 lines not on this page · raw message
Signature · 1 line
1.7.7.3
[tip:perf/core] tracing: Format non-nanosec times from tsc clock without a decimal point.
Commit-ID: 8be0709f10e3dd5d7d07933ad61a9f18c4b93ca5 Gitweb: http://git.kernel.org/tip/8be0709f10e3dd5d7d07933ad61a9f18c4b93ca5 Author: David Sharp <[email protected]> AuthorDate: Tue, 13 Nov 2012 12:18:22 -0800 Committer: Steven Rostedt <[email protected]> CommitDate: Tue, 13 Nov 2012 15:48:40 -0500
tracing: Format non-nanosec times from tsc clock without a decimal point.
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_on ; sleep 0.0005 ; echo 0 > tracing_on
$ 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_on ; sleep 0.0005 ; echo 0 > tracing_on
$ 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
--- 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 | 78 ++++++++++++++++++++++++++------------ 5 files changed, 72 insertions(+), 33 deletions(-)
arch/x86/include/asm/trace_clock.h +1 -1
@@ -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 },#else /* !CONFIG_X86_TSC */
include/linux/ftrace_event.h +6 -0
@@ -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 ;
kernel/trace/trace.c +12 -3
@@ -484,10 +484,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 };
@@ -2478,6 +2479,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 ();
@@ -3339,6 +3344,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);
kernel/trace/trace.h +0 -4
@@ -406,10 +406,6 @@ void tracing_stop_sched_switch_record(void);void tracing_start_sched_switch_record (void );int register_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;
kernel/trace/trace_output.c +53 -25
121 lines not on this page · raw message
PATCH v9 3/3 ftrace: Show raw time stamp on stats per cpu using counter or tsc mode for trace_clock
In reply to David SharpFrom: Yoshihiro YUNOMAE <[email protected]>
Show raw time stamp values for stats per cpu if you choose counter or tsc mode for trace_clock. Although a unit of tracing time stamp is nsec in local or global mode, the units in counter and TSC mode are tracing counter and cycles respectively.
--- kernel/trace/trace.c | 23 +++++++++++++++++------ 1 files changed, 17 insertions(+), 6 deletions(-)
kernel/trace/trace.c +17 -6
@@ -4388,13 +4388,24 @@ tracing_stats_read(struct file *filp, char __user *ubuf, cnt =ring_buffer_bytes_cpu (tr->buffer, cpu);trace_seq_printf (s,"bytes: %ld\n" , cnt); - t =ns2usecs (ring_buffer_oldest_event_ts (tr->buffer, cpu)); - usec_rem =do_div (t,USEC_PER_SEC ); -trace_seq_printf (s,"oldest event ts: %5llu.%06lu\n" , t, usec_rem); +if (trace_clocks[trace_clock_id].in_ns) { +/* local or global for trace_clock */ + t =ns2usecs (ring_buffer_oldest_event_ts (tr->buffer, cpu)); + usec_rem =do_div (t,USEC_PER_SEC ); +trace_seq_printf (s,"oldest event ts: %5llu.%06lu\n" , + t, usec_rem); + + t =ns2usecs (ring_buffer_time_stamp (tr->buffer, cpu)); + usec_rem =do_div (t,USEC_PER_SEC ); +trace_seq_printf (s,"now ts: %5llu.%06lu\n" , t, usec_rem); + }else { +/* counter or tsc mode for trace_clock */ +trace_seq_printf (s,"oldest event ts: %llu\n" , +ring_buffer_oldest_event_ts (tr->buffer, cpu)); - t =ns2usecs (ring_buffer_time_stamp (tr->buffer, cpu)); - usec_rem =do_div (t,USEC_PER_SEC ); -trace_seq_printf (s,"now ts: %5llu.%06lu\n" , t, usec_rem); +trace_seq_printf (s,"now ts: %llu\n" , +ring_buffer_time_stamp (tr->buffer, cpu)); + } cnt =ring_buffer_dropped_events_cpu (tr->buffer, cpu);trace_seq_printf (s,"dropped events: %ld\n" , cnt);
Signature · 1 line
1.7.7.3
[tip:perf/core] tracing: Show raw time stamp on stats per cpu using counter or tsc mode for trace_clock
Commit-ID: 11043d8b125671a32253cddb0b05177be0e976f6 Gitweb: http://git.kernel.org/tip/11043d8b125671a32253cddb0b05177be0e976f6 Author: Yoshihiro YUNOMAE <[email protected]> AuthorDate: Tue, 13 Nov 2012 12:18:23 -0800 Committer: Steven Rostedt <[email protected]> CommitDate: Tue, 13 Nov 2012 15:49:11 -0500
tracing: Show raw time stamp on stats per cpu using counter or tsc mode for trace_clock
Show raw time stamp values for stats per cpu if you choose counter or tsc mode for trace_clock. Although a unit of tracing time stamp is nsec in local or global mode, the units in counter and TSC mode are tracing counter and cycles respectively.
--- kernel/trace/trace.c | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-)
kernel/trace/trace.c +17 -6
@@ -4388,13 +4388,24 @@ tracing_stats_read(struct file *filp, char __user *ubuf, cnt =ring_buffer_bytes_cpu (tr->buffer, cpu);trace_seq_printf (s,"bytes: %ld\n" , cnt); - t =ns2usecs (ring_buffer_oldest_event_ts (tr->buffer, cpu)); - usec_rem =do_div (t,USEC_PER_SEC ); -trace_seq_printf (s,"oldest event ts: %5llu.%06lu\n" , t, usec_rem); +if (trace_clocks[trace_clock_id].in_ns) { +/* local or global for trace_clock */ + t =ns2usecs (ring_buffer_oldest_event_ts (tr->buffer, cpu)); + usec_rem =do_div (t,USEC_PER_SEC ); +trace_seq_printf (s,"oldest event ts: %5llu.%06lu\n" , + t, usec_rem); + + t =ns2usecs (ring_buffer_time_stamp (tr->buffer, cpu)); + usec_rem =do_div (t,USEC_PER_SEC ); +trace_seq_printf (s,"now ts: %5llu.%06lu\n" , t, usec_rem); + }else { +/* counter or tsc mode for trace_clock */ +trace_seq_printf (s,"oldest event ts: %llu\n" , +ring_buffer_oldest_event_ts (tr->buffer, cpu)); - t =ns2usecs (ring_buffer_time_stamp (tr->buffer, cpu)); - usec_rem =do_div (t,USEC_PER_SEC ); -trace_seq_printf (s,"now ts: %5llu.%06lu\n" , t, usec_rem); +trace_seq_printf (s,"now ts: %llu\n" , +ring_buffer_time_stamp (tr->buffer, cpu)); + } cnt =ring_buffer_dropped_events_cpu (tr->buffer, cpu);trace_seq_printf (s,"dropped events: %ld\n" , cnt);
Commit-ID: 8cbd9cc6254065c97c4bac42daa55ba1abe73a8e Gitweb: http://git.kernel.org/tip/8cbd9cc6254065c97c4bac42daa55ba1abe73a8e Author: David Sharp <[email protected]> AuthorDate: Tue, 13 Nov 2012 12:18:21 -0800 Committer: Steven Rostedt <[email protected]> CommitDate: Tue, 13 Nov 2012 15:48:27 -0500
tracing,x86: Add a TSC trace_clock
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
v7:
Generic arch bits in Kbuild.
Google-Bug-Id: 6980623
--- arch/alpha/include/asm/Kbuild | 1 + arch/arm/include/asm/Kbuild | 1 + arch/arm64/include/asm/Kbuild | 1 + arch/avr32/include/asm/Kbuild | 1 + arch/blackfin/include/asm/Kbuild | 1 + arch/c6x/include/asm/Kbuild | 1 + arch/cris/include/asm/Kbuild | 1 + arch/frv/include/asm/Kbuild | 1 + arch/h8300/include/asm/Kbuild | 1 + arch/hexagon/include/asm/Kbuild | 1 + arch/ia64/include/asm/Kbuild | 1 + arch/m32r/include/asm/Kbuild | 1 + arch/m68k/include/asm/Kbuild | 1 + arch/microblaze/include/asm/Kbuild | 1 + arch/mips/include/asm/Kbuild | 1 + arch/mn10300/include/asm/Kbuild | 1 + arch/openrisc/include/asm/Kbuild | 1 + arch/parisc/include/asm/Kbuild | 1 + arch/powerpc/include/asm/Kbuild | 1 + arch/s390/include/asm/Kbuild | 1 + arch/score/include/asm/Kbuild | 1 + arch/sh/include/asm/Kbuild | 1 + arch/sparc/include/asm/Kbuild | 1 + arch/tile/include/asm/Kbuild | 1 + arch/um/include/asm/Kbuild | 1 + arch/unicore32/include/asm/Kbuild | 1 + arch/x86/include/asm/trace_clock.h | 20 ++++++++++++++++++++ arch/x86/kernel/Makefile | 1 + arch/x86/kernel/trace_clock.c | 21 +++++++++++++++++++++ arch/xtensa/include/asm/Kbuild | 1 + include/asm-generic/trace_clock.h | 16 ++++++++++++++++ include/linux/trace_clock.h | 2 ++ kernel/trace/trace.c | 1 + 33 files changed, 88 insertions(+)
arch/alpha/include/asm/Kbuild +1 -0
@@ -11,3 +11,4 @@ header-y += reg.h header-y += regdef.h header-y += sysinfo.h generic-y += exec.h +generic-y += trace_clock.h
arch/arm/include/asm/Kbuild +1 -0
@@ -31,5 +31,6 @@ generic-y += sockios.h generic-y += termbits.h generic-y += termios.h generic-y += timex.h +generic-y += trace_clock.h generic-y += types.h generic-y += unaligned.h
arch/arm64/include/asm/Kbuild +1 -0
@@ -43,6 +43,7 @@ generic-y += swab.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += unaligned.h generic-y += user.h
arch/avr32/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/blackfin/include/asm/Kbuild +1 -0
@@ -38,6 +38,7 @@ generic-y += statfs.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/c6x/include/asm/Kbuild +1 -0
@@ -49,6 +49,7 @@ generic-y += termbits.h generic-y += termios.h generic-y += tlbflush.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += user.h
arch/cris/include/asm/Kbuild +1 -0
@@ -11,3 +11,4 @@ header-y += sync_serial.h generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/frv/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/h8300/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/hexagon/include/asm/Kbuild +1 -0
@@ -48,6 +48,7 @@ generic-y += stat.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/ia64/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += clkdev.h generic-y += exec.h generic-y += kvm_para.h +generic-y += trace_clock.h
arch/m32r/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm generic-y += clkdev.h generic-y += exec.h generic-y += module.h +generic-y += trace_clock.h
arch/m68k/include/asm/Kbuild +1 -0
@@ -24,6 +24,7 @@ generic-y += sections.h generic-y += siginfo.h generic-y += statfs.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += word-at-a-time.h generic-y += xor.h
arch/microblaze/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm header-y += elf.h generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/mips/include/asm/Kbuild +1 -0
@@ -1 +1,2 @@ # MIPS headers +generic-y += trace_clock.h
arch/mn10300/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h generic-y += exec.h +generic-y += trace_clock.h
arch/openrisc/include/asm/Kbuild +1 -0
@@ -60,6 +60,7 @@ generic-y += swab.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += user.h
arch/parisc/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ generic-y += word-at-a-time.h auxvec.h user.h cputime.h emergency-restart.h \ segment.h topology.h vga.h device.h percpu.h hw_irq.h mutex.h \ div64.h irq_regs.h kdebug.h kvm_para.h local64.h local.h param.h \ poll.h xor.h clkdev.h exec.h +generic-y += trace_clock.h
arch/powerpc/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += clkdev.h generic-y += rwsem.h +generic-y += trace_clock.h
arch/s390/include/asm/Kbuild +1 -0
@@ -1,3 +1,4 @@ generic-y += clkdev.h +generic-y += trace_clock.h
arch/score/include/asm/Kbuild +1 -0
@@ -3,3 +3,4 @@ include include/asm-generic/Kbuild.asm header-y += generic-y += clkdev.h +generic-y += trace_clock.h
arch/sh/include/asm/Kbuild +1 -0
@@ -31,5 +31,6 @@ generic-y += socket.h generic-y += statfs.h generic-y += termbits.h generic-y += termios.h +generic-y += trace_clock.h generic-y += ucontext.h generic-y += xor.h
arch/sparc/include/asm/Kbuild +1 -0
@@ -8,4 +8,5 @@ generic-y += local64.h generic-y += irq_regs.h generic-y += local.h generic-y += module.h +generic-y += trace_clock.h generic-y += word-at-a-time.h
arch/tile/include/asm/Kbuild +1 -0
@@ -34,5 +34,6 @@ generic-y += sockios.h generic-y += statfs.h generic-y += termbits.h generic-y += termios.h +generic-y += trace_clock.h generic-y += types.h generic-y += xor.h
arch/um/include/asm/Kbuild +1 -0
@@ -2,3 +2,4 @@ generic-y += bug.h cputime.h device.h emergency-restart.h futex.h hardirq.h generic-y += hw_irq.h irq_regs.h kdebug.h percpu.h sections.h topology.h xor.h generic-y += ftrace.h pci.h io.h param.h delay.h mutex.h current.h exec.h generic-y += switch_to.h clkdev.h +generic-y += trace_clock.h
arch/unicore32/include/asm/Kbuild +1 -0
@@ -54,6 +54,7 @@ generic-y += syscalls.h generic-y += termbits.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += types.h generic-y += ucontext.h generic-y += unaligned.h
arch/x86/include/asm/trace_clock.h new file +20 -0
@@ -0,0 +1,20 @@ +#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" }, + +#else /* !CONFIG_X86_TSC */ + +#define ARCH_TRACE_CLOCKS + +#endif + +#endif /* _ASM_X86_TRACE_CLOCK_H */
arch/x86/kernel/Makefile +1 -0
@@ -61,6 +61,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
arch/x86/kernel/trace_clock.c new file +21 -0
@@ -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; +}
arch/xtensa/include/asm/Kbuild +1 -0
@@ -25,4 +25,5 @@ generic-y += siginfo.h generic-y += statfs.h generic-y += termios.h generic-y += topology.h +generic-y += trace_clock.h generic-y += xor.h
include/asm-generic/trace_clock.h new file +16 -0
@@ -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 */
include/linux/trace_clock.h +2 -0
@@ -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);
kernel/trace/trace.c +1 -0
@@ -488,6 +488,7 @@ static struct { { trace_clock_local, "local" }, { trace_clock_global, "global" }, { trace_clock_counter, "counter" }, + ARCH_TRACE_CLOCKS };int trace_clock_id;