tracing,x86: Add a TSC trace_clock

PATCH Superseded David Sharp 1 participant 3 messages Nov 6, 2012 – Nov 13, 2012 1 message not in the archive

Subsystems (19)

Arm (32-bit) x86 PowerPC MIPS +15 more subsystems

lore

Share & tools

lore

A message that is not in the archive (sent off-list or not yet received): [email protected]

David Sharp

author

2012-11-06 00:46 UTC #1 lore raw

PATCH v8 1/5 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

Signed-off-by David Sharp <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Masami Hiramatsu <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Thomas Gleixner <[email protected]>

Cc "H. Peter Anvin" <[email protected]>

Acked-by Ingo Molnar <[email protected]>

---

Fixed build warnings and errors detected by kbuild test robot.

 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

index 64ffc9e..dcfabb9 100644
@@ -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

index f70ae17..514e398 100644
@@ -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

index a581a22..6e9ca46 100644
@@ -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

index 4807ded..4dd4f78 100644
@@ -1,3 +1,4 @@
 
 generic-y	+= clkdev.h
 generic-y	+= exec.h
+generic-y	+= trace_clock.h

arch/blackfin/include/asm/Kbuild +1 -0

index 5a0625a..27d7075 100644
@@ -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

index 112a496..eae7b59 100644
@@ -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

index 6d43a95..15a122c 100644
@@ -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

index 4a159da..c5d7670 100644
@@ -1,3 +1,4 @@
 
 generic-y += clkdev.h
 generic-y += exec.h
+generic-y += trace_clock.h

arch/h8300/include/asm/Kbuild +1 -0

index 50bbf38..4bc8ae7 100644
@@ -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

index 3bfa9b3..bdb54ce 100644
@@ -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

index dd02f09..05b03ec 100644
@@ -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

index 50bbf38..4bc8ae7 100644
@@ -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

index 88fa3ac..7f1949c 100644
@@ -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

index 8653072..2957fcc 100644
@@ -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

index 533053d..9b54b7a 100644
@@ -1 +1,2 @@
 # MIPS headers
+generic-y += trace_clock.h

arch/mn10300/include/asm/Kbuild +1 -0

index 4a159da..c5d7670 100644
@@ -1,3 +1,4 @@
 
 generic-y += clkdev.h
 generic-y += exec.h
+generic-y += trace_clock.h

arch/openrisc/include/asm/Kbuild +1 -0

index 78de680..8971026 100644
@@ -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

index bac8deb..ff4c9fa 100644
@@ -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

index a4fe15e..2d62b48 100644
@@ -2,3 +2,4 @@
 
 generic-y += clkdev.h
 generic-y += rwsem.h
+generic-y += trace_clock.h

arch/s390/include/asm/Kbuild +1 -0

index 0633dc6..f313f9c 100644
@@ -1,3 +1,4 @@
 
 
 generic-y += clkdev.h
+generic-y += trace_clock.h

arch/score/include/asm/Kbuild +1 -0

index ec697ae..16e41fe 100644
@@ -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

index 29f83be..280bea9 100644
@@ -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

index 645a58d..e26d430 100644
@@ -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

index 6948015..b17b9b8 100644
@@ -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

index 0f6e7b3..b30f34a 100644
@@ -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

index c910c98..7be503e 100644
@@ -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

new file mode 100644
index 0000000..5c16527
@@ -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

index 91ce48f..b2bb37f 100644
@@ -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

arch/x86/kernel/trace_clock.c new file +21 -0

new file mode 100644
index 0000000..25b9937
@@ -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

index 6d13027..095f0a2 100644
@@ -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

new file mode 100644
index 0000000..6726f1b
@@ -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

index 4eb4902..d563f37 100644
@@ -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

index 31e4f55..9aed7f5 100644
@@ -481,6 +481,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

David Sharp

author

2012-11-06 00:48 UTC #2 lore raw

PATCH v8 2/5 tracing: Reset ring buffer when changing trace_clocks

In reply to a message not in the archive

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 <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Masami Hiramatsu <[email protected]>

---
 kernel/trace/trace.c |    8 ++++++++
 1 files changed, 8 insertions(+), 0 deletions(-)

kernel/trace/trace.c +8 -0

index 9aed7f5..84aa489 100644
@@ -4017,6 +4017,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;

Signature · 1 line

1.7.7.3

David Sharp

author

2012-11-13 00:39 UTC #3 lore raw

PATCH v8 3/5 tracing: Format non-nanosec times from tsc clock without a decimal point.

In reply to a message not in the archive

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

Signed-off-by David Sharp <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Masami Hiramatsu <[email protected]>

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

index 5c16527..beab86c 100644
@@ -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

index 642928c..c760670 100644
@@ -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

index 84aa489..64e3fe5 100644
@@ -477,10 +477,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
 };

@@ -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);

kernel/trace/trace.h +0 -4

index c15f528..0460050 100644
@@ -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;

kernel/trace/trace_output.c +53 ~~-25~~

121 lines not on this page · raw message

Signature · 1 line

1.7.7.3