Tracer Timestamping

Hi,

Starting with the bottom of my LTTng patchset
(git://git.kernel.org/pub/scm/linux/kernel/git/compudj/linux-2.6-lttng.git)
I post as RFC the timestamping infrastructure I have been using for a while in the tracer. It integrates get_cycles() standardization following David Miller's comments I did more recently.

It also deals with 32 -> 64 bits timestamp counter extension with a RCU-style algorithm, which is especially useful on MIPS and SuperH architectures.

There is also a TSC synchronization test within this patchset to detect unsynchronized TSCs. See comments in this specific patch to figure out the difference between the current x86 tsc_sync.c and the one I propose in this patch.

It also provides an architecture-agnostic fallback in case there is no timestamp counter available : basically, it's
(jiffies << 13) | atomically_incremented_counter (if there are more than 8192 events per jiffy, time will still be monotonic, but will increment faster than the actual system frequency).

Comments are welcome. Note that this is only the beginning of the patchset. I plan to submit the event ID allocation/portable event typing aimed at exporting the data to userspace and buffering mechanism as soon as I integrate a core version of the LTTV userspace tools to the kernel build tree. Other than that, I currently have a tracer which fulfills most of the requirements expressed earlier. I just fear that if I release only the kernel part without foolproof binary-to-ascii trace decoder within the kernel, people might be a bit reluctant to fetch a separate userspace package.

Mathieu

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Create a new "HAVE_GET_CYCLES" architecture option to specify which architectures provide 64-bits TSC counters readable with get_cycles(). It's principally useful to only enable high-precision tracing code only on such architectures and don't even bother building it on architectures which lack such support.

It also requires architectures to provide get_cycles_barrier() and get_cycles_rate().

I mainly use it for the "priority-sifting rwlock" latency tracing code, which traces worse-case latency induced by the locking. It also provides the basic changes needed for the LTTng timestamping infrastructure.

---
 init/Kconfig |   10 ++++++++++
 1 file changed, 10 insertions(+)

Index: linux-2.6-lttng/init/Kconfig
===================================================================
@@ -323,6 +323,16 @@ config CPUSETS
 config HAVE_UNSTABLE_SCHED_CLOCK
 	bool
 
+#
+# Architectures with a 64-bits get_cycles() should select this.
+# They should also define
+# get_cycles_barrier() : instruction synchronization barrier if required
+# get_cycles_rate() : cycle counter rate, in HZ. If 0, TSC are not synchronized
+# across CPUs or their frequency may vary due to frequency scaling.
+#
+config HAVE_GET_CYCLES
+	def_bool n
+
 config GROUP_SCHED
 	bool "Group CPU scheduler"
 	depends on EXPERIMENTAL

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

This patch selects HAVE_GET_CYCLES and makes sure get_cycles_barrier() and get_cycles_rate() are implemented.

---
 arch/x86/Kconfig      |    1 +
 include/asm-x86/tsc.h |   12 ++++++++++++
 2 files changed, 13 insertions(+)

Index: linux-2.6-lttng/arch/x86/Kconfig
===================================================================
@@ -19,6 +19,7 @@ config X86_64
 config X86
 	def_bool y
 	select HAVE_UNSTABLE_SCHED_CLOCK
+	select HAVE_GET_CYCLES
 	select HAVE_IDE
 	select HAVE_OPROFILE
 	select HAVE_IOREMAP_PROT

Index: linux-2.6-lttng/include/asm-x86/tsc.h
===================================================================
@@ -50,6 +50,18 @@ extern void mark_tsc_unstable(char *reas
 extern int unsynchronized_tsc(void);
 int check_tsc_unstable(void);
 
+static inline cycles_t get_cycles_rate(void)
+{
+	if (check_tsc_unstable())
+		return 0;
+	return tsc_khz;
+}
+
+static inline void get_cycles_barrier(void)
+{
+	rdtsc_barrier();
+}
+
 /*
  * Boot-time check whether the TSCs are synchronized across
  * all CPUs/cores:

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

This patch selects HAVE_GET_CYCLES and makes sure get_cycles_barrier() and get_cycles_rate() are implemented.

---
 arch/sparc/include/asm/timex_64.h |   17 ++++++++++++++++-
 arch/sparc64/Kconfig              |    1 +
 2 files changed, 17 insertions(+), 1 deletion(-)

Index: linux-2.6-lttng/arch/sparc64/Kconfig
===================================================================
@@ -14,6 +14,7 @@ config SPARC64
 	select HAVE_DYNAMIC_FTRACE
 	select HAVE_FTRACE
 	select HAVE_IDE
+	select HAVE_GET_CYCLES
 	select HAVE_LMB
 	select HAVE_ARCH_KGDB
 	select USE_GENERIC_SMP_HELPERS if SMP

Index: linux-2.6-lttng/arch/sparc/include/asm/timex_64.h
===================================================================
@@ -12,7 +12,22 @@
 
 /* Getting on the cycle counter on sparc64. */
 typedef unsigned long cycles_t;
-#define get_cycles()	tick_ops->get_tick()
+
+static inline cycles_t get_cycles(void)
+{
+	return tick_ops->get_tick();
+}
+
+/* get_cycles instruction is synchronized on sparc64 */
+static inline void get_cycles_barrier(void)
+{
+	return;
+}
+
+static inline cycles_t get_cycles_rate(void)
+{
+	return CLOCK_TICK_RATE;
+}
 
 #define ARCH_HAS_READ_CURRENT_TIMER
 

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

This patch selects HAVE_GET_CYCLES and makes sure get_cycles_barrier() and get_cycles_rate() are implemented.

Changelog :
- Use tb_ticks_per_usec * 1000000 in get_cycles_rate().

---
 arch/sparc/include/asm/timex_64.h |   19 ++++++++++++++++++-
 arch/sparc64/Kconfig              |    1 +
 arch/sparc64/kernel/time.c        |    3 ++-
 3 files changed, 21 insertions(+), 2 deletions(-)

Index: linux-2.6-lttng/arch/sparc64/Kconfig
===================================================================
@@ -14,6 +14,7 @@ config SPARC64
 	select HAVE_DYNAMIC_FTRACE
 	select HAVE_FTRACE
 	select HAVE_IDE
+	select HAVE_GET_CYCLES
 	select HAVE_LMB
 	select HAVE_ARCH_KGDB
 	select USE_GENERIC_SMP_HELPERS if SMP

Index: linux-2.6-lttng/arch/sparc/include/asm/timex_64.h
===================================================================
@@ -12,7 +12,24 @@
 
 /* Getting on the cycle counter on sparc64. */
 typedef unsigned long cycles_t;
-#define get_cycles()	tick_ops->get_tick()
+
+static inline cycles_t get_cycles(void)
+{
+	return tick_ops->get_tick();
+}
+
+/* get_cycles instruction is synchronized on sparc64 */
+static inline void get_cycles_barrier(void)
+{
+	return;
+}
+
+extern unsigned long tb_ticks_per_usec;
+
+static inline cycles_t get_cycles_rate(void)
+{
+	return tb_ticks_per_usec * 1000000UL;
+}
 
 #define ARCH_HAS_READ_CURRENT_TIMER
 

Index: linux-2.6-lttng/arch/sparc64/kernel/time.c
===================================================================
@@ -1008,7 +1008,8 @@ static void __init setup_clockevent_mult
 	sparc64_clockevent.mult = mult;
 }
 
-static unsigned long tb_ticks_per_usec __read_mostly;
+unsigned long tb_ticks_per_usec __read_mostly;
+EXPORT_SYMBOL_GPL(tb_ticks_per_usec);
 
 void __delay(unsigned long loops)
 {

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

From: Mathieu Desnoyers <[email protected]>
Date: Thu, 16 Oct 2008 22:48:24 -0400

Yep, that'll work:

This patch selects HAVE_GET_CYCLES and makes sure get_cycles_barrier() and get_cycles_rate() are implemented.

---
 arch/powerpc/Kconfig             |    1 +
 arch/powerpc/include/asm/timex.h |   13 +++++++++++++
 2 files changed, 14 insertions(+)

Index: linux-2.6-lttng/arch/powerpc/Kconfig
===================================================================
@@ -122,6 +122,7 @@ config PPC
 	select HAVE_DMA_ATTRS if PPC64
 	select USE_GENERIC_SMP_HELPERS if SMP
 	select HAVE_OPROFILE
+	select HAVE_GET_CYCLES if PPC64
 
 config EARLY_PRINTK
 	bool

Index: linux-2.6-lttng/arch/powerpc/include/asm/timex.h
===================================================================
@@ -46,5 +46,18 @@ static inline cycles_t get_cycles(void)
 #endif
 }
 
+static inline cycles_t get_cycles_rate(void)
+{
+	return CLOCK_TICK_RATE;
+}
+
+/*
+ * To check : assuming mtfb requires isync to synchronize instruction execution.
+ */
+static inline void get_cycles_barrier(void)
+{
+	isync();
+}
+
 #endif	/* __KERNEL__ */
 #endif	/* _ASM_POWERPC_TIMEX_H */

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[snip]

Ok, this should work better. Thanks !

Do you know if mtfb implies an instruction synchronization (isync) ? I think that if it does not, the new get_cycles_barrier() might have to be used at some locations in the kernel code if more precise timestamp order is required.

Mathieu

get_cycles() : powerpc64 HAVE_GET_CYCLES

This patch selects HAVE_GET_CYCLES and makes sure get_cycles_barrier() and get_cycles_rate() are implemented.

---
 arch/powerpc/Kconfig             |    1 +
 arch/powerpc/include/asm/timex.h |   14 ++++++++++++++
 2 files changed, 15 insertions(+)

Index: linux-2.6-lttng/arch/powerpc/Kconfig
===================================================================
@@ -122,6 +122,7 @@ config PPC
 	select HAVE_DMA_ATTRS if PPC64
 	select USE_GENERIC_SMP_HELPERS if SMP
 	select HAVE_OPROFILE
+	select HAVE_GET_CYCLES if PPC64
 
 config EARLY_PRINTK
 	bool

Index: linux-2.6-lttng/arch/powerpc/include/asm/timex.h
===================================================================
@@ -9,6 +9,7 @@
 
 #include <asm/cputable.h>
 #include <asm/reg.h>
+#include <asm/time.h>
 
 #define CLOCK_TICK_RATE	1024000 /* Underlying HZ */
 

@@ -46,5 +47,18 @@ static inline cycles_t get_cycles(void)
 #endif
 }
 
+static inline cycles_t get_cycles_rate(void)
+{
+	return tb_ticks_per_sec;
+}
+
+/*
+ * To check : assuming mtfb requires isync to synchronize instruction execution.
+ */
+static inline void get_cycles_barrier(void)
+{
+	isync();
+}
+
 #endif	/* __KERNEL__ */
 #endif	/* _ASM_POWERPC_TIMEX_H */

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

It doesn't.

OK. I'll let you figure out where. :)

Paul.

From: Mathieu Desnoyers <[email protected]>
Date: Thu, 16 Oct 2008 20:43:28 -0400

You'll need to make a similar fix on sparc64.

I guess you are talking about using sparc64_get_clock_tick rather than CLOCK_TICK_RATE ? I assume sparc64_get_clock_tick() done on any CPU will return the same rate ?

Thanks,

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

From: Mathieu Desnoyers <[email protected]>
Date: Thu, 16 Oct 2008 22:08:13 -0400

You'll need to use tb_ticks_per_usec or similar.

The ->get_tick() thing you are using uses a TICK source which is synchronized across the entire system and advances at a non-changing rate.

sparc64_get_clock_tick() returns something different.

