Re: LTTng on ARM - timestamps

On Thu, 2007-07-26 at 14:15 -0400, Mathieu Desnoyers wrote:
> * Richard Purdie ([email protected]) wrote:
> > It turns out that there is instrumentation in do_timer() in
> > kernel/timer.c which requires the xtime_lock write seqlock to be held.
> > The default ARM timer implementation uses jiffies which is read using
> > the same xtime_lock() and hence always fails for this event (and
> > possibly others if there is more instrumentation in xtime_lock paths).
> 
> Yes, using jiffies as a time source is only a best effort. But I think
> we can do it better.
> 
> do_timer should be the only code that traces over the xtime write
> seqlock, except NMIs and, potentially, the lockdep instrumentation
> (Locking facility), which you don't have on ARM AFAIK.
> 
> > Basically this means LTTng is broken on ARM (and anything else using
> > jiffies based timer implementations for their timestamps).
> >
> AFAIK, ARM is the only architecture where I use this. Other
> architectures provide some sort of TSC or external timer to read from.

PPC seems to use jiffies as a fallback for some processors. MIPS used to
but doesn't now looking at the code.

> > The best solution I can see is to add a finer grained seqlock only held
> > with jiffies is changed and to use this in the timestamps for systems
> > without a TSC. Is this problem known about and is there any alternative?
> 
> Yes, I have always considered that taking a lock, even a read seqlock,
> in the tracing code should be made illegal ;) I have an alternative idea
> that would fix the problem:
> 
> - Use only the 32 LSB of the jiffies. No need to take a read seqlock.

Then the clock isn't of high enough resolution? When we discussed this
originally, the problem was that we needed an effectively unique counter
if I remember correctly and jiffies isn't of high enough resolution?

> - At 1000HZ, the maximum trace duration would be:
>   2^32 cycles / 1000 cycles/s = 4294967.296s = 49.71 days (a little bit
>   too low)
> 
> Which is not bad, but could be much better. Actually, I keep 13 bits
> (max of 8192 events per timer tick) for the "logical clock" and use the
> other 51 bits for the jiffies. (max trace duration of 71355.23 years)
> However, it requires to have a coherent 64 bits jiffies counter trucated
> to 51 bits.

The problem is combining the logical clock atomically with jiffies. That
is why we have the seqlock, even in the 32 bit case and is where the
problem arises.

> In order to do that correctly, using the ltt synthetic TSC which extends
> a 32 bits counter into a 64 bits counter should let you do that without
> locks. See ltt/ltt-heartbeat.c. The only "different" thing would be that
> you would use the 32 jiffies LSB instead of get_cycles() to feed the 32 LSBs
> to ltt-heartbeat.c. See asm-mips/ltt.h for an example of how it is used.

On ARM, some processors do have things that can be used as a 32 bit TSC
and I've used that code to turn them into 64 bit registers. See above
for the problem of combining the logical clock with jiffies even in the
32 bit case.

> About the "zero" test, 64 bits (even 51 bits) counters should suffice to
> insure that it will never wrap to 0 in the computer's life. I have seen
> that kind of test done elsewhere in the core kernel code also.

Ok, I'm still not sure I like it but that is a convincing argument for
64 bit assuming the counter starts from zero. We're also doing this for
32 bit counters though - every 50 days as you mention above...

Anyhow, I tried a quick experiment of introducing my own seqlock
specifically to solve the ARM jiffies problem. I can confirm the patch
below does mean no events get lost. It needs a bit of cleanup for
non-arm but illustrates one possible way this could be solved. The
seqlock itself should be very low impact since we can use the _begin and
_end functions in this context thanks to the surrounding xtime_lock.


Richard


Index: linux/arch/arm/kernel/time.c
===================================================================
--- linux.orig/arch/arm/kernel/time.c	2007-07-26 18:22:39.000000000 +0100
+++ linux/arch/arm/kernel/time.c	2007-07-26 18:24:58.000000000 +0100
@@ -34,7 +34,6 @@
 #include <asm/leds.h>
 #include <asm/thread_info.h>
 #include <asm/mach/time.h>
