Re: CPU Frequency scaling with LTTng

Hi Richard,

* Richard Purdie ([email protected]) wrote:
> Hi,
> 
> I've been experimenting with CPU frequency scaling and its effect on
> LTTng. I notice some of the header fields hint at planned support for
> frequency scaling but the userland tools (LTTV) don't seem to support
> it?
> 

Yes, this is something we have to address. LTTng should live correctly
with frequency scaling in UP systems, but won't give the correct elapsed
time in ns.

In SMP, the current version will detect non synchronized TSCs (which
happens when frequency scaling is used on x86, x86_64) and will fall
back on an hybrid clock based on the highest TSC count seen in the
system and a logical clock.

> >From a kernel point of view the easiest way to handle it seemed to be to
> force a subbuffer switch immediately after the frequency change. This is
> relatively straightforward to do with minor alterations to existing
> code.
> 

Hrm, but you can end up having maaaany buffers. How frequent can the
frequency change be in the worse case ? The idea is interesting and
points out a basic need : we have to be able to extract frequency change
events efficiently.

> I also added ltt-heartbeat to the cpufreq notifier chain so the
> heartbeat frequency would work correctly (cpufreq updates
> loops_per_jiffy).

Makes sense.

> 
> I've attached a patch of my experiment in case its interesting for
> others. It has a few potential issues like:
> 
> * the mod_timer in heartbeat has a race
> * the heatbeat precalc init function is too verbose for this use
> * the hook into the OMAP2 amounts to a hack:
>   - would fail to compile if LTT was disabled
>   - too verbose
>   (would it be better to call ltt_switch_buffers() as part of the
> cpufreq postchange notifier?)
> 
> I'm also not sure about the change to the top of ltt-tracer.c to call
> ltt_frequency(). If I don't do that, the correct start and end
> frequencies are logged in the headers for each buffer but the trace
> header in each buffer lists the start frequency. LTTV seems to ignore
> the start/end values and just looks at the header value. If I change the
> header value as shown, I get corrupt timestamp output from LTTV (not
> that this particularly surprises me)...
> 
> Are there any plans to support frequency scaling and is this approach
> along the right lines? Any thoughts on the subject are welcome!
> 

I had a design idea for this, just did not have time to implement it. It
implies modification of both LTTng and LTTV :

- We should create a new channel "frequency" channel, which would always
be in "normal" mode (just like the facilities channel). Therefore, we
can read the frequency channel before reading the rest of the trace and
extract the information about each frequency change that happened during
tracing. We can then create a data structure that will map :

cycles and cpu number -> time

Events in this tracefile will have, just like any event, a timestamp
and, for event data, the new frequency.

In LTTng, we will need to record the frequency in an event that uses the
"force" flag (currently used for 64 bits heartbeat written just before
we activate tracing). It separates the timestamp generation from the
physical buffer boundaries. It is useful when we plan to do multiple
trace "start/pause/unpause/.../stop".

In LTTV, we would keep one binary tree per CPU in a trace, indexed by
cycles. We would create this tree by reading the frequency channel on a
per cpu tracefile basis, keeping a counter of the time increasing (in
ns), at the rate of the last frequency encountered.

Afterward, a query to this data structure would look like :

LttTime get_timestamp_from_cpu_cycles(guint64 cycles, guint cpu);