partly reverts commit efb9ca08b5a2374b29938cdcab417ce4feb14b54. Selects HAVE_GET_CYCLES_32 only on CPUs where it is safe to use it.

Currently consider the "_WORKAROUND" cases for 4000 and 4400 to be unsafe, but should probably add other sub-architecture to the blacklist.

Do not define HAVE_GET_CYCLES because MIPS does not provide 64-bit tsc (only 32-bits).

---
 arch/mips/Kconfig        |    4 ++++
 include/asm-mips/timex.h |   25 +++++++++++++++++++++++++
 2 files changed, 29 insertions(+)

Index: linux-2.6-lttng/include/asm-mips/timex.h
===================================================================
@@ -29,14 +29,39 @@
  * which isn't an evil thing.
  *
  * We know that all SMP capable CPUs have cycle counters.
+ *
+ * Mathieu Desnoyers <[email protected]>
+ * HAVE_GET_CYCLES makes sure that this case is handled properly :
+ *
+ * Ralf Baechle <[email protected]> :
+ * This avoids us executing an mfc0 c0_count instruction on processors which
+ * don't have but also on certain R4000 and R4400 versions where reading from
+ * the count register just in the very moment when its value equals c0_compare
+ * will result in the timer interrupt getting lost.
  */
 
 typedef unsigned int cycles_t;
 
+#ifdef HAVE_GET_CYCLES_32
+static inline cycles_t get_cycles(void)
+{
+	return read_c0_count();
+}
+
+static inline void get_cycles_barrier(void)
+{
+}
+
+static inline cycles_t get_cycles_rate(void)
+{
+	return CLOCK_TICK_RATE;
+}
+#else
 static inline cycles_t get_cycles(void)
 {
 	return 0;
 }
+#endif
 
 #endif /* __KERNEL__ */
 

Index: linux-2.6-lttng/arch/mips/Kconfig
===================================================================
@@ -1581,6 +1581,10 @@ config CPU_R4000_WORKAROUNDS
 config CPU_R4400_WORKAROUNDS
 	bool
 
+config HAVE_GET_CYCLES_32
+	def_bool y
+	depends on !CPU_R4400_WORKAROUNDS
+
 #
 # Use the generic interrupt handling code in kernel/irq/:
 #

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[...]

Hrm, this sounds fragile. What happens if the instrumentation is added in a irq-disabled code path ? We would be executing the timer interrupt handler at this site synchronously when it should be deferred until the irq off section is done. That would therefore behave like there is an interrupt occuring in an irq off section.

OTOH, if we detect that get_cycles() is called with irqs off and decide not to execute the irq handler, then the handler that would be expected to be executed when the irq off section ends will simply be discarded and a timer interrupt will be lost.

Or is there some way to raise the interrupt line from the CPU so it behaves like a standard asynchronous interrupt ?

The other way around would be to add a check in local_irq_enable() to verify that such work is pending, but it might have a significant performance impact.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Adds the basic LTTng config options.

sparc32 needs to have ltt/ added to core-y for some reason (seems broken).

ltt/Kconfig is sourced from kernel/Kconfig.instrumentation.

---
 Makefile            |    2 +-
 arch/sparc/Makefile |    2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

Index: linux-2.6-lttng/arch/sparc/Makefile
===================================================================
@@ -37,7 +37,7 @@ drivers-$(CONFIG_OPROFILE)	+= arch/sparc
 # Renaming is done to avoid confusing pattern matching rules in 2.5.45 (multy-)
 INIT_Y		:= $(patsubst %/, %/built-in.o, $(init-y))
 CORE_Y		:= $(core-y)
-CORE_Y		+= kernel/ mm/ fs/ ipc/ security/ crypto/ block/
+CORE_Y		+= kernel/ mm/ fs/ ipc/ security/ crypto/ block/ ltt/
 CORE_Y		:= $(patsubst %/, %/built-in.o, $(CORE_Y))
 DRIVERS_Y	:= $(patsubst %/, %/built-in.o, $(drivers-y))
 NET_Y		:= $(patsubst %/, %/built-in.o, $(net-y))

Index: linux-2.6-lttng/Makefile
===================================================================
@@ -619,7 +619,7 @@ export mod_strip_cmd
 
 
 ifeq ($(KBUILD_EXTMOD),)
