Re: LTTng on ARM - timestamps

On Thu, 2007-07-26 at 18:18 -0400, Mathieu Desnoyers wrote:
> Oh, right I forgot about this locking issue. We could get away with no
> locking by changing it slightly:
> 
> Instead of using the jiffies counter _at all_, we could keep our own 32
> bits counter, updated atomically by the timer interrupt and the
> timestamp readers like this:
> 
> #define LTT_CLOCK_SHIFT 13
> atomic_t ltt_clock;
> 
> * timer interrupt:
> 
> int old_ltt_clock;
> 
> do {
>   old_ltt_clock = atomic_read(&ltt_clock);
>   } while(atomic_cmpxchg(&ltt_clock, old_ltt_clock, 
>     (old_ltt_clock + (1<<LTT_CLOCK_SHIFT)) & ((1<<LTT_CLOCK_SHIFT)-1))
>         != old_ltt_clock);
> 
> timestamp read (32 bits)
> 
> return atomic_inc_return(&ltt_clock);
> 
> so we have 32-13 = 19 bits before the ltt jiffies overflows.  Upon
> overflow, notice that we mask out the 13 LSBs, so the overflow won't
> bother us, it will simply reset to 0.
> 
> Duration between overflows:
> 2^19 / 1000 tick/s = 524.288s = 8.73 minutes.
> 
> Therefore, we _really_ have to use the synthetic clock to extend this 32
> bit clock to a 64 bit one.

Looks good to me (after the bugfix). I've included a version of this
below which I've tested on ARM where it seems to work ok. I've also
included an untested update to ppc to fix this problem there as well.

> About the test if (tsc == 0), note that the code goes like this
> (intentionally):
> 
> 
>                 tsc = ltt_get_timestamp64();
>                 if (tsc == 0) {
>                         /*
>                          * Error in getting the timestamp : should not happen :
>                          * it would mean we are called from an NMI during a
>                          * write seqlock on xtime.
>                          */
>                         return;
>                 }
> 
> The test is done in the full 64 bits counter, _never_ the 32 bits one,
> so we don't have to worry about periodic 32 bits overflows.

That is one area in ltt-relay.c, in another it says:

#ifdef CONFIG_LTT_HEARTBEAT_EVENT
		if (begin_switch || end_switch_old || end_switch_current)
			*tsc = ltt_get_timestamp64();
		else
			*tsc = ltt_get_timestamp32();
#else
		*tsc = ltt_get_timestamp64();
#endif //CONFIG_LTT_HEARTBEAT_EVENT
		if (*tsc == 0) {
			/* Error in getting the timestamp, event lost */
			local_inc(&ltt_buf->events_lost);
			return NULL;
		}

so a path to the 32 bit counter is possible. I guess we can remove this
with these ltt_get_timestamp changes though? or can the tsc fail on some
archs?

Richard

---
 arch/arm/kernel/time.c |    2 -
 arch/ppc/kernel/time.c |    2 -
 include/asm-arm/ltt.h  |   58 +++++++++++-----------------------------
 include/asm-ppc/ltt.h  |   70 ++++++++++++++-----------------------------------
 ltt/Kconfig            |    4 ++
 ltt/ltt-core.c         |    4 +-
 6 files changed, 44 insertions(+), 96 deletions(-)

Index: linux/arch/arm/kernel/time.c
===================================================================
--- linux.orig/arch/arm/kernel/time.c	2007-07-27 12:31:33.000000000 +0100
+++ linux/arch/arm/kernel/time.c	2007-07-27 12:32:24.000000000 +0100
@@ -338,7 +338,7 @@ void timer_tick(void)
 	do_set_rtc();
 	do_timer(1);
 #ifdef CONFIG_LTT
-	ltt_reset_timestamp();
+	ltt_inc_timestamp();
 #endif
 #ifndef CONFIG_SMP
 	update_process_times(user_mode(get_irq_regs()));