-#include <asm/ltt.h>
 
 /*
  * Our system timer.
@@ -337,9 +336,6 @@ void timer_tick(void)
 	do_leds();
 	do_set_rtc();
 	do_timer(1);
-#ifdef CONFIG_LTT
-	ltt_reset_timestamp();
-#endif
 #ifndef CONFIG_SMP
 	update_process_times(user_mode(get_irq_regs()));
 #endif
Index: linux/include/asm-arm/ltt.h
===================================================================
--- linux.orig/include/asm-arm/ltt.h	2007-07-26 17:58:43.000000000 +0100
+++ linux/include/asm-arm/ltt.h	2007-07-26 20:15:04.000000000 +0100
@@ -58,10 +58,10 @@ static inline u32 ltt_get_timestamp32(vo
 	u32 ret;
 
 	do {
-		seq = read_seqbegin(&xtime_lock);
+		seq = read_seqbegin(&ltt_jiffy_lock);
 		ret = (jiffies << LTTNG_LOGICAL_SHIFT)
 			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
+	} while (read_seqretry(&ltt_jiffy_lock, seq) && (--try) > 0);
 
 	if (try == 0) {
 		printk(KERN_ERR "Exhausted tries 32 %d\n", ret);
@@ -80,10 +79,10 @@ static inline u64 ltt_get_timestamp64(vo
 	u64 ret;
 
 	do {
-		seq = read_seqbegin(&xtime_lock);
+		seq = read_seqbegin(&ltt_jiffy_lock);
 		ret = (jiffies_64 << LTTNG_LOGICAL_SHIFT)
 			| (atomic_add_return(1, &lttng_logical_clock));
-	} while (read_seqretry(&xtime_lock, seq) && (--try) > 0);
+	} while (read_seqretry(&ltt_jiffy_lock, seq) && (--try) > 0);
 
 	if (try == 0) {
 		printk(KERN_ERR "Exhausted tries 64 %llu\n", ret);
Index: linux/include/linux/time.h
===================================================================
--- linux.orig/include/linux/time.h	2007-07-26 18:01:24.000000000 +0100
+++ linux/include/linux/time.h	2007-07-26 18:01:54.000000000 +0100
@@ -91,6 +91,7 @@ static inline struct timespec timespec_s
 extern struct timespec xtime;
 extern struct timespec wall_to_monotonic;
 extern seqlock_t xtime_lock __attribute__((weak));
+extern seqlock_t ltt_jiffy_lock __attribute__((weak));
 
 extern unsigned long read_persistent_clock(void);
 void timekeeping_init(void);
Index: linux/kernel/timer.c
===================================================================
--- linux.orig/kernel/timer.c	2007-07-26 17:52:25.000000000 +0100
+++ linux/kernel/timer.c	2007-07-26 18:24:50.000000000 +0100
@@ -43,6 +43,7 @@
 #include <asm/timex.h>
 #include <asm/io.h>
 #include <asm/irq_regs.h>
+#include <asm/ltt.h>
 
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
@@ -1345,7 +1346,10 @@ static inline void update_times(unsigned
 	update_wall_time();
 	calc_load(ticks);
 }
-  
+
+__attribute__((weak)) __cacheline_aligned_in_smp DEFINE_SEQLOCK(ltt_jiffy_lock);
+EXPORT_SYMBOL(ltt_jiffy_lock);
+
 /*
  * The 64-bit jiffies value is not atomic - you MUST NOT read it
  * without sampling the sequence number in xtime_lock.
@@ -1354,7 +1358,12 @@ static inline void update_times(unsigned
 
 void do_timer(unsigned long ticks)
 {
+	write_seqcount_begin(&ltt_jiffy_lock);
 	jiffies_64 += ticks;
+#ifdef CONFIG_LTT
+	ltt_reset_timestamp();
+#endif
+	write_seqcount_end(&ltt_jiffy_lock);
 	update_times(ticks);
 	MARK(kernel_timer_update_time,
 	"%8b %*.*r %*.*r",