-core-y		+= kernel/ mm/ fs/ ipc/ security/ crypto/ block/
+core-y		+= kernel/ mm/ fs/ ipc/ security/ crypto/ block/ ltt/
 
 vmlinux-dirs	:= $(patsubst %/,%,$(filter %/, $(init-y) $(init-m) \
 		     $(core-y) $(core-m) $(drivers-y) $(drivers-m) \

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Hi

just nit

  CHK     include/linux/version.h
  CHK     include/linux/utsrelease.h
  CALL    scripts/checksyscalls.sh
  CHK     include/linux/compile.h

Will fix in the next release, thanks !

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

LTTng synthetic TSC code for timestamping. Extracts 64 bits tsc from a [0..32] bits counter, kept up to date by periodical timer interrupt. Lockless.

Nope, I don't use RCU internals in this code. Preempt disable seemed like the best way to handle this utterly short code path and I wanted the write side to be fast enough to be called periodically. What I do is:

- Disable preemption at the read-side :
it makes sure the pointer I get will point to a data structure that will never change while I am in the preempt disabled code. (see *)
- I use per-cpu data to allow the read-side to be as fast as possible (only need to disable preemption, does not race against other CPUs and won't generate cache line bouncing). It also allows dealing with unsynchronized TSCs if needed.
- Periodical write side : it's called from an IPI running on each CPU.

(*) We expect the read-side (preempt off region) to last shorter than the interval between IPI updates so we can guarantee the data structure it uses won't be modified underneath it. Since the IPI update is launched each seconds or so (depends on the frequency of the counter we are trying to extend), it's more than ok.

Changelog:

- Support [0..32] bits -> 64 bits.

I volountarily limit the code to use at most 32 bits of the hardware clock for performance considerations. If this is a problem it could be changed. Also, the algorithm is aimed at a 32 bits architecture. The code becomes muuuch simpler on a 64 bits arch, since we can do the updates atomically.

---
 init/Kconfig        |    2 
 ltt/Kconfig         |   17 ++++
 ltt/Makefile        |    1 
 ltt/ltt-timestamp.c |  212 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 232 insertions(+)

Index: linux-2.6-lttng/ltt/ltt-timestamp.c
===================================================================
@@ -0,0 +1,212 @@
+/*
+ * (C) Copyright	2006,2007 -
+ * 		Mathieu Desnoyers ([email protected])
+ *
+ * notes : ltt-timestamp timer-based clock cannot be used for early tracing in
+ * the boot process, as it depends on timer interrupts.
+ *
+ * The timer is only on one CPU to support hotplug.
+ * We have the choice between schedule_delayed_work_on and an IPI to get each
+ * CPU to write the heartbeat. IPI has been chosen because it is considered
+ * faster than passing through the timer to get the work scheduled on all the
+ * CPUs.
+ */
+
+#include <linux/module.h>
+#include <linux/init.h>
+#include <linux/delay.h>
+#include <linux/timer.h>
+#include <linux/workqueue.h>
+#include <linux/cpu.h>
+#include <linux/timex.h>
+#include <linux/bitops.h>
+#include <linux/ltt.h>
+#include <linux/smp.h>
+#include <linux/sched.h> /* FIX for m68k local_irq_enable in on_each_cpu */
+
+/*
+ * Number of hardware clock bits. The higher order bits are expected to be 0.
+ * If the hardware clock source has more than 32 bits, the bits higher than the
+ * 32nd will be truncated by a cast to a 32 bits unsigned. Range : 1 - 32.
+ * (too few bits would be unrealistic though, since we depend on the timer to
+ * detect the overflows).
+ */
+#define HW_BITS				32
+
+#define HW_BITMASK			((1ULL << HW_BITS) - 1)
+#define HW_LSB(hw)			((hw) & HW_BITMASK)
+#define SW_MSB(sw)			((sw) & ~HW_BITMASK)
+
+/* Expected maximum interrupt latency in ms : 15ms, *2 for security */
+#define EXPECTED_INTERRUPT_LATENCY	30
+
+atomic_t lttng_generic_clock;
+EXPORT_SYMBOL(lttng_generic_clock);
+
+static struct timer_list stsc_timer;
+static unsigned int precalc_expire;
+
+struct synthetic_tsc_struct {
+	union {
+		u64 val;
+		struct {
+#ifdef __BIG_ENDIAN
+			u32 msb;
+			u32 lsb;
+#else
+			u32 lsb;
+			u32 msb;
+#endif
+		} sel;
+	} tsc[2];
+	unsigned int index;	/* Index of the current synth. tsc. */
+};
+
+static DEFINE_PER_CPU(struct synthetic_tsc_struct, synthetic_tsc);
+
+/* Called from IPI : either in interrupt or process context */
+static void ltt_update_synthetic_tsc(void)
+{
+	struct synthetic_tsc_struct *cpu_synth;
+	u32 tsc;
+
+	preempt_disable();
+	cpu_synth = &per_cpu(synthetic_tsc, smp_processor_id());
+	tsc = ltt_get_timestamp32();		/* Hardware clocksource read */
+
+	if (tsc < HW_LSB(cpu_synth->tsc[cpu_synth->index].sel.lsb)) {
+		unsigned int new_index = 1 - cpu_synth->index; /* 0 <-> 1 */
+		/*
+		 * Overflow
+		 * Non atomic update of the non current synthetic TSC, followed
+		 * by an atomic index change. There is no write concurrency,
+		 * so the index read/write does not need to be atomic.
+		 */
+		cpu_synth->tsc[new_index].val =
+			(SW_MSB(cpu_synth->tsc[cpu_synth->index].val)
+				| (u64)tsc) + (1ULL << HW_BITS);
+		cpu_synth->index = new_index;	/* atomic change of index */
+	} else {
+		/*
+		 * No overflow : We know that the only bits changed are
+		 * contained in the 32 LSBs, which can be written to atomically.
+		 */
+		cpu_synth->tsc[cpu_synth->index].sel.lsb =
+			SW_MSB(cpu_synth->tsc[cpu_synth->index].sel.lsb) | tsc;
+	}
+	preempt_enable();
+}
+
+/* Called from buffer switch : in _any_ context (even NMI) */
+u64 notrace ltt_read_synthetic_tsc(void)
+{
+	struct synthetic_tsc_struct *cpu_synth;
+	u64 ret;
+	unsigned int index;
+	u32 tsc;
+
+	preempt_disable_notrace();
+	cpu_synth = &per_cpu(synthetic_tsc, smp_processor_id());
+	index = cpu_synth->index;		/* atomic read */
+	tsc = ltt_get_timestamp32();		/* Hardware clocksource read */
+
+	/* Overflow detection */
+	if (unlikely(tsc < HW_LSB(cpu_synth->tsc[index].sel.lsb)))
+		ret = (SW_MSB(cpu_synth->tsc[index].val) | (u64)tsc)
+			+ (1ULL << HW_BITS);
+	else
+		ret = SW_MSB(cpu_synth->tsc[index].val) | (u64)tsc;
+	preempt_enable_notrace();
+	return ret;
+}
+EXPORT_SYMBOL_GPL(ltt_read_synthetic_tsc);
+
+static void synthetic_tsc_ipi(void *info)
+{
+	ltt_update_synthetic_tsc();
+}
+
+/* We need to be in process context to do an IPI */
+static void synthetic_tsc_work(struct work_struct *work)
+{
+	on_each_cpu(synthetic_tsc_ipi, NULL, 1);
+}
+static DECLARE_WORK(stsc_work, synthetic_tsc_work);
+
+/*
+ * stsc_timer : - Timer function synchronizing synthetic TSC.
+ * @data: unused
+ *
+ * Guarantees at least 1 execution before low word of TSC wraps.
+ */
+static void stsc_timer_fct(unsigned long data)
+{
+	PREPARE_WORK(&stsc_work, synthetic_tsc_work);
+	schedule_work(&stsc_work);
+
+	mod_timer(&stsc_timer, jiffies + precalc_expire);
+}
+
+/*
+ * precalc_stsc_interval: - Precalculates the interval between the clock
+ * wraparounds.
+ */
+static int __init precalc_stsc_interval(void)
+{
+	precalc_expire =
+		(HW_BITMASK / ((ltt_frequency() / HZ * ltt_freq_scale()) << 1)
+			- 1 - (EXPECTED_INTERRUPT_LATENCY * HZ / 1000)) >> 1;
+	WARN_ON(precalc_expire == 0);
+	printk(KERN_DEBUG "Synthetic TSC timer will fire each %u jiffies.\n",
+		precalc_expire);
+	return 0;
+}
+
+/*
+ * 	hotcpu_callback - CPU hotplug callback
+ * 	@nb: notifier block
+ * 	@action: hotplug action to take
+ * 	@hcpu: CPU number
+ *
+ *	Sets the new CPU's current synthetic TSC to the same value as the
+ *	currently running CPU.
+ *
+ * 	Returns the success/failure of the operation. (NOTIFY_OK, NOTIFY_BAD)
+ */
+static int __cpuinit hotcpu_callback(struct notifier_block *nb,
+				unsigned long action,
+				void *hcpu)
+{
+	unsigned int hotcpu = (unsigned long)hcpu;
+	struct synthetic_tsc_struct *cpu_synth;
+	u64 local_count;
+
+	switch (action) {
+	case CPU_UP_PREPARE:
+		cpu_synth = &per_cpu(synthetic_tsc, hotcpu);
+		local_count = ltt_read_synthetic_tsc();
+		cpu_synth->tsc[0].val = local_count;
+		cpu_synth->index = 0;
+		smp_wmb();	/* Writing in data of CPU about to come up */
+		break;
+	case CPU_ONLINE:
+		/* As we are preemptible, make sure it runs on the right cpu */
+		smp_call_function_single(hotcpu, synthetic_tsc_ipi, NULL, 0);
+		break;
+	}
+	return NOTIFY_OK;
+}
+
+/* Called from one CPU, before any tracing starts, to init each structure */
+static int __init ltt_init_synthetic_tsc(void)
+{
+	hotcpu_notifier(hotcpu_callback, 3);
+	precalc_stsc_interval();
+	init_timer(&stsc_timer);
+	stsc_timer.function = stsc_timer_fct;
+	stsc_timer.expires = jiffies + precalc_expire;
+	add_timer(&stsc_timer);
+	return 0;
+}
+
+__initcall(ltt_init_synthetic_tsc);

Index: linux-2.6-lttng/ltt/Kconfig
===================================================================
@@ -0,0 +1,17 @@
+menu "Linux Trace Toolkit"
+
+config LTT_TIMESTAMP
+	bool "LTTng fine-grained timestamping"
+	default y
+	help
+	  Allow fine-grained timestamps to be taken from tracing applications.
+
+config HAVE_LTT_CLOCK
+	def_bool n
+
+config HAVE_LTT_SYNTHETIC_TSC
+	bool
+	default y if (!HAVE_LTT_CLOCK)
+	default n if HAVE_LTT_CLOCK
+
+endmenu

Index: linux-2.6-lttng/ltt/Makefile
===================================================================
@@ -0,0 +1 @@
+obj-$(CONFIG_HAVE_LTT_SYNTHETIC_TSC)	+= ltt-timestamp.o

Index: linux-2.6-lttng/init/Kconfig
===================================================================
@@ -787,6 +787,8 @@ config MARKERS
 	  Place an empty function call at each marker site. Can be
 	  dynamically changed for a probe function.
 
+source "ltt/Kconfig"
+
 source "arch/Kconfig"
 
 config PROC_PAGE_MONITOR

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

more nit.

  CHK     include/linux/version.h
  CHK     include/linux/utsrelease.h
  CALL    scripts/checksyscalls.sh
  CHK     include/linux/compile.h
  GZIP    kernel/config_data.gz
  IKCFG   kernel/config_data.h
  CC      kernel/configs.o
  LD      kernel/built-in.o
  CC      ltt/ltt-timestamp.o

Thanks for pointing this out. Will fix in the next release with the following patchset order :

get-cycles-kconfig-have-get-cycles.patch
get-cycles-x86-have-get-cycles.patch
get-cycles-sparc64-have-get-cycles.patch
get-cycles-powerpc-have-get-cycles.patch
get-cycles-mips-have-get-cycles.patch

#LTTng timestamping
#
lttng-timestamp-core.patch
lttng-timestamp-generic.patch
lttng-build-instrumentation-menu.patch
lttng-build-instrumentation-menu-timestamp.patch
lttng-mips-export-hpt-frequency.patch
lttng-timestamp-mips.patch
lttng-timestamp-powerpc.patch
lttng-timestamp-sparc64.patch
lttng-timestamp-sh.patch
lttng-test-tsc.patch
lttng-timestamp-x86.patch

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Wrapper to use the lower level clock sources available on the systems. Fall-back on jiffies or'd with a logical clock for architectures lacking CPU timestamp counters. Fall-back on a mixed TSC-logical clock on architectures lacking synchronized TSC on SMP.

A generic fallback based on a logical clock and the timer interrupt is available.

generic - Uses jiffies or'd with a logical clock extended to 64 bits by
ltt-timestamp.c.
i386 - Uses TSC. If detects non synchronized TSC, uses mixed TSC-logical clock. mips - Uses TSC extended atomically from 32 to 64 bits by ltt-heartbeat.c. powerpc - Uses TSC or generic ltt clock.
x86_64 - Uses TSC. If detects non synchronized TSC, uses mixed TSC-logical clock

---
 include/asm-generic/ltt.h |   53 ++++++++++++++++++++++++++++++++++++++++++++++
 include/linux/ltt.h       |   27 +++++++++++++++++++++++
 kernel/timer.c            |    2 +
 3 files changed, 82 insertions(+)

Index: linux-2.6-lttng/kernel/timer.c
===================================================================
@@ -37,6 +37,7 @@
 #include <linux/delay.h>
 #include <linux/tick.h>
 #include <linux/kallsyms.h>
+#include <linux/ltt.h>
 
 #include <asm/uaccess.h>
 #include <asm/unistd.h>

@@ -1066,6 +1067,7 @@ void do_timer(unsigned long ticks)
 {
 	jiffies_64 += ticks;
 	update_times(ticks);
+	ltt_add_timestamp(ticks);
 }
 
 #ifdef __ARCH_WANT_SYS_ALARM

Index: linux-2.6-lttng/include/linux/ltt.h
===================================================================
@@ -0,0 +1,27 @@
+#ifndef _LINUX_LTT_H
+#define _LINUX_LTT_H
+
+/*
+ * Generic LTT clock.
+ *
+ * Chooses between an architecture specific clock or an atomic logical clock.
+ *
+ * Copyright (C) 2007 Mathieu Desnoyers ([email protected])
+ */
+
+#ifdef CONFIG_LTT_TIMESTAMP
+#ifdef CONFIG_HAVE_LTT_CLOCK
+#include <asm/ltt.h>
+#else
+#include <asm-generic/ltt.h>
+
+#define ltt_get_timestamp32	ltt_get_timestamp32_generic
+#define ltt_get_timestamp64	ltt_get_timestamp64_generic
+#define ltt_add_timestamp	ltt_add_timestamp_generic
+#define ltt_frequency		ltt_frequency_generic
+#define ltt_freq_scale		ltt_freq_scale_generic
+#endif /* CONFIG_HAVE_LTT_CLOCK */
+#else
+#define ltt_add_timestamp(ticks)
+#endif /* CONFIG_LTT_TIMESTAMP */
+#endif /* _LINUX_LTT_H */

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

LTTng needs it from modules.

---
 arch/mips/kernel/time.c  |    1 +
 include/asm-mips/timex.h |    2 ++
 2 files changed, 3 insertions(+)

Index: linux-2.6-lttng/include/asm-mips/timex.h
===================================================================
@@ -63,6 +63,8 @@ static inline cycles_t get_cycles(void)
 }
 #endif
 
+extern unsigned int mips_hpt_frequency;
+
 #endif /* __KERNEL__ */
 
 #endif /*  _ASM_TIMEX_H */

Index: linux-2.6-lttng/arch/mips/kernel/time.c
===================================================================
@@ -70,6 +70,7 @@ EXPORT_SYMBOL(perf_irq);
  */
 
 unsigned int mips_hpt_frequency;
+EXPORT_SYMBOL(mips_hpt_frequency);
 
 void __init clocksource_set_clock(struct clocksource *cs, unsigned int clock)
 {

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

MIPS get_cycles only returns a 32 bits TSC (see timex.h). The assumption there is that the reschedule is done every 8 seconds or so. Given that tracing needs to detect delays longer than 8 seconds, we need a full 64-bits TSC, whic is provided by LTTng syntheric TSC.

---
 arch/mips/Kconfig      |    2 ++
 include/asm-mips/ltt.h |   44 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 46 insertions(+)

Index: linux-2.6-lttng/include/asm-mips/ltt.h
===================================================================
@@ -0,0 +1,44 @@
+/*
+ * Copyright (C) 2005, Mathieu Desnoyers
+ *
+ * MIPS definitions for tracing system
+ */
+
+#ifndef _ASM_MIPS_LTT_H
+#define _ASM_MIPS_LTT_H
+
+#include <linux/timex.h>
+#include <asm/processor.h>
+
+extern u64 ltt_read_synthetic_tsc(void);
+
+/*
+ * MIPS get_cycles only returns a 32 bits TSC (see timex.h). The assumption
+ * there is that the reschedule is done every 8 seconds or so. Given that
+ * tracing needs to detect delays longer than 8 seconds, we need a full 64-bits
+ * TSC, whic is provided by LTTng syntheric TSC.
+*/
+static inline u32 ltt_get_timestamp32(void)
+{
+	return get_cycles();
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	return ltt_read_synthetic_tsc();
+}
+
+static inline void ltt_add_timestamp(unsigned long ticks)
+{ }
+
+static inline unsigned int ltt_frequency(void)
+{
+	return mips_hpt_frequency;
+}
+
+static inline u32 ltt_freq_scale(void)
+{
+	return 1;
+}
+
+#endif /* _ASM_MIPS_LTT_H */

Index: linux-2.6-lttng/arch/mips/Kconfig
===================================================================
@@ -1584,6 +1584,8 @@ config CPU_R4400_WORKAROUNDS
 config HAVE_GET_CYCLES_32
 	def_bool y
 	depends on !CPU_R4400_WORKAROUNDS
+	select HAVE_LTT_CLOCK
+	select HAVE_LTT_SYNTHETIC_TSC
 
 #
 # Use the generic interrupt handling code in kernel/irq/:

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

---
 arch/powerpc/Kconfig      |    1 +
 include/asm-powerpc/ltt.h |   37 +++++++++++++++++++++++++++++++++++++
 2 files changed, 38 insertions(+)

Index: linux-2.6-lttng/include/asm-powerpc/ltt.h
===================================================================
@@ -0,0 +1,37 @@
+/*
+ * Copyright (C) 2005, Mathieu Desnoyers
+ *
+ * POWERPC definitions for tracing system
+ */
+
+#ifndef _ASM_POWERPC_LTT_H
+#define _ASM_POWERPC_LTT_H
+
+#include <linux/timex.h>
+#include <asm/time.h>
+#include <asm/processor.h>
+
+static inline u32 ltt_get_timestamp32(void)
+{
+	return get_tbl();
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	return get_tb();
+}
+
+static inline void ltt_add_timestamp(unsigned long ticks)
+{ }
+
+static inline unsigned int ltt_frequency(void)
+{
+	return tb_ticks_per_sec;
+}
+
+static inline u32 ltt_freq_scale(void)
+{
+	return 1;
+}
+
+#endif /* _ASM_POWERPC_LTT_H */

Index: linux-2.6-lttng/arch/powerpc/Kconfig
===================================================================
@@ -115,6 +115,7 @@ config PPC
 	select HAVE_IOREMAP_PROT
 	select HAVE_EFFICIENT_UNALIGNED_ACCESS
 	select HAVE_KPROBES
+	select HAVE_LTT_CLOCK
 	select HAVE_ARCH_KGDB
 	select HAVE_KRETPROBES
 	select HAVE_ARCH_TRACEHOOK

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Implement LTTng timestamping for sparc64

---
 arch/sparc/include/asm/ltt.h |   35 +++++++++++++++++++++++++++++++++++
 arch/sparc64/Kconfig         |    1 +
 2 files changed, 36 insertions(+)

Index: linux-2.6-lttng/arch/sparc/include/asm/ltt.h
===================================================================
@@ -0,0 +1,35 @@
+/*
+ * Copyright (C) 2008, Mathieu Desnoyers
+ *
+ * SPARC64 definitions for tracing system
+ */
+
+#ifndef _ASM_SPARC_LTT_H
+#define _ASM_SPARC_LTT_H
+
+#include <linux/timex.h>
+
+static inline u32 ltt_get_timestamp32(void)
+{
+	return get_cycles();
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	return get_cycles();
+}
+
+static inline void ltt_add_timestamp(unsigned long ticks)
+{ }
+
+static inline unsigned int ltt_frequency(void)
+{
+	return CLOCK_TICK_RATE;
+}
+
+static inline u32 ltt_freq_scale(void)
+{
+	return 1;
+}
+
+#endif /* _ASM_SPARC_LTT_H */

Index: linux-2.6-lttng/arch/sparc64/Kconfig
===================================================================
@@ -19,6 +19,7 @@ config SPARC64
 	select HAVE_ARCH_KGDB
 	select USE_GENERIC_SMP_HELPERS if SMP
 	select HAVE_ARCH_TRACEHOOK
+	select HAVE_LTT_CLOCK
 
 config GENERIC_TIME
 	bool

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

This patch adds the timestamping mechanism in the ltt.h arch header file. The new timestamp functions use the TMU channel 1.

This code only works if the TMU channel 1 is initialized during the kernel boot

Note from Mathieu :
This patch seems to assume TMU channel 1 is setup at boot. Is it always true on all SuperH boards ? Is there some Kconfig selection that should be done here ? We could probably extract part of this patch into get_cycles() and remove CONFIG_LTT dependency.

From: Giuseppe Cavallaro <[email protected]>

---
 arch/sh/Kconfig             |    2 +
 arch/sh/include/asm/ltt.h   |   45 ++++++++++++++++++++++++++++++++++++++++++++
 arch/sh/include/asm/timex.h |    8 ++++++-
 3 files changed, 54 insertions(+), 1 deletion(-)

Index: linux-2.6-lttng/arch/sh/include/asm/ltt.h
===================================================================
@@ -0,0 +1,45 @@
+/*
+ * Copyright (C) 2007, Giuseppe Cavallaro <[email protected]>
+ *                     Mathieu Desnoyers <[email protected]>
+ *
+ * SuperH definitions for tracing system
+ */
+
+#ifndef _ASM_SH_LTT_H
+#define _ASM_SH_LTT_H
+
+#include <linux/timer.h>
+#include <asm/clock.h>
+
+extern u64 ltt_read_synthetic_tsc(void);
+
+static inline u32 ltt_get_timestamp32(void)
+{
+	return get_cycles();
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	return ltt_read_synthetic_tsc();
+}
+
+static inline void ltt_add_timestamp(unsigned long ticks)
+{ }
+
+static inline unsigned int ltt_frequency(void)
+{
+	unsigned long rate;
+	struct clk *tmu1_clk;
+
+	tmu1_clk = clk_get(NULL, "tmu1_clk");
+	rate = (clk_get_rate(tmu1_clk));
+
+	return (unsigned int)(rate);
+}
+
+static inline u32 ltt_freq_scale(void)
+{
+	return 1;
+}
+
+#endif /* _ASM_SH_LTT_H */

Index: linux-2.6-lttng/arch/sh/include/asm/timex.h
===================================================================
@@ -6,12 +6,18 @@
 #ifndef __ASM_SH_TIMEX_H
 #define __ASM_SH_TIMEX_H
 
-#define CLOCK_TICK_RATE		(CONFIG_SH_PCLK_FREQ / 4) /* Underlying HZ */
+#include <linux/io.h>
+#include <asm/cpu/timer.h>
+
+#define CLOCK_TICK_RATE		(HZ * 100000UL)
 
 typedef unsigned long long cycles_t;
 
 static __inline__ cycles_t get_cycles (void)
 {
+#ifdef CONFIG_LTT
+	return 0xffffffff - ctrl_inl(TMU1_TCNT);
+#endif
 	return 0;
 }
 

Index: linux-2.6-lttng/arch/sh/Kconfig
===================================================================
@@ -11,6 +11,8 @@ config SUPERH
 	select HAVE_CLK
 	select HAVE_IDE
 	select HAVE_OPROFILE
+	select HAVE_LTT_CLOCK
+	select HAVE_LTT_SYNTHETIC_TSC
 	select HAVE_GENERIC_DMA_COHERENT
 	help
 	  The SuperH is a RISC processor targeted for use in embedded systems

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Test TSC synchronization across CPUs. Architecture independant and can therefore be used on various architectures. Aims at testing the TSC synchronization on a running system (not only at early boot), with minimal impact on interrupt latency.

I've written this code before x86 tsc_sync.c existed and given it worked well for my needs, I never switched to tsc_sync.c. Although it has the same goal, it does it a bit differently :

tsc_sync looks at the cycle counters on two CPUs to see if one compared to the other are going backward when read in loop. The LTTng code synchronizes both cores with a counter used as a memory barrier and then reads the two TSCs at a delta equal to the cache line exchange. Instruction and data caches are primed. This test is repeated in loops to insure we deal with MCE, NMIs which could skew the results.

The problem I see with tsc_sync.c is that is one of the two CPUs is delayed by an interrupt handler (for way too long) while the other CPU is doing its check_tsc_warp() execution, and if the CPU with the lowest TSC values runs first, this code will fail to detect unsynchronized CPUs.

LTTng TSC sync test code does not have this problem.

---
 ltt/Kconfig        |    3 +
 ltt/Makefile       |    1 
 ltt/ltt-test-tsc.c |  132 +++++++++++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 136 insertions(+)

Index: linux-2.6-lttng/ltt/ltt-test-tsc.c
===================================================================
@@ -0,0 +1,132 @@
+/*
+ * ltt-test-tsc.c
+ *
+ * Test TSC synchronization
+ *
+ * Mathieu Desnoyers <[email protected]>
+ */
+#include <linux/module.h>
+#include <linux/timer.h>
+#include <linux/timex.h>
+#include <linux/jiffies.h>
+#include <linux/cpu.h>
+#include <linux/kthread.h>
+#include <linux/mutex.h>
+
+#define MAX_CYCLES_DELTA 1000ULL
+
+static DEFINE_PER_CPU(cycles_t, tsc_count);
+static DEFINE_MUTEX(tscsync_mutex);
+
+static DEFINE_PER_CPU(int, wait_sync);
+static DEFINE_PER_CPU(int, wait_end_sync);
+
+int ltt_tsc_is_sync = 1;
+EXPORT_SYMBOL(ltt_tsc_is_sync);
+
+cycles_t ltt_last_tsc;
+EXPORT_SYMBOL(ltt_last_tsc);
+
+/*
+ * Mark it noinline so we make sure it is not unrolled.
+ * Wait until value is reached.
+ */
+static noinline void tsc_barrier(long wait_cpu, int value)
+{
+	sync_core();
+	per_cpu(wait_sync, smp_processor_id())--;
+	do {
+		smp_mb();
+	} while (unlikely(per_cpu(wait_sync, wait_cpu) > value));
+	rdtsc_barrier();
+	__get_cpu_var(tsc_count) = get_cycles();
+	rdtsc_barrier();
+}
+
+/*
+ * Worker thread called on each CPU.
+ * First wait with interrupts enabled, then wait with interrupt disabled,
+ * for precision. We are already bound to one CPU.
+ */
+static void test_sync(void *arg)
+{
+	long wait_cpu = (long)arg;
+	unsigned long flags;
+
+	local_irq_save(flags);
+	/* Make sure the instructions are in I-CACHE */
+	tsc_barrier(wait_cpu, 1);
+	tsc_barrier(wait_cpu, 0);
+	per_cpu(wait_end_sync, smp_processor_id())--;
+	do {
+		smp_mb();
+	} while (unlikely(per_cpu(wait_end_sync, wait_cpu) > 1));
+	per_cpu(wait_end_sync, smp_processor_id())--;
+	local_irq_restore(flags);
+}
+
+/*
+ * Do loops (making sure no unexpected event changes the timing), keep the
+ * best one. The result of each loop is the highest tsc delta between the
+ * master CPU and the slaves.
+ */
+static int test_tsc_synchronization(void)
+{
+	long cpu, master;
+	cycles_t max_diff = 0, diff, best_loop, worse_loop = 0;
+	int i;
+
+	mutex_lock(&tscsync_mutex);
+	preempt_disable();
+	master = smp_processor_id();
+	for_each_online_cpu(cpu) {
+		if (master == cpu)
+			continue;
+		best_loop = ULLONG_MAX;
+		for (i = 0; i < 10; i++) {
+			/*
+			 * Each CPU (master and slave) must decrement the
+			 * wait_sync value twice (one for priming in cache).
+			 */
+			per_cpu(wait_sync, master) = 2;
+			per_cpu(wait_sync, cpu) = 2;
+			per_cpu(wait_end_sync, master) = 2;
+			per_cpu(wait_end_sync, cpu) = 2;
+			smp_call_function_single(cpu, test_sync,
+						(void *)master, 0);
+			test_sync((void *)cpu);
+			/*
+			 * Wait until slave is done so that we don't overwrite
+			 * wait_end_sync prematurely.
+			 */
+			while (unlikely(per_cpu(wait_end_sync, cpu) > 0))
+				cpu_relax();
+
+			diff = abs(per_cpu(tsc_count, cpu)
+				- per_cpu(tsc_count, master));
+			best_loop = min(best_loop, diff);
+			worse_loop = max(worse_loop, diff);
+		}
+		max_diff = max(best_loop, max_diff);
+	}
+	preempt_enable();
+	if (max_diff >= MAX_CYCLES_DELTA) {
+		printk(KERN_WARNING
+			"LTTng : Your timestamp counter is not reliable.\n"
+			"See LTTng documentation to find the "
+			"appropriate solution for your architecture.\n");
+		printk("TSC unsynchronized : %llu cycles delta is over "
+			"threshold %llu\n", max_diff, MAX_CYCLES_DELTA);
+	}
+	mutex_unlock(&tscsync_mutex);
+	return max_diff < MAX_CYCLES_DELTA;
+}
+EXPORT_SYMBOL_GPL(test_tsc_synchronization);
+
+static int __init tsc_test_init(void)
+{
+	ltt_tsc_is_sync = test_tsc_synchronization();
+	return 0;
+}
+
+__initcall(tsc_test_init);

Index: linux-2.6-lttng/ltt/Makefile
===================================================================
@@ -1 +1,2 @@
 obj-$(CONFIG_HAVE_LTT_SYNTHETIC_TSC)	+= ltt-timestamp.o
+obj-$(CONFIG_HAVE_LTT_UNSTABLE_TSC)	+= ltt-test-tsc.o

Index: linux-2.6-lttng/ltt/Kconfig
===================================================================
@@ -6,6 +6,9 @@ config LTT_TIMESTAMP
 	help
 	  Allow fine-grained timestamps to be taken from tracing applications.
 
+config HAVE_LTT_UNSTABLE_TSC
+	def_bool n
+
 config HAVE_LTT_CLOCK
 	def_bool n
 

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

X86 LTTng timestamping. Depends on ltt-test-tsc module to detect if timestamp counters are synchronized on the machine.

---
 arch/x86/Kconfig      |    2 
 include/asm-x86/ltt.h |  123 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 125 insertions(+)

Index: linux-2.6-lttng/include/asm-x86/ltt.h
===================================================================
@@ -0,0 +1,123 @@
+#ifndef _ASM_X86_LTT_H
+#define _ASM_X86_LTT_H
+/*
+ * linux/include/asm-x86/ltt.h
+ *
+ * Copyright (C) 2005,2006 - Mathieu Desnoyers ([email protected])
+ *
+ * x86 time and TSC definitions for ltt
+ */
+
+#include <linux/timex.h>
+#include <asm/system.h>
+#include <asm/processor.h>
+#include <asm/atomic.h>
+
+/* Minimum duration of a probe, in cycles */
+#define LTT_MIN_PROBE_DURATION 200
+
+#ifdef CONFIG_HAVE_LTT_SYNTHETIC_TSC
+/* Only for testing. Never needed on x86. */
+u64 ltt_read_synthetic_tsc(void);
+#endif
+
+#ifdef CONFIG_HAVE_LTT_UNSTABLE_TSC
+extern cycles_t ltt_last_tsc;
+extern int ltt_tsc_is_sync;
+
+/*
+ * Support for architectures with non-sync TSCs.
+ * When the local TSC is discovered to lag behind the highest TSC counter, we
+ * increment the TSC count of an amount that should be, ideally, lower than the
+ * execution time of this routine, in cycles : this is the granularity we look
+ * for : we must be able to order the events.
+ */
+static inline cycles_t ltt_async_tsc_read(void)
+{
+	cycles_t new_tsc;
+	cycles_t last_tsc;
+
+	rdtsc_barrier();
+	new_tsc = get_cycles();
+	rdtsc_barrier();
+	do {
+		last_tsc = ltt_last_tsc;
+		if (new_tsc < last_tsc)
+			new_tsc = last_tsc + LTT_MIN_PROBE_DURATION;
+		/*
+		 * If cmpxchg fails with a value higher than the new_tsc, don't
+		 * retry : the value has been incremented and the events
+		 * happened almost at the same time.
+		 * We must retry if cmpxchg fails with a lower value :
+		 * it means that we are the CPU with highest frequency and
+		 * therefore MUST update the value.
+		 */
+	} while (cmpxchg64(&ltt_last_tsc, last_tsc, new_tsc) < new_tsc);
+	return new_tsc;
+}
+
+static inline u32 ltt_get_timestamp32(void)
+{
+	u32 cycles;
+
+	if (ltt_tsc_is_sync) {
+		rdtsc_barrier();
+		cycles = (u32)get_cycles(); /* only need the 32 LSB */
+		rdtsc_barrier();
+	} else
+		cycles = (u32)ltt_async_tsc_read();
+	return cycles;
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	u64 cycles;
+
+	if (ltt_tsc_is_sync) {
+		rdtsc_barrier();
+		cycles = get_cycles();
+		rdtsc_barrier();
+	} else
+		cycles = ltt_async_tsc_read();
+	return cycles;
+}
+#else /* CONFIG_HAVE_LTT_UNSTABLE_TSC */
+static inline u32 ltt_get_timestamp32(void)
+{
+	u32 cycles;
+
+	rdtsc_barrier();
+	cycles = (u32)get_cycles(); /* only need the 32 LSB */
+	rdtsc_barrier();
+	return cycles;
+}
+
+static inline u64 ltt_get_timestamp64(void)
+{
+	u64 cycles;
+
+	rdtsc_barrier();
+	cycles = get_cycles();
+	rdtsc_barrier();
+	return cycles;
+}
+#endif /* CONFIG_HAVE_LTT_UNSTABLE_TSC */
+
+/*
+ * Periodic IPI to have an upper bound on TSC inaccuracy.
+ * TODO: should implement this in ltt-test-tsc.ko.
+ */
+static inline void ltt_add_timestamp(unsigned long ticks)
+{ }
+
+static inline unsigned int ltt_frequency(void)
+{
+	return cpu_khz;
+}
+
+static inline u32 ltt_freq_scale(void)
+{
+	return 1000;
+}
+
+#endif /* _ASM_X86_LTT_H */

Index: linux-2.6-lttng/arch/x86/Kconfig
===================================================================
@@ -26,6 +26,8 @@ config X86
 	select HAVE_KPROBES
 	select ARCH_WANT_OPTIONAL_GPIOLIB
 	select HAVE_KRETPROBES
+	select HAVE_LTT_CLOCK
+	select HAVE_LTT_UNSTABLE_TSC
 	select HAVE_DYNAMIC_FTRACE
 	select HAVE_FTRACE
 	select HAVE_KVM if ((X86_32 && !X86_VOYAGER && !X86_VISWS && !X86_NUMAQ) || X86_64)

Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

(a) this shouldn't be inline

If it isn't clear: the alternative is to just always use local timestamps.

At least that way the timestamps mean _something_. You can get the difference between two events when they happen on the same CPU, and it is about as meaningful as it can be.

Don't even _try_ to make a global clock.

Yes, to be able to compare across CPU's you'd need to have extra synchronization information (eg offset and frequency things), but quite frankly, the "global TSC" thing is already worse than even a totally non-synchronized TSC for the above reasons.

Linus

Ok, will fix. I will put this in a new arch/x86/kernel/ltt.c.

Ok, let's try to figure out what the use-cases are, because we are really facing an architectural mess (thanks to Intel and AMD). I don't think there is a single perfect solution for all, but I'll try to explain why I accept the cache-line bouncing behavior when unsynchronized TSCs are detected by LTTng.

First, the most important thing in LTTng is to provide the event flow in the correct order across CPUs. Secondary to that, getting the precise execution time is a nice-to-have when the architecture supports it, but the time granularity itself is not crucially important, as long as we have a way to determine which of two events close in time happens first. The principal use-case where I have seen such tracer in action is when one have to understand why one or more processes are slower than expected. The root cause can easily sit on another CPU, be a locking delay in a particular race condition, or just a process waiting for other processes waiting for a timeout.

This cache-line bouncing global clock is a best-effort to provide correct event order in the trace on architectures with unsync tsc. It's actually better than a global tracing buffer because it limits the number of cache line transfers required to one per event. Global tracing buffers may require to transfer many cache lines across CPUs when events are written across cache lines or larger than a cache line.

Sharing only a single cache-line is not completely pointless, as explained above, but yes, there is a big performance hit involved.

I agree that we should maybe add a degree of flexibility in this time infrastructure to let users select the type of time source they want :

- Global clock, potentially slow on unsynchronized CPUs.
- Local clock, fast, possibility unsynchronized across CPUs.

I simply don't like the global traces because of the extra cache-line bouncing experienced by events written on multiple cache-lines.

I thought about this one. There is actually a FIXME in the code which plans to add an IPI called at each timer interrupt to do a "read tsc" on each CPU. This would give an HZ upper bound to the time precision, which would give a trace with events ordered across CPUs and manage to have the execution time at a HZ precision.

So given that global buffers are less efficient that just synchronizing a single cache-line and that some people are willing to pay the price to get events synchronized across CPUs and others are not, what do you think of leaving the choice to the user about globally/locally synchronized timestamps ?

Thanks for the feedback,

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Even one line bouncing between cpus can be a performamce disaster. You'll probably hit a serious wall somewhere between 8 and 16 cpus (ia64 has code that looks a lot like this in the gettimeofday() path because it does not synchronize cpu cycle counters ... some applications that are overly fond of timestamping internal events using gettimeofday() end up spending significant time doing so on large systems ... even with only a few thousands of calls per second).

-Tony

I agree that one cache line bouncer is devastating to performance. But as Mathieu said, it is better than a global tracer with lots of bouncing going on. My logdev tracer (something similar to ftrace, but used only for debugging) use to have a single buffer. By moving it to a per cpu buffer and using an atomic counter to sort the events, the increase of speed was a few magnitudes.

ftrace does not have a global counter, but on some boxes with out of sync TSCs, it could not find race conditions. I had to pull in logdev, which found the race right away, because of this atomic counter.

logdev adds a bit of perfomance degradation, but for debugging, I don't care, and it has helped me quite a bit.

ftrace can help in debugging most of the time, but on some boxes with wacky time stamps, it is useless to find race problems between CPUS. But ftrace is for production, and can not afford the performance penalty of a global counter.

-- Steve

Scale up enough, and it becomes more than just a performance problem. When SGI first tried to boot on 512 cpus they found the kernel hung completely because of a single global atomic counter for how many interrupts there were. With HZ=1024 and 512 cpus the ensuing cache line bouncing storm from each interrupt took longer to resolve than the interval between interrupts.

With higher event rates (1KHz seems relatively low) this wall will be a problem for smaller systems too.

Perhaps this needs to be optional (and run-time switchable). Some users (tracking performance issues) will want the tracer to have the minumum possible effect on the system. Others (chasing race conditions) will want the best possible ordering of events between cpus[*].

-Tony

[*] I'd still be concerned that a heavyweight strict ordering might perturb the system enough to make the race disappear when tracing is enabled.

Hrm, on such systems
- *large* amount of cpus
- no synchronized TSCs

What would be the best approach to order events ? Do you think we should consider using HPET, event though it's painfully slow ? Would it be faster than cache-line bouncing on such large boxes ? With a frequency around 10MHz, that would give a 100ns precision, which should be enough to order events. However, HPET is known for its poor performances, which I doubt will do better than the cache-line bouncing alternative.

Yup, I think this solution would work. The user could specify the time source for a specific set of buffers (a trace) through debugfs files.

Yes, it's true that it may make the race disappear, but what has been seen in the field (Steven could confirm that) is that it usually makes the race more likely to appear due to an enlarged race window. But I guess it all depends on where the activated instrumentation is.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

There isn't a perfect solution for this. My feeling is that your best hope is with per-cpu buffers logged with the local TSC ... together with some fancy heuristics to post-process the logs to come up with the best approximation to the actual ordering.

If you have a tight upper bound estimate for the errors in converting from "per-cpu" TSC values to "global system time" then the post processing tool will be able to identify events for which the order is uncertain.

This sounds like a poor choice. Makes all traces very slow. 100ns precision isn't all that good ... we can probably do almost as well estimating the delta between TSC on different cpus.

-Tony

The only problem I see with "fancy heuristics" regarding the time base is that when we detect that something is going wrong in the kernel or in a userspace program, the *very last* thing we want to do is to doubt about the reliability of the time source. When a problematic situation is detected, it makes a huge difference whether this information can be trusted or not. I've seen much simpler algorithms in the past (I'm referring to the original LTT heartbeat here) which were told to be plain simple but ended up being buggy and unreliable in rare corner-cases (it did not take into account interrupt latency). After fixing the main problems, I decided to start all over from scratch, because unreliable timestamps means unreliable traces and this is not something I am willing to provide.

100ns is not bad at all actually, especially given we don't plan to require a memory barrier to be issued around the timestamp counter reads. Memory read/writes can easily be reordered so they cause timing skew in the order of 100ns. Also, just the TSC frequency drift and imprecision of the TSC synchronization even when they are synchronized (which is typically one cache line transfer delay when the TSCs are not synchronized by the BIOS/mobo) is also in the order of 100ns. So sorry, I disagree and think 100ns is actually the kind of precision we can expect even from TSC reads.

Having read a lot about the subtle timestamp counter bugs one can find in Intel and AMD boxes (gross summary of my findings here :
http://ltt.polymtl.ca/svn/trunk/lttv/doc/developer/tsc.txt), I think there is no reliable way to give an upper bound on the timing inaccurary, even with heroic measures trying to map the specific bugs of each of those CPUs, when you have stuff like the southbridge temperature throttling slowing down your CPU clock without notifying the kernel. And as a said above, the timestamping code should be _very_ _very_ simple, given that the first thing a kernel developer will point his finger at when a tracer discovers a bug in his code is the tracer itself. So let's save everyone precious time and make this code easy to review. :-)

So we are talking about performance impact of time base reads. Let's look at some interesting numbers :

On my x86_64 box
model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz
stepping : 6
cpu MHz : 2000.060
(dual quad-core, *not* NUMA)

Cycles to read (from 10000 loops, on a single CPU) :

get_cycles :                                                         60
cpuid + get_cycles + cpuid (with rdtsc_barrier) :                    77
ltt_get_timestamp_64() with synchronized TSC :                       79

ltt_get_timestamp_64() with non-synchronized TSC (cache-hot) : 163
ltt_get_timestamp_64() with non-synchronized TSC (after clflush) : 310
(just doing the clflush takes 68 cycles, has been substracted from the previous result)
HPET : 945

So if we have 512 processors doing timestamp reads like crazy, we can suppose the execution to be serialized by cacheline transfer operations from cpu to cpu. Therefore, assuming a worse-case scenario where all the timestamp reads cause a cache line transfer, the 310 cycles (upper bound) it takes to do the cmpxchg, with CPUs running at 2.0GHz, means that we can do 6 451 612 timestamp reads per second on the overall system. On 512 nodes, that means we can do 12 600 timestamp reads/second/cpu.

Compared to this, HPET would offer a slower time base read (945 cycles per read is fairly slow, which gives 2 116 402 time stamp read per second), but if this mmio read is done in parallel across CPUs (I don't see any reason why it should hold the bus exclusively for a simple read.. ?), then it would scale much better so we could expect about 2.1M timestamp read/second/cpu.

I guess the cache-line bouncing approach would get much worse with NUMA systems, and in that case HPET could become increasingly interesting.

To give an order of magnitude, I expect some worse-case scenarios to be around 8MB/s/cpu when tracing stuff like lockdep in circular per-cpu memory buffers. With an average of, say, 16 bytes per event, including the event header and payload, that would mean 524 288 events/second/cpu. In that case, using the cache-line bouncing approach on a 512 nodes box would simply kill the system, but if the HPET reads does not imply serialization, time base reads would add a 25% performance loss in this utterly extreme case, which is acceptable given this is a best-effort. Compared to this, the TSC-based solution (given we have synchronized TSCs) would add a 2% performance hit.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Complexity of dealing with all the random issues that have plagued TSC in different cpus over the years definitely seems to be a problem.

I have one more idea on how we might be able to use TSC locally and still have confidence that we can merge local cpu buffers into a consistent stream.

What if we read the HPET occasionally (once per second?) and add a record to our per-cpu buffer with the value of the HPET. That would give us a periodic cross-check of each cpus TSC against real time so that a "smart" post-processor can sanity check the log entries at regular intervals.

It doesn't deal with the truly insane TSC behaivours (like stopping completely in certain C states, or varying frequency) ... but it would at least be able to reliably detect these forms of insanity.

We need periodic entries added to the buffer anyway to make sure we can detect rollover since we don't want waste space in log records with a full width TSC value.

-Tony

Yes :(

Hrm, that would make the timestamps much more sensitive to tracing hiccups :

- if interrupts are disabled for a long time on the system (kernel bug or at early boot), we cannot assume those HPET events will be logged at the expected interval.
- if we are in buffer full condition (buffers are too small to handle the load and we drop events on buffer full condition), we will not only have missing events : given we depend on those HPET events to have a consistent time-base, all the trace time-base must be considered untrustable.
- we would also have to get this HPET timer value at each subbuffer boundary (at each page in Steven's implementation). This is required so we can make sense of the time-base of buffers when we only gather the last subbuffers written, given the previous ones have been overwritten in flight-recorder mode. However, with a relatively large load and small subbuffers (e.g. 4kB), we would have to get this HPET value 2048 times/second/cpu. On a 512 nodes machine, it may become a problem. See my analysis of poor HPET scalability below.

I also like the one done by AMD when the cycle counter goes backward one a single CPU. :) Hrm, I thought those you say are truly insane behaviors are exactly the ones we are trying to deal with ?

And what do we say when we detect this ? "sorry, please upgrade your hardware to get a reliable trace" ? ;)

Nope, this is not required. I removed the heartbeat event from LTTng two weeks ago, implementing detection of the delta from the last timestamp written into the trace. If we detect that the new timestamp is too far from the previous one, we write the full 64 bits TSC in an extended event header. Therefore, we have no dependency on interrupt latency to get a sane time-base.

Here are some numbers showing the scalability of synchronized TSC vs cache-line bouncing vs HPET read under tracing load. I use LTTng to take a trace only in circular per-cpu memory buffers while tbench is running. I look at the resulting tbench speed. This kind of load generates a lot of tracing data especially because tbench does a lot of small read/writes which generates a lot of system call events. Side-note:
LTTng is currently fully dynamic and parses the format string like printk, and this is accountable for a large part of the performance degradation. LTTng however supports to override this probe with "specialized" probes which know exactly which types to record. I just did not create any yet. So let's focus on timestamping :

model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz
stepping : 6
cpu MHz : 2000.073

tbench, x86_64 dual quad-core, 2.0GHz, 16GB ram Speed Slowdown

(8 cores up)
No tracing : 1910.50 MB/sec
Flight recorder tracing (per-cpu memory buffers)

    synchronized TSC, get_cycles with cpuid :        940.20 MB/sec (50%)
    unsync TSC, get_cycles + cmpxchg :               716.96 MB/sec (62%)
    unsync TSC, HPET read :                          586.53 MB/sec (69%)

(2 cores up)
No tracing : 488.15 MB/sec
Flight recorder tracing (per-cpu memory buffers)

    synchronized TSC, get_cycles with cpuid :        241.34 MB/sec (50%)
    unsync TSC, get_cycles + cmpxchg :               202.30 MB/sec (58%)
    unsync TSC, HPET read :                          187.04 MB/sec (61%)

(1 core up)
No tracing : 270.67 MB/sec
Flight recorder tracing (per-cpu memory buffers)
synchronized TSC, get_cycles with cpuid : 126.82 MB/sec (53.1%)
unsync TSC, get_cycles + cmpxchg : 124.54 MB/sec (53.9%)
unsync TSC, HPET read : 98.75 MB/sec (63.5%)

So, the conclusion it brings about scalability of those time sources regarding tracing is :
- local TSC read scales very well when the number of CPU increases (constant 50% overhead)
- Comparing the added overhead of both get_cyles+cmpxchg and HPET to the local sync TSC :

cores get_cycles+cmpxchg HPET

      1                  0.8%     10%
      2                  8  %     11%
      8                 12  %     19%

So, is it me, or HPET scales even more poorly than a cache-line bouncing cmpxchg ? I find it a bit surprising.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

You should basically expect it to scale perfectly. Of course the tracing itself adds overhead, and at some point the trace data generation may add so much cache/memory traffic that you start getting worse scaling because of _that_, but just a local TSC access itself will be perfect on any sane setup.

I don't think that's strictly true.

The cacheline is going to generally be faster than HPET ever will, since caches are really important. But as you can see, the _degradation_ is actually worse for the cacheline, since the cacheline works perfectly in the UP case (not surprising) and starts degrading a lot more when you start getting bouncing.

And I'm not sure what the behaviour would be for many-core, but I would not be surprised of the cmpxchg actually ends up losing at some point. The HPET is never fast (you can think of it as "uncached access"), and it's going to degrade too (contention at the IO hub level), but it's actually possible that the contention at some point becomes less than wild bouncing.

Many cacheline bouncing issues end up being almost exponential. When you *really* get bouncing, things degrade in a major way. I don't think you've seen the worst of it with 8 cores ;)

And that's why I'd really like to see the "only local TSC" access, even if I admit that the code is going to be much more subtle, and I will also admit that especially in the presense of frequency changes *and* hw with unsynchronized TSC's you may be in the situation where you never get exactly what you want.

But while you may not like some of the "purely local TSC" issues, I would like to point out that

- In _practice_, it's going to be essentially perfect on a lot of machines, and under a lot of loads.

For example, yes it's true that frequency changes will make TSC things less reliable on a number of machines, but people already end up disabling dynamic cpufreq when doing various benchmark runs, simply because people want more consistent numbers for benchmarking across different kernels etc.

So it's entirely possible (and I'd say "likely") that most people are simply willing to do the same thing for tracing if they are tracing things at a level where CPU frequency changes might otherwise matter.

So maybe the "local TSC" approach isn't always perfect, but I'd expect that quite often people who do tracing are willing to work around it. The people doing tracing are generally not doing so without being aware of what they are up to..

- While there is certainly a lot of hardware out there with flaky TSC's, there's also a lot of hardware (especially upcoming) that do *not* have flaky TSC's. We've been complaining to Intel about TSC behavior for years, and the thing is, it actually _is_ improving. It just takes some time.

- So considering that some of the tracing will actually be very important on machines that have lots of cores, and considering that a lot of the issues can generally be worked around, I really do think that it's worth trying to spend a bit of effort on doing the "local TSC + timely corrections"

For example, you mention that interrupts can be disabled for a time, delaying things like regular sync events with some stable external clock (say the HPET). That's true, and it would even be a problem if you'd use the time of the interrupt itself as the source of the sync, but you don't really need to depend on the timing of the interrupt - just that it happens "reasonably often" (and now we're talking _much_ longer timeframes than some interrupt-disabled time - we're talking tenths of seconds or even more).

Then, rather than depend on the time of the interrupt, you just purely can check the local TSC against the HPET (or other source), and synchronize just _purely_ based on those. That you can do by basically doing something like

	do {
		start = read_tsc();
		hpet = read_hpet();
		end = read_tsc();
	} while (end - start > ERROR);

and now, even if you have interrupts enabled (or worry about NMI's), you now know that you have a totally _independent_ sync point, ie you know that your hpet read value is withing ERROR cycles of the start/end values, so now you have a good point for doing future linear interpolation based on those kinds of sync points.

And if you make all these linear interpolations be per-CPU (so you have per-CPU offsets and frequencies) you never _ever_ need to touch any shared data at all, and you know you can scale basically perfectly.

Your linear interpolations may not be _perfect_, but you'll be able to get them pretty damn near. In fact, even if the TSC's aren't synchronized at all, if they are at least _individually_ stable (just running at slightly different frequencies because they are in different clock domains, and/or at different start points), you can basically perfect the precision over time.

Linus

there's been code submitted by Michael Davidson recently that looked interesting, which turns the TSC into such an entity:

    http://lkml.org/lkml/2008/9/25/451

The periodic synchronization uses the hpet, but it thus allows lockless and globally correct readouts of the TSC .

And that would match the long term goal as well: the hw should do this all automatically. So perhaps we should have a trace_clock() after all, independent of sched_clock(), and derived straight from RDTSC.

The approach as propoed has a couple of practical problems, but if we could be one RDTSC+multiplication away from a pretty good timestamp that would be rather useful, very fast and very robust ...

Ingo

Looking at this code, I wonder :

- How it would support virtualization.
- How it would scale to 512 nodes, if we consider that every idle node is doing an HPET readl each time it exits from safe_halt() (this can end up taking most of the HPET timer bandwidth). So in the case where we have 256 idle nodes taking all the HPET timer bandwidth and a 256 nodes doing useful work, the time these HPET reads can take on the useful nodes when they try to resync with the HPET could be long (they may need to sample it periodically or at CPU frequency change, or they may simply go idle once in a while). We might end up having difficulty getting a CPU out of idle due to the time it takes simply to get hold of the HPET.

Given the bad scalability numbers I've recently posted for the HPET, I doubt this a workable solution to the scalability issue.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Given the rest of tracing mainly consists in reading cache-hot data to put it in per-cpu buffers, it actually scales very well.

Too bad I don't have enough cores to generate a meaningful figure, but I've been surprised to see how bad the HPET evolved between 2 and 8 cores (11% impact -> 19% impact) vs cacheline (8% -> 12%). The real big step for cacheline bouncing seems to be between 1 and 2 CPUs, but after that it seems to increase much more slowly than HPET.

I wonder how this can end up being exponential considering I could switch this cache-line bouncing access into an uncached memory access. This would slow down the few CPU cases, but would likely behave much like the HPET read. And the performance impact of that would be expected to increase linearly with the number of cores. I think what makes this linear with the number of cores is because we are talking about a single cache-line exchange. I standard programs, we have to bounce many cache-lines between the CPUs, which therefore follows a time complexity of O(nr cores * nr shared cache-lines). If the number of shared cache-lines is big, it may look like an exponential increase.

I also wonder how many 8+ cores with non-sync TSC systems there are out there, and if tracing is a vital requirement for them, and also I wonder if it's worth all the effort we are putting into this. I am always tempted to just detect this kind of behavior, keep a slower-but-solid solution, and point to some documentation that says what workarounds can be enabled.

The way I work around this issue in LTTng is to detect non-synchronized TSCs, print a warning message telling that the time-base used for tracing is not perfect, and let the user know about some documentation which explains how to work-around the problem with specific kernel command line arguments (e.g. idle=poll and disabling freq scaling). There are however some people who will not be willing to reboot their computer or change their setup, and this is the use-case where I think providing a non-perfect solution (which does not scale as well) makes sense.

Hurray ! :)

As we can see in other threads, it seems to have been tried for a while by very competent people without brilliant success. Given that the requirements tracing have for timestamps that follows as closely as possible the event order across CPUs, which is stronger than the standard kernel time-sources, I think those things should be tried as a new kernel time source which has more relax constraints, and maybe eventually become a trace_clock() source if it is judged stable and precise enough (e.g. we could trace it with a tracer based on a cache-line bouncing clock to see if the event order is correct on various loads).

Even the "reasonably often" can be a problem. Some examples :

- boot time tracing, where interrupts can be off for a while.
- some races within the kernel which could disable interrupts for a long while. Yes, this should _never_ happen, but when it does, a tracer becomes very handy.

Just hope you don't run this on uncommon (e.g. virtualized hardware) and always have end - start > ERROR, because you would be creating an infinite loop. This might cause some problems. But yes, that would help reading the hpet and tsc together. We could probably use the average for TSC value there too :
tsc = start + ((start - end) >> 1);

Hrm, you seem to assume the CPU frequency is nearly constant, but I suspect AMD systems with idle cores will actually make the overall frequency jump drastically between high and low CPU load. Therefore, I don't even think we can really consider those to be individually stable.

The other problem with interpolation is when a CPU starts to accelerate. In the sched_clock code, what is currently done is to cap the tsc value to a max within the time window between two HPET reads so it does not appear to go backwards when the next HPET read occurs. Such case would clearly mess the event synchronization in a noticeable way.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

My employer might be happy with that answer ;-) ... but I think we could tell the user to:

1) adjust something in /sys/...
2) boot with some special option
3) rebuild kernel with CONFIG_INSANE_TSC=y