Index: linux/arch/ppc/kernel/time.c
===================================================================
--- linux.orig/arch/ppc/kernel/time.c	2007-07-27 12:31:33.000000000 +0100
+++ linux/arch/ppc/kernel/time.c	2007-07-27 12:32:24.000000000 +0100
@@ -158,7 +158,7 @@ void timer_interrupt(struct pt_regs * re
 		write_seqlock(&xtime_lock);
 		tb_last_stamp = jiffy_stamp;
 #ifdef CONFIG_LTT
-		ltt_reset_timestamp();
+		ltt_inc_timestamp();
 #endif //CONFIG_LTT
 		do_timer(1);
 
Index: linux/include/asm-arm/ltt.h
===================================================================
--- linux.orig/include/asm-arm/ltt.h	2007-07-27 12:32:02.000000000 +0100
+++ linux/include/asm-arm/ltt.h	2007-07-27 12:54:35.000000000 +0100
@@ -15,68 +15,42 @@
 #define LTT_ARCH_TYPE LTT_ARCH_TYPE_ARM
 #define LTT_ARCH_VARIANT LTT_ARCH_VARIANT_NONE
 
-#undef LTT_HAS_TSC
+u64 ltt_heartbeat_read_synthetic_tsc(void);
+extern atomic_t lttng_clock;
 
-#define LTTNG_LOGICAL_SHIFT 13
+#undef LTT_HAS_TSC
 
-extern atomic_t lttng_logical_clock;
+#define LTT_CLOCK_SHIFT 13
 
 static inline u32 ltt_get_timestamp32(void)
 {
-	unsigned long seq;
-	unsigned long try = 5;
-	u32 ret;
-
-	do {
-		seq = read_seqbegin(&xtime_lock);
-		ret = (jiffies << LTTNG_LOGICAL_SHIFT)
-			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
-
-	if (try == 0)
-		return 0;
-	else
-		return ret;
+	return atomic_add_return(1, &lttng_clock);
 }
 
-
-/* The shift overflow doesn't matter */
 static inline u64 ltt_get_timestamp64(void)
 {
-	unsigned long seq;
-	unsigned long try = 5;
-	u64 ret;
-
-	do {
-		seq = read_seqbegin(&xtime_lock);
-		ret = (jiffies_64 << LTTNG_LOGICAL_SHIFT)
-			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
-
-	if (try == 0)
-		return 0;
-	else
-		return ret;
+	return ltt_heartbeat_read_synthetic_tsc();
 }
 
-/* this has to be called with the write seqlock held */
-static inline void ltt_reset_timestamp(void)
+static inline void ltt_inc_timestamp(void)
 {
-	atomic_set(&lttng_logical_clock, 0);
-}
+	int old_clock, new_clock;
 
+	do {
+		old_clock = atomic_read(&lttng_clock);
+		new_clock = (old_clock + (1 << LTT_CLOCK_SHIFT))
+				& (~((1 << LTT_CLOCK_SHIFT) - 1));
+	} while (atomic_cmpxchg(&lttng_clock, old_clock, new_clock) != old_clock);
+}
 
 static inline unsigned int ltt_frequency(void)
 {
-  return HZ << LTTNG_LOGICAL_SHIFT;
+	return HZ << LTT_CLOCK_SHIFT;
 }
 
-
 static inline u32 ltt_freq_scale(void)
 {
-  return 1;
+	return 1;
 }
 
-
-
 #endif
Index: linux/include/asm-ppc/ltt.h
===================================================================
--- linux.orig/include/asm-ppc/ltt.h	2007-07-27 12:31:33.000000000 +0100
+++ linux/include/asm-ppc/ltt.h	2007-07-27 12:43:22.000000000 +0100
@@ -38,29 +38,9 @@
 #define LTT_ARCH_VARIANT LTT_ARCH_VARIANT_NONE
 #endif
 
-#define LTTNG_LOGICAL_SHIFT 13
-
-extern atomic_t lttng_logical_clock;
-
-
-/* The shift overflow doesn't matter */
-static inline u32 _ltt_get_timestamp32(void)
-{
-	unsigned long seq;
-	unsigned long try = 5;
-	u32 ret;
-
-	do {
-		seq = read_seqbegin(&xtime_lock);
-		ret = (jiffies << LTTNG_LOGICAL_SHIFT)
-			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
+#define LTT_CLOCK_SHIFT 13
 
-	if (try == 0)
-		return 0;
-	else
-		return ret;
-}
+extern atomic_t lttng_clock;
 
 static inline void _ltt_get_tb32(u32 *p)
 {
@@ -74,29 +54,10 @@ static inline u32 ltt_get_timestamp32(vo
 {
 	u32 ret;
 	if (__is_processor(1))
-		ret = _ltt_get_timestamp32();
-	else
-		_ltt_get_tb32((u32*)&ret);
-	return ret;
-}
-
-/* The shift overflow doesn't matter */
-static inline u64 _ltt_get_timestamp64(void)
-{
-	unsigned long seq;
-	unsigned long try = 5;
-	u64 ret;
-
-	do {
-		seq = read_seqbegin(&xtime_lock);
-		ret = (jiffies_64 << LTTNG_LOGICAL_SHIFT)
-			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
+		return atomic_add_return(1, &lttng_clock);
 
-	if (try == 0)
-		return 0;
-	else
-		return ret;
+	_ltt_get_tb32((u32*)&ret);
+	return ret;
 }
 
 /* from arch/ppc/xmon/xmon.c */
@@ -116,23 +77,31 @@ static inline u64 ltt_get_timestamp64(vo
 {
 	u64 ret;
 	if (__is_processor(1))
-  		ret = _ltt_get_timestamp64();
-	else
-		_ltt_get_tb64((unsigned*)&ret);
+  		return ltt_heartbeat_read_synthetic_tsc();
+
+	_ltt_get_tb64((unsigned*)&ret);
 	return ret;
 }
 
 /* this has to be called with the write seqlock held */
-static inline void ltt_reset_timestamp(void)
+static inline void ltt_inc_timestamp(void)
 {
-	if (__is_processor(1))
+	int old_clock, new_clock;
+
+	if (!__is_processor(1))
+		return;
+
+	do {
+		old_clock = atomic_read(&lttng_clock);
+		new_clock = (old_clock + (1 << LTT_CLOCK_SHIFT))
+				& (~((1 << LTT_CLOCK_SHIFT) - 1));
+	} while (atomic_cmpxchg(&lttng_clock, old_clock, new_clock) != old_clock);
-		atomic_set(&lttng_logical_clock, 0);
 }
 
 static inline unsigned int ltt_frequency(void)
 {
 	if (__is_processor(1))
-		return HZ << LTTNG_LOGICAL_SHIFT;
+		return HZ << LTT_CLOCK_SHIFT;
 	else
 		return (tb_ticks_per_jiffy * HZ);
 }
Index: linux/ltt/Kconfig
===================================================================
--- linux.orig/ltt/Kconfig	2007-07-27 12:31:33.000000000 +0100
+++ linux/ltt/Kconfig	2007-07-27 12:32:24.000000000 +0100
@@ -4,6 +4,10 @@ config LTT
 	depends on MARKERS
 	select LTT_HEARTBEAT if MIPS
 	select LTT_SYNTHETIC_TSC if MIPS
+	select LTT_HEARTBEAT if ARM
+	select LTT_SYNTHETIC_TSC if ARM
+	select LTT_HEARTBEAT if PPC
+	select LTT_SYNTHETIC_TSC if PPC
 	default n
 	help
 	  It is possible for the kernel to log important events to a trace
Index: linux/ltt/ltt-core.c
===================================================================
--- linux.orig/ltt/ltt-core.c	2007-07-27 12:31:33.000000000 +0100
+++ linux/ltt/ltt-core.c	2007-07-27 12:32:24.000000000 +0100
@@ -22,5 +22,5 @@ volatile unsigned int ltt_nesting[NR_CPU
 
 EXPORT_SYMBOL(ltt_nesting);
 
-atomic_t lttng_logical_clock = ATOMIC_INIT(0);
-EXPORT_SYMBOL(lttng_logical_clock);
+atomic_t lttng_clock = ATOMIC_INIT(0);
+EXPORT_SYMBOL(lttng_clock);