[PATCH] ftrace: Add a C-state tracer to help power optimization

[PATCH] ftrace: Add a C-state tracer to help power optimization

[Arjan van de Ven]

From: Arjan van de Ven <arjan@linux.intel.com>
Date: Fri, 3 Oct 2008 10:18:21 -0700
Subject: [PATCH] ftrace: Add a C-state tracer to help power optimization

This patch adds a C-state ftrace plugin that will generate
detailed statistics about the C-states that are being used,
so that we can look at detailed decisions that the C-state
code is making, rather than the too high level "average"
that we have today.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
---
 arch/x86/kernel/process.c   |    9 +++
 include/linux/ftrace.h      |   13 +++++
 kernel/trace/Kconfig        |   11 ++++
 kernel/trace/Makefile       |    1 +
 kernel/trace/trace.h        |    5 ++
 kernel/trace/trace_cstate.c |  123 +++++++++++++++++++++++++++++++++++++++++++
 6 files changed, 162 insertions(+), 0 deletions(-)
 create mode 100644 kernel/trace/trace_cstate.c

diff --git a/arch/x86/kernel/process.c b/arch/x86/kernel/process.c
index 3468131..68c7234 100644
--- a/arch/x86/kernel/process.c
+++ b/arch/x86/kernel/process.c
@@ -7,6 +7,7 @@
 #include <linux/module.h>
 #include <linux/pm.h>
 #include <linux/clockchips.h>
+#include <linux/ftrace.h>
 #include <asm/system.h>
 
 unsigned long idle_halt;