to switch over to a heavyweight workaround in s/w. Systems that require this are already in the minority ... and I think (hope!) that current and future generations of cpus won't have these challenges.

So this is mostly a campaign for the default code path to be based on current (sane) TSC behaviour ... with the workarounds for past problems kept to one side.

Neat. Could you grab the HPET value here too?

Interesting results. I'm not at all sure why HPET scales so badly. Maybe some h/w throttling/synchronizing going on???

-Tony

This is exactly what I do in this patchset actually :) The common case, when a synchronized TSC is detected, is to do a plain TSC read. However, if a non-synchronized TSC is detected, a warning message is written to the console (pointing to some documentation to get precise timestamping) and the heavyweight cmpxchg-based workaround is enabled.

Yes, I could. When I detect that the TSC value is too far apart from the previous one, I reserve extra space for the header (this could include an extra 64-bits for the HPET). At that moment, I could also sample the HPET, given this happens relatively rarely.

Given the frequency is expected to go at about 1GHz, the 27 bits would overflow 7-8 times per second. The only thing is that I only need this extended field when there are absolutely no events in the stream for an whole overflow period, which is the only case that makes the overflow impossible to detect without having more TSC bits. In the common case where there is a steady flow of event, we would never have such "large TSC header" event.

However, I could do something slightly different from the large TSC header detection. I could make sure there would be a HPET sampling done "periodically", or at least periodically when there are events saved to the buffer by saving, for each buffer, the last TSC value at which the HPET sampling has been done. When we log following events, we do a HPET sampling (and write an extended event header) if we are too far apart from the previous sample.

