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

From: Arjan van de Ven <[email protected]>
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.

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

index 3468131..68c7234 100644
@@ -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 */

index 91954eb..e6b4da6 100644
@@ -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 */

index 396aea1..fa2347a 100644
@@ -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

index a85dfba..2b85724 100644
@@ -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

index a921ba5..1ef1ded 100644
@@ -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:

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

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 <[email protected]>

#
# 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

Hi Arjan,

Very nice! I just have a few comments below.

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

	trace_assign_type(field, entry);

	struct cstate_trace *entry;

	[...]

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

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

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

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

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

nor that guy

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

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.

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

-- Steve