@@ -100,6 +101,8 @@ static inline int hlt_use_halt(void)
 void default_idle(void)
 {
 	if (hlt_use_halt()) {
+		struct cstate_trace it;
+		it.stamp = ktime_get();
 		current_thread_info()->status &= ~TS_POLLING;
 		/*
 		 * TS_POLLING-cleared state must be visible before we
@@ -112,6 +115,8 @@ void default_idle(void)
 		else
 			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
+		it.end = ktime_get();
+		trace_cstate(&it, 1);
 	} else {
 		local_irq_enable();
 		/* loop is done by the caller */
@@ -154,12 +159,16 @@ EXPORT_SYMBOL_GPL(cpu_idle_wait);
  */
 void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
 {
+	struct cstate_trace it;
+	it.stamp = ktime_get();
 	if (!need_resched()) {
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
 			__mwait(ax, cx);
 	}
+	it.end = ktime_get();
+	trace_cstate(&it, (ax>>4)+1);
 }
 
 /* Default MONITOR/MWAIT with no hints, used for default C1 state */
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 91954eb..e6b4da6 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -226,6 +226,19 @@ static inline void trace_boot(struct boot_trace *it) { }
 static inline void start_boot_trace(void) { }
 #endif
 
+struct cstate_trace {
+	ktime_t			stamp;
+	ktime_t			end;
+	int			state;
+	int			CPU;
+};
+
+#ifdef CONFIG_CSTATE_TRACER
+extern void trace_cstate(struct cstate_trace *it, int state);
+#else
+static inline void trace_cstate(struct cstate_trace *it, int state) { }
+#endif
+
 
 
 #endif /* _LINUX_FTRACE_H */
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 396aea1..fa2347a 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -134,6 +134,17 @@ config BOOT_TRACER
 	  be enabled if this tracer is selected since only one tracer
 	  should touch the tracing buffer at a time.
 
+config CSTATE_TRACER
+	bool "Trace C-state behavior"
+	depends on HAVE_FTRACE
+	depends on DEBUG_KERNEL
+	depends on X86
+	select TRACING
+	help
+	  This tracer helps developers to analyize and optimize the kernels
+	  power management decisions, specifically the C-state behavior.
+
+
 config STACK_TRACER
 	bool "Trace max stack"
 	depends on HAVE_FTRACE
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index a85dfba..2b85724 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -24,5 +24,6 @@ obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
 obj-$(CONFIG_BOOT_TRACER) += trace_boot.o
+obj-$(CONFIG_CSTATE_TRACER) += trace_cstate.o
 
 libftrace-y := ftrace.o
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index a921ba5..1ef1ded 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -117,6 +117,11 @@ struct trace_boot {
 	struct boot_trace	initcall;
 };
 
+struct trace_cstate {
+	struct trace_entry	ent;
+	struct cstate_trace	state_data;
+};
+
 /*
  * trace_flag_type is an enumeration that holds different
  * states when a trace occurs. These are:
diff --git a/kernel/trace/trace_cstate.c b/kernel/trace/trace_cstate.c
new file mode 100644
index 0000000..fcd4e6e
--- /dev/null
+++ b/kernel/trace/trace_cstate.c
@@ -0,0 +1,123 @@
+/*
+ * ring buffer based C-state tracer
+ *
+ * Arjan van de Ven <arjan@linux.intel.com>
+ * Copyright (C) 2009 Intel Corporation
+ *
+ * Much is borrowed from trace_boot.c which is
+ * Copyright (C) 2008 Frederic Weisbecker <fweisbec@gmail.com>
+ *
+ */
+
+#include <linux/init.h>
+#include <linux/debugfs.h>
+#include <linux/ftrace.h>
+#include <linux/kallsyms.h>
+
+#include "trace.h"
+
+static struct trace_array *cstate_trace;
+static int trace_cstate_enabled;
+
+
+/* Should be started after do_pre_smp_initcalls() in init/main.c */
+static void start_cstate_trace(void)
+{
+	trace_cstate_enabled = 1;
+}
+
+void stop_cstate_trace(struct trace_array *tr)
+{
+	trace_cstate_enabled = 0;
+}
+
+static void cstate_trace_init(struct trace_array *tr)
+{
+	int cpu;
+	cstate_trace = tr;
+
+	trace_cstate_enabled = 1;
+
+	for_each_cpu_mask(cpu, cpu_possible_map)
+		tracing_reset(tr, cpu);
+}
+
+static void cstate_trace_ctrl_update(struct trace_array *tr)
+{
+	if (tr->ctrl)
+		start_cstate_trace();
+	else
+		stop_cstate_trace(tr);
+}
+
+static enum print_line_t cstate_print_line(struct trace_iterator *iter)
+{
+	int ret;
+	struct trace_entry *entry = iter->ent;
+	struct trace_cstate *field = (struct trace_cstate *)entry;
+	struct cstate_trace *it = &field->state_data;
+	struct trace_seq *s = &iter->seq;
+	struct timespec stamp = ktime_to_timespec(it->stamp);
+	struct timespec duration = ktime_to_timespec(
+					ktime_sub(it->end, it->stamp));
+
+	if (entry->type == TRACE_BOOT) {
+		ret = trace_seq_printf(s, "[%5ld.%09ld] Going to C%i on cpu %i for %ld.%09ld\n",
+					  stamp.tv_sec,
+					  stamp.tv_nsec,
+					  it->state, it->CPU,
+					  duration.tv_sec,
+					  duration.tv_nsec);
+		if (!ret)
+			return TRACE_TYPE_PARTIAL_LINE;
+		return TRACE_TYPE_HANDLED;
+	}
+	return TRACE_TYPE_UNHANDLED;
+}
+
+struct tracer cstate_tracer __read_mostly =
+{
+	.name		= "cstate",
+	.init		= cstate_trace_init,
+	.reset		= stop_cstate_trace,
+	.ctrl_update	= cstate_trace_ctrl_update,
+	.print_line	= cstate_print_line,
+};
+
+static int init_cstate_trace(void)
+{
+	return register_tracer(&cstate_tracer);
+}
+device_initcall(init_cstate_trace);
+
+void trace_cstate(struct cstate_trace *it, int level)
+{
+	struct ring_buffer_event *event;
+	struct trace_cstate *entry;
+	struct trace_array_cpu *data;
+	unsigned long irq_flags;
+	struct trace_array *tr = cstate_trace;
+
+	if (!trace_cstate_enabled)
+		return;
+
+	it->state = level;
+	preempt_disable();
+	it->CPU = smp_processor_id();
+	data = tr->data[smp_processor_id()];
+
+	event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
+					 &irq_flags);
+	if (!event)
+		goto out;
+	entry	= ring_buffer_event_data(event);
+	tracing_generic_entry_update(&entry->ent, 0);
+	entry->ent.type = TRACE_BOOT;
+	entry->state_data = *it;
+	ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
+
+	trace_wake_up();
+
+ out:
+	preempt_enable();
+}
-- 
1.5.5.1


-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

[PATCH 2/2] cstate ftrace userland script

[Arjan van de Ven]

and here's a script to turn the cstate ftrace output into a nice SVG
that you can view with inkscape

#!/usr/bin/perl

# Copyright 2008, Intel Corporation
#
# This file is part of the Linux kernel
#
# This program file is free software; you can redistribute it and/or modify it
# under the terms of the GNU General Public License as published by the
# Free Software Foundation; version 2 of the License.
#
# This program is distributed in the hope that it will be useful, but WITHOUT
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
# for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program in a file named COPYING; if not, write to the
# Free Software Foundation, Inc.,
# 51 Franklin Street, Fifth Floor,
# Boston, MA 02110-1301 USA
#
# Authors:
# 	Arjan van de Ven <arjan@linux.intel.com>


#
# This script turns a cstate ftrace output into a SVG graphic that shows 
# historic C-state information
#
#
# 	cat /sys/kernel/debug/tracer/trace | perl cstate.pl > out.svg
#

my @rows;
my @styles;
my $base = 0;


$styles[0] = "fill:rgb(0,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[1] = "fill:rgb(0,255,0);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[2] = "fill:rgb(255,0,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[3] = "fill:rgb(255,255,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[4] = "fill:rgb(255,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[5] = "fill:rgb(0,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[6] = "fill:rgb(0,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[7] = "fill:rgb(0,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
$styles[8] = "fill:rgb(255,0,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
my $stylecounter = 0;


print "<?xml version=\"1.0\" standalone=\"no\"?> \n";
print "<svg width=\"10000\" height=\"100%\" version=\"1.1\" xmlns=\"http://www.w3.org/2000/svg\">\n";

my $scale = 30000.0;
while (<>) {
	my $line = $_;
	if ($line =~ /([0-9\.]+)\] Going to C([0-9]) on cpu ([0-9]+) for ([0-9\.]+)/) {
#	if ($line =~ /([0-9\.]+)\] Going to C([0-9]) /) {
		if ($base == 0) {
			$base = $1;
		}
		my $time = $1 - $base;	
		my $time = $time * $scale;
		my $C = $2;
		my $cpu = $3;
		my $y = 200 * $cpu;
		my $duration = $4 * $scale;
		my $msec = int($4 * 100000)/100.0;
		my $height = $C * 20;
		$style = $styles[$C];
		
		$y = $y + 140 - $height;
		
		$x2 = $time + 4;
		$y2 = $y + 4;


		print "<rect x=\"$time\" width=\"$duration\" y=\"$y\" height=\"$height\" style=\"$style\"/>\n";
		print "<text transform=\"translate($x2,$y2) rotate(90)\">C$C $msec</text>\n";
	}
}


print "</svg>\n";


-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Steven Rostedt]

Hi Arjan,

Very nice! I just have a few comments below.

On Fri, 3 Oct 2008, Arjan van de Ven wrote:
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index a921ba5..1ef1ded 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -117,6 +117,11 @@ struct trace_boot {
>  	struct boot_trace	initcall;
>  };
>  
> +struct trace_cstate {
> +	struct trace_entry	ent;
> +	struct cstate_trace	state_data;
> +};
> +

Can you please register this in the trace_assign_type macro.

	IF_ASSIGN(var, ent, struct trace_cstate, TRACE_BOOT); \



>  /*
>   * trace_flag_type is an enumeration that holds different
>   * states when a trace occurs. These are:
> diff --git a/kernel/trace/trace_cstate.c b/kernel/trace/trace_cstate.c
> new file mode 100644
> index 0000000..fcd4e6e
> --- /dev/null
> +++ b/kernel/trace/trace_cstate.c


> +static enum print_line_t cstate_print_line(struct trace_iterator *iter)
> +{
> +	int ret;
> +	struct trace_entry *entry = iter->ent;
> +	struct trace_cstate *field = (struct trace_cstate *)entry;

And here, do not typecast. Use the trace_assign_type macro below.

> +	struct cstate_trace *it = &field->state_data;
> +	struct trace_seq *s = &iter->seq;
> +	struct timespec stamp = ktime_to_timespec(it->stamp);

Also note that iter->ts holds a timestamp counter from bootup in nanosecs.
It currently uses the sched_clock to record, but may change later to 
something a bit better.

> +	struct timespec duration = ktime_to_timespec(
> +					ktime_sub(it->end, it->stamp));


	trace_assign_type(field, entry);

The above will do a typecheck to force correct types.

But, you may not need to do any of this. See below.

> +
> +	if (entry->type == TRACE_BOOT) {
> +		ret = trace_seq_printf(s, "[%5ld.%09ld] Going to C%i on cpu %i for %ld.%09ld\n",
> +					  stamp.tv_sec,
> +					  stamp.tv_nsec,
> +					  it->state, it->CPU,
> +					  duration.tv_sec,
> +					  duration.tv_nsec);
> +		if (!ret)
> +			return TRACE_TYPE_PARTIAL_LINE;
> +		return TRACE_TYPE_HANDLED;
> +	}
> +	return TRACE_TYPE_UNHANDLED;
> +}
> +
> +struct tracer cstate_tracer __read_mostly =
> +{
> +	.name		= "cstate",
> +	.init		= cstate_trace_init,
> +	.reset		= stop_cstate_trace,
> +	.ctrl_update	= cstate_trace_ctrl_update,
> +	.print_line	= cstate_print_line,

Here you bypass the print_line altogether. You really don't even need
to make a trace_cstate. You do not use any of the data in the entry field
so you can simply just store your cstate_trace data directly into the 
buffer.  The entry is only used for ftrace formatted prints.


> +};
> +
> +static int init_cstate_trace(void)
> +{
> +	return register_tracer(&cstate_tracer);
> +}
> +device_initcall(init_cstate_trace);
> +
> +void trace_cstate(struct cstate_trace *it, int level)
> +{
> +	struct ring_buffer_event *event;
> +	struct trace_cstate *entry;
> +	struct trace_array_cpu *data;
> +	unsigned long irq_flags;
> +	struct trace_array *tr = cstate_trace;
> +
> +	if (!trace_cstate_enabled)
> +		return;
> +
> +	it->state = level;
> +	preempt_disable();
> +	it->CPU = smp_processor_id();

You don't need to copy the smp_processor_id. Since all the buffers are
per_cpu, the cpu id is passed into your print_line via the iter
structure.

  iter->cpu is the cpu that this entry was recorded on.


> +	data = tr->data[smp_processor_id()];

You don't need the above 'data' structure, unless you want to use it
to prevent being reentrant. But you currently dont.

> +
> +	event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
> +					 &irq_flags);
> +	if (!event)
> +		goto out;
> +	entry	= ring_buffer_event_data(event);
> +	tracing_generic_entry_update(&entry->ent, 0);
> +	entry->ent.type = TRACE_BOOT;

It doesn't look like you use any of the trace_entry structure. You can 
just store your normal structure, since you bypass the output with you 
print_line function.

	struct cstate_trace *entry;

	[...]

	entry = ring_buffer_event_data(event);
	*entry = *it;
	ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
	

-- Steve

> +	entry->state_data = *it;
> +	ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
> +
> +	trace_wake_up();
> +
> + out:
> +	preempt_enable();
> +}
> -- 
> 1.5.5.1
> 
> 
> -- 
> Arjan van de Ven 	Intel Open Source Technology Centre
> For development, discussion and tips for power savings, 
> visit http://www.lesswatts.org
> 

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Arjan van de Ven]

On Fri, 3 Oct 2008 20:32:51 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Hi Arjan,
> 
> Very nice! I just have a few comments below.

since this is my first tracer.... I would suggest having a "golden
example" one that people can copy (it seems I copied a less than
perfect one ;-)... maybe a trace_example.c ?

I'll look into your comments tomorrow when I'm more awake.
-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Steven Rostedt]

On Fri, 3 Oct 2008, Arjan van de Ven wrote:

> On Fri, 3 Oct 2008 20:32:51 -0400 (EDT)
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > 
> > Hi Arjan,
> > 
> > Very nice! I just have a few comments below.
> 
> since this is my first tracer.... I would suggest having a "golden
> example" one that people can copy (it seems I copied a less than
> perfect one ;-)... maybe a trace_example.c ?

Yeah, that would make sense to have.  People are starting to come
up with so many different tracers, I'm not sure what a golden
example would look like :-/

Some of my comments came about just noticing what you did and realized
that there's other ways to do it. I didn't think about those other
ways until I looked at your code ;-)

> 
> I'll look into your comments tomorrow when I'm more awake.

I'll comment more when I'm more awake. But that may not be until Monday.
Putting in 16 hour days during the week, my wife puts her foot down and
keeps me away from the computer during the weekend.

-- Steve

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Fri, 3 Oct 2008, Arjan van de Ven wrote:
> 
> > On Fri, 3 Oct 2008 20:32:51 -0400 (EDT)
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > 
> > > Hi Arjan,
> > > 
> > > Very nice! I just have a few comments below.
> > 
> > since this is my first tracer.... I would suggest having a "golden
> > example" one that people can copy (it seems I copied a less than
> > perfect one ;-)... maybe a trace_example.c ?
> 
> Yeah, that would make sense to have.  People are starting to come
> up with so many different tracers, I'm not sure what a golden
> example would look like :-/

i think starting with kernel/trace/trace_nop.c is the simplest: copy 
that into a new plugin and make it show up in make oldconfig and make it 
build. Then add ftrace_printk() lines initially - only specialize the 
trace entries to that plugin later on.

	Ingo

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Arjan van de Ven]

On Fri, 3 Oct 2008 20:32:51 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:
> > +struct trace_cstate {
> > +	struct trace_entry	ent;
> > +	struct cstate_trace	state_data;
> > +};
> > +
> 
> Can you please register this in the trace_assign_type macro.
> 
> 	IF_ASSIGN(var, ent, struct trace_cstate, TRACE_BOOT); \

I don't see this anywhere in the kernel ;(

> And here, do not typecast. Use the trace_assign_type macro below.

nor that guy


> 
> > +	struct cstate_trace *it = &field->state_data;
> > +	struct trace_seq *s = &iter->seq;
> > +	struct timespec stamp = ktime_to_timespec(it->stamp);
> 
> Also note that iter->ts holds a timestamp counter from bootup in
> nanosecs. It currently uses the sched_clock to record, but may change
> later to something a bit better.

given that some of these clocks stop during idle... I really do care
about which timestamp is used, tracing idle with a clock that stops
during idle won't work too well.


-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: [PATCH] ftrace: Add a C-state tracer to help power optimization

[Steven Rostedt]

On Sat, 4 Oct 2008, Arjan van de Ven wrote:

> On Fri, 3 Oct 2008 20:32:51 -0400 (EDT)
> Steven Rostedt <rostedt@goodmis.org> wrote:
> > > +struct trace_cstate {
> > > +	struct trace_entry	ent;
> > > +	struct cstate_trace	state_data;
> > > +};
> > > +
> > 
> > Can you please register this in the trace_assign_type macro.
> > 
> > 	IF_ASSIGN(var, ent, struct trace_cstate, TRACE_BOOT); \
> 
> I don't see this anywhere in the kernel ;(
> 
> > And here, do not typecast. Use the trace_assign_type macro below.
> 
> nor that guy

The two should be in linux-tip. If you are based against mainline, then
no they will not be.

If you are already using linux-tip, try refreshing.


> 
> 
> > 
> > > +	struct cstate_trace *it = &field->state_data;
> > > +	struct trace_seq *s = &iter->seq;
> > > +	struct timespec stamp = ktime_to_timespec(it->stamp);
> > 
> > Also note that iter->ts holds a timestamp counter from bootup in
> > nanosecs. It currently uses the sched_clock to record, but may change
> > later to something a bit better.
> 
> given that some of these clocks stop during idle... I really do care
> about which timestamp is used, tracing idle with a clock that stops
> during idle won't work too well.
> 

OK, I just wanted to let you know about it.

-- Steve