We would probably need to sample the HPET at subbuffer switch too to allow fast time-based seek on the trace when we read it.

We could then do a pre-processing on the trace buffers which would calculate the linear interpolation of cycles counters between the per-buffer HPET values. The nice thing is that we know the _next_ value coming _after_ an event (which is not the case for a standard kernel time-base), so we can be a bit more precise and we do not suffer from things like "the TSC of a given cpu accelerates and times appears to go backwards when the next HPET sample is taken".

But I am not sure this would be sufficient to insure generally correct event order; the maximum interpolation error can become quite large on systems with different clock speeds in halt states and which would happen to have a non-steady flow of events.

As Linus said, there is probably some contention at the IO hub level. But it implies that we have to be careful about the frequency at which we sample the HPET, otherwise it wouldn't scale.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

What about selective counting? Or have counters per nodes? If you are dealing with a race, most cases, the race is not happening against CPUs not sharing a node. Those not sharing will try hard not to ever use the same cache lines.

I've seen both. 9 out of 10 times, the tracer helps induce the race. But I've had that 1 out of 10 where it makes the race go away.

Actually, what happens is that I'll start adding trace markers (printk like traces), and the race will happen quicker. Then I'll add a few more markers and the race goes away. Those are the worst ;-)

-- Steve

My strong opinion has been - for a longish while now, and independently of any timestamping code - that we should be seriously looking at basically doing essentially a "ntp" inside the kernel to give up the whole idiotic notion of "synchronized TSCs". Yes, TSC's are often synchronized, but even when they are, we might as well _think_ of them as not being so.

