Re: LTTng on ARM - timestamps

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

You are completely right. Actually, removing the seqlock fixes
everything: there is no more need to verify if the timestamp is 0
anymore because reading the timestamp can never fail. I will apply your
patch in my tree and it will be in my next release.

Thanks!

Mathieu

> 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);
> 
> 

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