Re: LTTng on ARM - timestamps

* 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))
        != 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