In other words, instead of expecting internal clocks to be synchronized, just make the clock be a clock network of independent TSC domains. The domains could in theory be per-package (assuming TSC is synchronized at that level), but even if we _could_ do that, we'd probably still be better off by simply always doing it per-core. If only because then the reading would be per-core.

I think it's a mistake for us to maintain a single clock for gettimeofday() (well, "getnstimeofday" and the whole "clocksource_read()" crud to be technically correct). And sure, I bet clocksource_read() can do various per-CPU things and try to do that, but it's complex and pretty generic code, and as far as I know none of the clocksources have even tried. The TSC clocksource read certainly does not (it just does a very similar horrible "at least don't go backwards" crud that the LTTng patch suggested).

So I think we should make "xtime" be a per-CPU thing, and add support for per-CPU clocksources. And screw that insane "mark_tsc_unstable()" thing.

And if we did it well, we migth be able to get good timestamps that way too.

Linus

Personally I'd been hoping that the experiments in the trace timestamping code would provide a safe area of experimentation before we adapt it to the TSC clocksource implementation for getnstimeofday(). Earlier I know Andi and Jiri were working on such a per-cpu TSC clocksource, but I don't know where it ended up.

I'm not quite sure I followed your per-cpu xtime thoughts. Could you explain further your thinking as to why the entire timekeeping subsystem should be per-cpu instead of just keeping that back in the arch-specific clocksource implementation? In other words, why keep things synced at the nanosecond level instead of keeping the per-cpu TSC synched at the cycle level?