This O(log(n)) search would be useful when we look for the right block
containing the information looked for (it's already a O(log(n)) search).
However, for the sequential trace read, we would hook on the frequency
change events in ltt/tracefile.c (it would be an hardcoded event) and
keep track of the current frequency of each CPU. We could then compute
the current time in ns with minimal CPU time required.

What do you think of this ?

Mathieu



> Regards,
> 
> Richard

>  arch/arm/mach-omap2/clock.c |    7 +++
>  include/linux/ltt-tracer.h  |    2 +
>  ltt/ltt-heartbeat.c         |   24 ++++++++++++
>  ltt/ltt-relay.c             |   16 ++++++++
>  ltt/ltt-tracer.c            |   22 ++++++++++-
> 
> Index: linux/arch/arm/mach-omap2/clock.c
> ===================================================================
> --- linux.orig/arch/arm/mach-omap2/clock.c	2007-11-08 16:35:32.000000000 +0000
> +++ linux/arch/arm/mach-omap2/clock.c	2007-11-08 18:54:51.000000000 +0000
> @@ -22,6 +22,7 @@
>  #include <linux/errno.h>
>  #include <linux/delay.h>
>  #include <linux/clk.h>
> +#include <linux/ltt-tracer.h>
>  
>  #include <asm/io.h>
>  
> @@ -339,6 +340,12 @@ static void omap2_clksel_recalc(struct c
>  		clk->rate = clk->parent->rate / div;
>  	}
>  
> +	if (clk == &mpu_ck) {
> +		cpu_khz = clk->rate / 1000;
> +		ltt_switch_buffers();
> +		printk("MPU clock changed to %dkhz\n", cpu_khz);
> +	}
> +
>  	if (unlikely(clk->flags & RATE_PROPAGATES))
>  		propagate_rate(clk);
>  }
> Index: linux/ltt/ltt-tracer.c
> ===================================================================
> --- linux.orig/ltt/ltt-tracer.c	2007-11-08 16:35:32.000000000 +0000
> +++ linux/ltt/ltt-tracer.c	2007-11-08 19:20:45.000000000 +0000
> @@ -241,7 +241,7 @@ void ltt_write_trace_header(struct ltt_t
>  	header->has_alignment = 0;
>  #endif
>  	header->freq_scale = trace->freq_scale;
> -	header->start_freq = trace->start_freq;
> +	header->start_freq = ltt_frequency();
>  	header->start_tsc = trace->start_tsc;
>  	header->start_monotonic = trace->start_monotonic;
>  	header->start_time_sec = trace->start_time.tv_sec;
> @@ -880,6 +880,26 @@ int ltt_control(enum ltt_control_msg msg
>  }
>  EXPORT_SYMBOL_GPL(ltt_control);
>  
> +void ltt_switch_buffers(void)
> +{
> +	struct ltt_trace_struct* trace;
> +
> +	down(&ltt_traces_sem);
> +	list_for_each_entry_rcu(trace, &ltt_traces.head, list) {
> +		trace->ops->switch_channel(trace->channel.facilities);
> +		trace->ops->switch_channel(trace->channel.interrupts);
> +		trace->ops->switch_channel(trace->channel.processes);
> +		trace->ops->switch_channel(trace->channel.modules);
> +		trace->ops->switch_channel(trace->channel.network);
> +		trace->ops->switch_channel(trace->channel.cpu);
> +#ifdef CONFIG_LTT_HEARTBEAT_EVENT
> +		trace->ops->switch_channel(trace->channel.compact);
> +#endif
> +	}
> +	up(&ltt_traces_sem);
> +}
> +EXPORT_SYMBOL_GPL(ltt_switch_buffers);
> +
>  int ltt_filter_control(enum ltt_filter_control_msg msg, char *trace_name)
>  {
>  	int err;
> Index: linux/include/linux/ltt-tracer.h
> ===================================================================
> --- linux.orig/include/linux/ltt-tracer.h	2007-11-08 17:33:50.000000000 +0000
> +++ linux/include/linux/ltt-tracer.h	2007-11-08 18:53:25.000000000 +0000
> @@ -181,6 +181,7 @@ struct ltt_trace_ops {
>  	void (*wakeup_channel) (struct ltt_channel_struct *ltt_channel);
>  	void (*finish_channel) (struct ltt_channel_struct *channel);
>  	void (*remove_channel) (struct ltt_channel_struct *channel);
> +	void (*switch_channel) (struct ltt_channel_struct *channel);
>  	void *(*reserve_slot) (struct ltt_trace_struct *trace,
>  				struct ltt_channel_struct *channel,
>  				void **transport_data, size_t data_size,
> @@ -690,6 +691,7 @@ void ltt_write_trace_header(struct ltt_t
>  		struct ltt_trace_header *header);
>  extern void ltt_buffer_destroy(struct ltt_channel_struct *ltt_chan);
>  extern void ltt_wakeup_writers(struct work_struct *work);
> +extern void ltt_switch_buffers(void);
>  
>  void ltt_core_register(int (*function)(u8, void*));
>  
> Index: linux/ltt/ltt-relay.c
> ===================================================================
> --- linux.orig/ltt/ltt-relay.c	2007-11-08 16:37:09.000000000 +0000
> +++ linux/ltt/ltt-relay.c	2007-11-08 17:30:28.000000000 +0000
> @@ -769,6 +769,21 @@ static void ltt_relay_buffer_flush(struc
>  	ltt_force_switch(buf, FORCE_FLUSH);
>  }
>  
> +static void ltt_relay_buffer_flush_active(void *info)
> +{
> +	struct rchan *rchan = info;
> +	struct rchan_buf *buf = &rchan->buf[smp_processor_id()];
> +
> +	ltt_force_switch(buf, FORCE_ACTIVE);
> +}
> +
> +static void ltt_relay_switch_buffers_chan(struct ltt_channel_struct *ltt_channel)
> +{
> +	struct rchan *rchan = ltt_channel->trans_channel_data;
> +
> +	on_each_cpu(ltt_relay_buffer_flush_active, rchan, 1, 1);
> +}
> +
>  static void ltt_relay_async_wakeup_chan(struct ltt_channel_struct *ltt_channel)
>  {
>  	unsigned int i;
> @@ -1226,6 +1241,7 @@ static struct ltt_transport ltt_relay_tr
>  		.finish_channel = ltt_relay_finish_channel,
>  		.remove_channel = ltt_relay_remove_channel,
>  		.wakeup_channel = ltt_relay_async_wakeup_chan,
> +		.switch_channel = ltt_relay_switch_buffers_chan,
>  		.commit_slot = ltt_relay_commit_slot,
>  		.reserve_slot = ltt_relay_reserve_slot,
>  		.user_blocking = ltt_relay_user_blocking,
> Index: linux/ltt/ltt-heartbeat.c
> ===================================================================
> --- linux.orig/ltt/ltt-heartbeat.c	2007-11-09 10:40:46.000000000 +0000
> +++ linux/ltt/ltt-heartbeat.c	2007-11-09 11:15:54.000000000 +0000
> @@ -23,6 +23,7 @@
>  #include <linux/cpu.h>
>  #include <linux/timex.h>
>  #include <linux/bitops.h>
> +#include <linux/cpufreq.h>
>  #include <linux/marker.h>
>  #include <linux/ltt-facilities.h>
>  #include <linux/ltt-tracer.h>
> @@ -37,6 +38,10 @@
>  static struct timer_list heartbeat_timer;
>  static unsigned int precalc_heartbeat_expire = 0;
>  
> +#ifdef CONFIG_CPU_FREQ
> +static struct notifier_block ltt_hb_freq_notifier;
> +#endif
> +
>  int ltt_compact_data_shift = 0;
>  EXPORT_SYMBOL_GPL(ltt_compact_data_shift);
>  
> @@ -299,6 +304,21 @@ static void init_heartbeat_timer(void)
>  			"- continuing without one \n");
>  }
>  
> +#ifdef CONFIG_CPU_FREQ
> +static int
> +ltt_hb_freq_freq_transition(struct notifier_block *nb, unsigned long val, void *data)
> +{
> +	switch (val) {
> +	case CPUFREQ_POSTCHANGE:
> +		init_heartbeat_timer();
> +		if (timer_pending(&heartbeat_timer))
> +			mod_timer(&heartbeat_timer, jiffies + precalc_heartbeat_expire);
> +		break;
> +	}
> +	return 0;
> +}
> +#endif
> +
>  /* ltt_init_compact_facility reserves the number of bits to identify the event
>   * numbers in the compact headers. It must be called every time the compact
>   * facility is changed. */
> @@ -415,6 +435,10 @@ static int __init ltt_heartbeat_init(voi
>  	ltt_heartbeat_init_synthetic_tsc();
>  #endif //CONFIG_LTT_SYNTHETIC_TSC
>  	init_heartbeat_timer();
> +#ifdef CONFIG_CPU_FREQ
> +	ltt_hb_freq_notifier.notifier_call = ltt_hb_freq_freq_transition;
> +	cpufreq_register_notifier(&ltt_hb_freq_notifier, CPUFREQ_TRANSITION_NOTIFIER);
> +#endif
>  	return 0;
>  }
>  

> _______________________________________________
> Ltt-dev mailing list
> [email protected]
> http://listserv.shafik.org/mailman/listinfo/ltt-dev


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