Re: LTTng on ARM - timestamps

* Mathieu Desnoyers ([email protected]) wrote:
> * Richard Purdie ([email protected]) wrote:
> > 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.
> > 
> 
> 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))

Sorry, I mean:
      (old_ltt_clock + (1<<LTT_CLOCK_SHIFT)) & (~((1<<LTT_CLOCK_SHIFT)-1)))
(missing ~)

>         != 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.
> 
> 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.
> 
> What do you think about this ?
> 
> Mathieu
> 
> > > 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",
> > 
> 
> -- 
> Mathieu Desnoyers
> Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

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