thanks
-john

I don't think you can kep them sync'ed without taking frequency drift into account. When you have multiple boards (ie big boxes), they simply _will_ be in different clock domains. They won't have the exact same frequency.

So the "rewrite the TSC every once in a while" approach (where "after coming out of idle" is just a special case of "once in a while" due to many CPU's losing TSC in idle) works well in the kind of situation where you really only have a single clock domain, and the TSC's are all basically from the same reference clock. And that's a common case, but it certainly isn't the _only_ case.

What about fundamnetally different frequencies (old TSC's that change with cpufreq)? Or what about just subtle different ones (new TSC's but on separate sockets that use separate external clocks)?

But sure, I can imagine using a global xtime, but just local TSC offsets and frequencies, and just generating a local offset from xtime. BUT HOW DO YOU EXPECT TO DO THAT?

Right now, the global xtime offset thing also depends on the fact that we have a single global TSC offset! That whole "delta against xtime" logic depends very much on this:

	/* calculate the delta since the last update_wall_time: */
	cycle_delta = (cycle_now - clock->cycle_last) & clock->mask;

and that base-time setting depends on a _global_ clock source. Why? Because it depends on setting that in sync with updating xtime.

And maybe I'm missing something. But I do not believe that it's easy to just make the TSC be per-CPU. You need per-cpu correction factors, but you _also_ need a per-CPU time base.

Oh, I'm sure you can do hacky things, and work around known issues, and consider the TSC to be globally stable in a lot of common schenarios. That's what you get by re-syncing after idle etc. And it's going to work in a lot of situations.

But it's not going to solve the "hey, I have 512 CPU's, they are all on different boards, and no, they are _not_ synchronized to one global clock!".

That's why I'd suggest making _purely_ local time, and then aiming for something NTP-like. But maybe there are better solutions out there.

Linus

this 'fast local time' was the rough idea we tried to implement via the cpu_clock(cpu) interface.

cpu_clock() results are loosely coupled to xtime in every scheduler tick via the scd->tick_gtod logic.

( That way in a sense it tracks NTP time as well, if NTP is fed back
into GTOD, such as when ntpd is running. Granted, this is not the same quality at all as if it did native NTP-alike corrections, but it at least has a long-term stability. )

And it only ever does cross-CPU work if we specifically ask for a remote clock:

        if (cpu != raw_smp_processor_id()) {
                struct sched_clock_data *my_scd = this_scd();

                lock_double_clock(scd, my_scd);

it still does this "serialization looking" even in the local case:

                __raw_spin_lock(&scd->lock);
                clock = __update_sched_clock(scd, now);
        }

        __raw_spin_unlock(&scd->lock);

... but that lock is strictly per CPU, so it only matters if there _is_ cross-CPU "interest" in that clock. Otherwise these locks are in essence just per CPU and cause no cacheline bouncing, etc.

... but we could try to eliminate even that potential for any locking. On 64-bit it's a real possibility i think. (we need the lock for 32-bit mainly, the timestamps are all 64 bits)

... it also has all the tsc-stops-in-idle smarts, knows about cpufreq, etc. Those things are needed even on UP, to not get really bad transients in time.

That still leaves us with sched_clock() complexity, which has spread out a bit more than it should have. So it's not all as simple as you'd like it to be i think, but we are trying hard ...

Ideas to simplify/robustify it are welcome.

Ingo

At the same time, it would definitely be nice to encourage vendors of large SMP systems to provide a common root crystal (frequency standard) for a single SMP domain. Preferrably a really good one, TCXO or better.

-hpa

A single root crystal is nice for us software guys. But it often also turns into a single point of failure, which the hardware guys are always trying to eliminate. So I think multiple crystals are inevitable for the really large machines.

Bjorn

They are almost inevitable for another reason too: the interconnect seldom has a concept of "clock signal" other than for the signalling itself, and the signal clock is designed for the signal itself and is designed for signal integrity rather than "stable clock".

Does _any_ common interconnect have integral support for clock distribution?

And no, nobody is going to add another clock network for just clock distribution.

So even ignoring redundancy issues, and the fact that people want to hot-plug things (and yes, that would make a central clock interesting), I doubt any hw manufacturer really looks at it the way we do.

The best we could hope for is some hardware assist for helping distribute a common clock. Ie not a real single crystal, but having time-packets in the interconnect that are used to synchronize nodes whenever there is communication between them. It's hard to do that in software, because the overhead is fairly high, but if hardware does at least some of it you could probably get a damn fine distributed clock source.

But I don't know if any hw people are worried enough about it to do it...

Linus

How do you mean "integral"? All it really would end up being would be a separate wire anyway carrying the 14.318 MHz clock, so the only way it would ever be "integral" is as part of the slot connector definition.

Note that this is a *frequency standard*. This is a much simpler task than distributing a clock that has to be in phase with a bunch of data wires.

I have defitely seen machines with a common backplane clock source. That does not mean that it is common. I can certainly see the redundancy issues being a big deal there.

Hotplugging isn't so bad (the clock source is tiny, and goes on the backplane.) Redundancy is harder, but not impossible -- even cheap TCXOs can usually operate either self-running or as slaves to an incoming signal. The hard part is to avoid partition on failure, since in that case you have to handle the unsynchronized case correctly anyway.

Most likely not, which means that any solutions we as software guys propose are probably pointless.

-hpa

I realize you're asking about x86, but just for interest, this is what POWER6 does to give us a timebase register that increments at 512MHz and is synchronized across the machine (i.e. sufficiently well synchronized that the difference between the timebases on any two cores is less than the time taken for them to synchronize via a memory location).

The hardware distributes a 32MHz clock pulse to all nodes, which increments the upper 60 bits of the timebase and clears the bottom 4 bits. The bottom 4 bits are then incremented at a rate that is the processor clock speed divided by some number N set by the hypervisor. The bottom 4 bits also stop incrementing once they reach 0xf.

This seems to work pretty well in practice and avoids the need for hardware to distribute a synchronous 512MHz clock everywhere.

Paul.

Ok. Thanks, the clarification about dealing with the multiple frequency domains helps me understand what you're looking for and why per-cpu time bases would be needed.

I was assuming that we were just looking at the single frequency domain, but unsynced TSCs due to idle halting (or maybe just very slight frequency skew).

<snip>

Yea, and indeed this is path we've been on, because folks have had quite a bit of difficulty getting the single freq domain solution working. So small hacks have been added over time, hoping to get there for just one freq.

Yep. And for now we dodge that by pushing to use an stable global clocksource like HPET for these cases, at the cost of performance.

The difficulty with NTP-like, is distributed systems tend to expect slight deltas between machines. Userland gettimeofday() users do not expect detectable skew between cpus.

Getting that last part right without those "at least don't go backwards" hacks is hard.

I'll keep thinking about it.

thanks
-john

Yep, it looks like a promising area to look into. I think, however, that it would be good to first experiment with it as a in-kernel time source rather than as a tracing time source, so we can use a tracer to make sure it is stable enough. :-)

Also, we have to wonder if it's worth side-stepping tracing developement on what I consider being a "special-case for buggy hardware". If we let development on this specific problem at the kernel level go on its own and decide to use it for tracing when it's judged good enough, we (tracing people) can focus on the following steps needed to get a tracer into Linux, namely buffering, event id management, etc. Given I feel the need for tracing is relatively urgent for the community, I'd recommend getting a basic, non-perfect timestamping solution in first, and keep room for improvement.

I prefer to provide tracing for 98% of the machines out there and point to some documentation telling how to configure the other 1.95% (and feel sorry for the people how fall in the inevitable 0.05%) than to spend years trying to come up with a complex scheme aiming precisely at this 1.95%.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

The code exist by necessity because some systems do not have synchronized ITCs and one would not have time go backward. The cmpxchg there is usually switched off. Its horrible in terms of scaling to large numbers of processor and also horrible in terms of clock accuracy.

Have you looked at the existing 32->63 extention code in include/linux/cnt32_to_63.h and considered unifying it?

We already have such code, no? Does this code replace that one or just add a second test?

Right so you don't unify, that's a missed opportunity, no?

It might be good to drop all the ltt naming and pick more generic names, esp. as ftrace could use a lot of this infrastructure as well.

Yep, I felt this code was dangerous on SMP given it could suffer from the following type of race due to lack of proper barriers :

CPU A B
read hw cnt low
read __m_cnt_hi
read hw cnt low
(wrap detected)
write __m_cnt_hi (incremented)
read __m_cnt_hi (wrap detected) write __m_cnt_hi (incremented)

we therefore increment the high bits twice in the given race.

On UP, the same race could happen if the code is called with preemption enabled.

I don't think the "volatile" statement would necessarily make sure the compiler and CPU would do the __m_cnt_hi read before the hw cnt low read. A real memory barrier to order mmio reads wrt memory reads (or instruction sync barrier if the value is taken from the cpu registers) would be required to insure such order.

I also felt it would be more solid to have per-cpu structures to keep track of 32->64 bits TSC updates, given the TSCs can always be slightly out-of-sync :

CPU A B
read __m_cnt_hi
read hw cnt low (+200 cycles)
(wrap detected)
write __m_cnt_hi (incremented)
read __m_cnt_hi read hw cnt low (-200 cycles) (no wrap)
-> bogus value returned.

It adds a second test, which seems more solid to me than the existing x86 tsc_sync detection code.

Yep, If we can switch the current x86 tsc_sync code to use my architecture agnostic implementation, that would be a gain. We could probably port other tsc sync detect code (ia64 ?) to use this infrastructure too.

Sure. I've done all this development as part of the LTTng project, but I don't care about renaming stuff. trace_clock() seems like a good name for trace clock source. The unsync TSC detection and the 23->64 bits TSC extension would also probably require more generic names (and would benefit to be moved to kernel/).

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

You are wrong.

No. Either you do the _same_ incrementation twice effectively writing the _same_ high value twice, or you don't have simultaneous wrap detections. Simulate it on paper with real numbers if you are not convinced.

Wrong again.

That's easy enough to fix, right?

If the low part is a per CPU value then the high part has to be a per CPU value too. There only needs to be a per-CPU variant of the same algorithm where the only difference is that __m_cnt_hi would be per CPU.

If the low part is global then __m_cnt_hi has to be global, even on SMP.

Nicolas

Hi Nicolas,

Yup, you are right. However, the case where one CPU sees the clock source a little bit off-sync (late) still poses a problem. Example follows :

CPU A B

       read __m_cnt_hi (0x80000000)
       read hw cnt low (0x00000001)
       (wrap detected :
        (s32)(0x80000000 ^ 0x1) < 0)
       write __m_cnt_hi = 0x00000001
       return 0x0000000100000001
                                            read __m_cnt_hi (0x00000001)
                                     (late) read hw cnt low (0xFFFFFFFA)
                                            (wrap detected :
                                             (s32)(0x00000001 ^ 0xFFFFFFFA) < 0)
                                            write __m_cnt_hi = 0x80000001
                                            return 0x80000001FFFFFFFA
                                                                  (time jumps)
       read __m_cnt_hi (0x80000001)
       read hw cnt low (0x00000020)
       (wrap detected :
        (s32)(0x80000001 ^ 0x20) < 0)
       write __m_cnt_hi = 0x00000002
       return 0x0000000200000020
                             (time jumps again)

A similar situation can be generated by out-of-order hi/low bits reads.

For memory read vs cycle counter, something like the "data_barrier(x)" on powerpc would probably be enough when available. We would need something that orders memory reads with the rest of instruction execution. On other architectures, smp_rmb() + get_cycles_barrier() (the latter being an instruction sync) would be required.

For memory read vs mmap io read, a smp_rmb() should be enough.

Hrm, given the performance impact of barriers that would need to be added to insure correct read order of hi and low bits, and also considering the risk that a "synchronized" timestamp counter off by a few cycles poses in terms of time jumping forward, I don't see why we would ever want to use a global __m_cnt_hi ? I would therefore recommend to always use a per-cpu __m_cnt_hi.

Also, a small nit, to make sure cnt32_to_63 never gets scheduled out with a stale old __m_cnt_hi value, its comments should probably say that it has to be always used with preemption off.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

If this is through a global counter then I have a big problem believing you.

If this is a per-CPU counter then you just need a per-CPU version of __m_cnt_hi.

This, of course, should and can be prevented. No big deal.

I still would like to know just _how_ you could manage to have one CPU perform two reads and one write and manage for another CPU to see that just written value but read an even older value from the global counter than what the first CPU saw.

No, not until you convince me of the above nonsense. Sure it will work with a per-CPU __m_cnt_hi of course, but then the timing constraint to keep the algorithm warm is for each CPU which, if the source counter is global, shouldn't be necessary.

If the 63-bit counter is queried often enough on each CPU then it is of course advantageous to go per-CPU to avoid excessive cache bouncing, and if you start worrying about cache bouncing then you certainly call this code often enough to keep everything in synch. But that needs not to be always the case.

NO! THAT's THE WHOLE POINT OF THIS CODE: TO NOT NEED ANY KIND OF LOCKING! The only requirement is that you must not be preempted away for longer than half (or a quarter if you want to play real safe) the period of the base counter. If you cannot guarantee that then either your base counter is so fast that it wraps so often to be unusable, or you have another and bigger problem for being preempted for so long.

Nicolas

If the global counter read through mmap io insures that the values monotonically increases and if the proper memory barriers are there, it should be ok and two consecutive reads done on different CPUs should never go backward.

Counters like MIPS 32-bits timestamp counter is supposedly synchronized across cores, and could thus be thought to be global, but could suffer from such small drift due to inexact counter synchronization.

As I said above, it would be ok with a global mmio counter, given the proper barriers are used.

True, with a mmio time source, only a single counter seems necessary. Only when there are slightly off time sources (such as "almost" synchronized TSC") would the per-cpu counter be needed.

This code should only cache bounce about once or twice per overflow period. The rest should only read the __m_cnt_hi value for comparison. Therefore I don't think cache-line bouncing is such an issue here. OTOH, added barriers can degrade performance a lot.

Or maybe you are just unlucky and a user hit CTRL-Z at the wrong time ? I could be wrong and maybe there is no such thing possible as to "stop" a thread while it's in kernel-space, but unless there are restrictions about where a thread can be stopped, I assume such scenario could cause a very long preemption if preemption is not disabled.

Even if such thread stop is not possible, assuming the scheduler will never leave _any_ thread out of the runqueue for a few seconds seems questionable.

Mathieu

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68