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

PATCH In review Arjan van de Ven 4 participants 6 messages Oct 4, 2008 – Oct 6, 2008

Subsystems (3)

x86 Tracing ftrace

lore

Share & tools

lore

Arjan van de Ven

author

2008-10-04 17:55 UTC #0 lore raw

PATCH v2 1/1 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.

An example way of using this is:
mount -t debugfs none /sys/kernel/debug
echo cstate > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_enabled
sleep 1
echo 0 > /sys/kernel/debug/tracing/tracing_enabled
cat /sys/kernel/debug/tracing/trace | perl scripts/trace/cstate.pl > out.svg

Signed-off-by Arjan van de Ven <[email protected]>

---
 arch/x86/kernel/process.c   |   15 +++++
 include/linux/ftrace.h      |   14 +++++
 kernel/trace/Kconfig        |   11 ++++
 kernel/trace/Makefile       |    1 +
 kernel/trace/trace.h        |    5 ++
 kernel/trace/trace_cstate.c |  131 +++++++++++++++++++++++++++++++++++++++++++
 scripts/trace/cstate.pl     |   84 +++++++++++++++++++++++++++
 7 files changed, 261 insertions(+), 0 deletions(-)
 create mode 100644 kernel/trace/trace_cstate.c
 create mode 100644 scripts/trace/cstate.pl

arch/x86/kernel/process.c +15 -0

index 3468131..9733ef4 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,9 @@ static inline int hlt_use_halt(void)
 void default_idle(void)
 {
 	if (hlt_use_halt()) {
+		struct cstate_trace it;
+
+		trace_cstate_start(&it, 1);
 		current_thread_info()->status &= ~TS_POLLING;
 		/*
 		 * TS_POLLING-cleared state must be visible before we

@@ -112,6 +116,7 @@ void default_idle(void)
 		else
 			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
+		trace_cstate_end(&it);
 	} else {
 		local_irq_enable();
 		/* loop is done by the caller */

@@ -154,24 +159,31 @@ EXPORT_SYMBOL_GPL(cpu_idle_wait);
  */
 void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
 {
+	struct cstate_trace it;
+
+	trace_cstate_start(&it, (ax>>4)+1);
 	if (!need_resched()) {
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
 			__mwait(ax, cx);
 	}
+	trace_cstate_end(&it);
 }
 
 /* Default MONITOR/MWAIT with no hints, used for default C1 state */
 static void mwait_idle(void)
 {
+	struct cstate_trace it;
 	if (!need_resched()) {
+		trace_cstate_start(&it, 1);
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
 			__sti_mwait(0, 0);
 		else
 			local_irq_enable();
+		trace_cstate_end(&it);
 	} else
 		local_irq_enable();
 }

@@ -183,9 +195,12 @@ static void mwait_idle(void)
  */
 static void poll_idle(void)
 {
+	struct cstate_trace it;
+	trace_cstate_start(&it, 0);
 	local_irq_enable();
 	while (!need_resched())
 		cpu_relax();
+	trace_cstate_end(&it);
 }
 
 /*

include/linux/ftrace.h +14 -0

index 91954eb..184365c 100644
@@ -226,6 +226,20 @@ 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;
+};
+
+#ifdef CONFIG_CSTATE_TRACER
+extern void trace_cstate_start(struct cstate_trace *it, unsigned int state);
+extern void trace_cstate_end(struct cstate_trace *it);
+#else
+static inline void trace_cstate_start(struct cstate_trace *it, int state) { }
+static inline void trace_cstate_end(struct cstate_trace *it) { }
+#endif
+
 
 
 #endif /* _LINUX_FTRACE_H */

kernel/trace/Kconfig +11 -0

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

kernel/trace/Makefile +1 -0

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

kernel/trace/trace.h +5 -0

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:

kernel/trace/trace_cstate.c new file +131 -0

131 lines not on this page · raw message

scripts/trace/cstate.pl new file +84 -0

84 lines not on this page · raw message

Signature · 7 lines

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

Steven Rostedt

maintainer

2008-10-04 18:17 UTC #1 lore raw

My comments are more towards Ingo than to Arjan.

kernel/trace/Kconfig config BOOT_TRACER · line 139

Quoted 8 lines · Arjan van de Ven

+++ b/kernel/trace/Kconfig

kernel/trace/Kconfig +3 -0

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

Ingo, here's the confusion again between the FTRACE infrastructure and the ftrace "function tracer". the HAVE_FTRACE should really be HAVE_FUNCTION_TRACER. The infrastructure of a lot of the ftrace tracers do not depend on the function tracer.

The CSTATE_TRACER also does not depend on HAVE_FTRACE. Think we should rename this? Otherwise more kernel developers will get confused by it. :-(

Quoted 90 lines

kernel/trace/Kconfig +8 -0

+	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

kernel/trace/Makefile +1 -0

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

kernel/trace/trace.h +5 -0

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:

kernel/trace/trace_cstate.c new file +46 -0

new file mode 100644
index 0000000..272c577
@@ -0,0 +1,131 @@
+/*
+ * ring buffer based C-state tracer
+ *
+ * Arjan van de Ven <[email protected]>
+ * Copyright (C) 2009 Intel Corporation
+ *
+ * Much is borrowed from trace_boot.c which is
+ * Copyright (C) 2008 Frederic Weisbecker <[email protected]>
+ *
+ */
+
+#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;
+
+
+static void start_cstate_trace(void)
+{
+	trace_cstate_enabled = 1;
+}
+
+static 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)

kernel/trace/trace_cstate.c line 56

Quoted 10 lines

kernel/trace/trace_cstate.c new file +10 -0

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

Ingo, isn't the trace_assign_type in your latest tree?

-- Steve

Quoted 20 lines

kernel/trace/trace_cstate.c new file +20 -0

+	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, iter->cpu,
+					  duration.tv_sec,
+					  duration.tv_nsec);
+		if (!ret)
+			return TRACE_TYPE_PARTIAL_LINE;
+		return TRACE_TYPE_HANDLED;
+	}
+	return TRACE_TYPE_UNHANDLED;
+}
+

Arjan van de Ven

author

2008-10-04 18:29 UTC #2 lore raw

Quoted 3 lines · On Sat, 4 Oct 2008 14:17:47 -0400 (EDT) Steven Rostedt <[email protected]>…

Review
Quoted 1 line
(quoted diff) +1 -0
+	struct trace_cstate *field = (struct trace_cstate *)entry;
Ingo, isn't the trace_assign_type in your latest tree?

like this?

From: Arjan van de Ven <[email protected]>
Date: Fri, 3 Oct 2008 10:18:21 -0700
Subject: [PATCH v3] ftrace: Add a C-state tracer to help power optimization

Signed-off-by Arjan van de Ven <[email protected]>

---
 arch/x86/kernel/process.c   |   15 +++++
 include/linux/ftrace.h      |   14 +++++
 kernel/trace/Kconfig        |   10 +++
 kernel/trace/Makefile       |    1 +
 kernel/trace/trace.h        |    7 ++
 kernel/trace/trace_cstate.c |  135 +++++++++++++++++++++++++++++++++++++++++++
 scripts/trace/cstate.pl     |   84 +++++++++++++++++++++++++++
 7 files changed, 266 insertions(+), 0 deletions(-)
 create mode 100644 kernel/trace/trace_cstate.c
 create mode 100644 scripts/trace/cstate.pl

arch/x86/kernel/process.c +15 -0

index 3468131..9733ef4 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,9 @@ static inline int hlt_use_halt(void)
 void default_idle(void)
 {
 	if (hlt_use_halt()) {
+		struct cstate_trace it;
+
+		trace_cstate_start(&it, 1);
 		current_thread_info()->status &= ~TS_POLLING;
 		/*
 		 * TS_POLLING-cleared state must be visible before we

@@ -112,6 +116,7 @@ void default_idle(void)
 		else
 			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
+		trace_cstate_end(&it);
 	} else {
 		local_irq_enable();
 		/* loop is done by the caller */

@@ -154,24 +159,31 @@ EXPORT_SYMBOL_GPL(cpu_idle_wait);
  */
 void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
 {
+	struct cstate_trace it;
+
+	trace_cstate_start(&it, (ax>>4)+1);
 	if (!need_resched()) {
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
 			__mwait(ax, cx);
 	}
+	trace_cstate_end(&it);
 }
 
 /* Default MONITOR/MWAIT with no hints, used for default C1 state */
 static void mwait_idle(void)
 {
+	struct cstate_trace it;
 	if (!need_resched()) {
+		trace_cstate_start(&it, 1);
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
 			__sti_mwait(0, 0);
 		else
 			local_irq_enable();
+		trace_cstate_end(&it);
 	} else
 		local_irq_enable();
 }

@@ -183,9 +195,12 @@ static void mwait_idle(void)
  */
 static void poll_idle(void)
 {
+	struct cstate_trace it;
+	trace_cstate_start(&it, 0);
 	local_irq_enable();
 	while (!need_resched())
 		cpu_relax();
+	trace_cstate_end(&it);
 }
 
 /*

include/linux/ftrace.h +14 -0

index 5812dba..fc477aa 100644
@@ -232,6 +232,20 @@ static inline void start_boot_trace(void) { }
 static inline void stop_boot_trace(void) { }
 #endif
 
+struct cstate_trace {
+	ktime_t			stamp;
+	ktime_t			end;
+	int			state;
+};
+
+#ifdef CONFIG_CSTATE_TRACER
+extern void trace_cstate_start(struct cstate_trace *it, unsigned int state);
+extern void trace_cstate_end(struct cstate_trace *it);
+#else
+static inline void trace_cstate_start(struct cstate_trace *it, int state) { }
+static inline void trace_cstate_end(struct cstate_trace *it) { }
+#endif
+
 
 
 #endif /* _LINUX_FTRACE_H */

kernel/trace/Kconfig +10 -0

index 396aea1..92f91ae 100644
@@ -134,6 +134,16 @@ 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 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

kernel/trace/Makefile +1 -0

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

kernel/trace/trace.h +7 -0

index f1f9957..06363df 100644
@@ -22,6 +22,7 @@ enum trace_type {
 	TRACE_MMIO_RW,
 	TRACE_MMIO_MAP,
 	TRACE_BOOT,
+	TRACE_CSTATE,
 
 	__TRACE_LAST_TYPE
 };

@@ -117,6 +118,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:

@@ -217,6 +223,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_map,		\
 			  TRACE_MMIO_MAP);				\
 		IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT);	\
+		IF_ASSIGN(var, ent, struct trace_cstate, TRACE_CSTATE); \
 		__ftrace_bad_type();					\
 	} while (0)

kernel/trace/trace_cstate.c new file +135 -0

135 lines not on this page · raw message

scripts/trace/cstate.pl new file +84 -0

84 lines not on this page · raw message

Signature · 1 line

1.5.5.1

Peter Zijlstra

2008-10-06 16:52 UTC #3 lore raw

Quoted 30 lines · Arjan van de Ven

arch/x86/kernel/process.c +11 -0

@@ -100,6 +101,9 @@ static inline int hlt_use_halt(void)
 void default_idle(void)
 {
 	if (hlt_use_halt()) {
+		struct cstate_trace it;
+
+		trace_cstate_start(&it, 1);
 		current_thread_info()->status &= ~TS_POLLING;
 		/*
 		 * TS_POLLING-cleared state must be visible before we

@@ -112,6 +116,7 @@ void default_idle(void)
 		else
 			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
+		trace_cstate_end(&it);
 	} else {
 		local_irq_enable();
 		/* loop is done by the caller */

@@ -232,6 +232,20 @@ static inline void start_boot_trace(void) { }
 static inline void stop_boot_trace(void) { }
 #endif
 
+struct cstate_trace {
+	ktime_t			stamp;
+	ktime_t			end;
+	int			state;
+};
+
+#ifdef CONFIG_CSTATE_TRACER

arch/x86/kernel/process.c static inline void start_boot_trace(void) { } · line 251

Quoted 10 lines

arch/x86/kernel/process.c +7 -0

+extern void trace_cstate_start(struct cstate_trace *it, unsigned int state);
+extern void trace_cstate_end(struct cstate_trace *it);
+#else
+static inline void trace_cstate_start(struct cstate_trace *it, int state) { }
+static inline void trace_cstate_end(struct cstate_trace *it) { }
+#endif
+
 
 
 #endif /* _LINUX_FTRACE_H */

Why have the cstate_trace structure? If you just log start, stop you could compute the time delta from the trace time stamps, no?

If you decide to keep the structure, perhaps declare it empty for ! CONFIG_CSTATE_TRACER so as to not bloat stack usage when its not configured.

Arjan van de Ven

author

2008-10-06 16:57 UTC #4 lore raw

Quoted 6 lines · On Mon, 06 Oct 2008 18:52:39 +0200 Peter Zijlstra <[email protected]>…

Quoted 3 lines
#endif /* _LINUX_FTRACE_H */
Why have the cstate_trace structure? If you just log start, stop you could compute the time delta from the trace time stamps, no?

there's 2 other fields I need than just the timestamp.

Quoted 4 lines

If you decide to keep the structure, perhaps declare it empty for ! CONFIG_CSTATE_TRACER so as to not bloat stack usage when its not configured.

ok good point

Quoted 1 line

Signature · 3 lines

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

Ingo Molnar

2008-10-05 09:53 UTC #5 lore raw

In reply to Steven Rostedt

Quoted 18 lines · Steven Rostedt

My comments are more towards Ingo than to Arjan.
kernel/trace/Kconfig config BOOT_TRACER · line 139
Quoted 8 lines · Arjan van de Ven
+++ b/kernel/trace/Kconfig
kernel/trace/Kconfig +3 -0
@@ -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
Ingo, here's the confusion again between the FTRACE infrastructure and the ftrace "function tracer". the HAVE_FTRACE should really be HAVE_FUNCTION_TRACER. The infrastructure of a lot of the ftrace tracers do not depend on the function tracer.

Quoted 3 lines

The CSTATE_TRACER also does not depend on HAVE_FTRACE. Think we should rename this? Otherwise more kernel developers will get confused by it. :-(

agreed, please send a rename patch to make it more consistent.

Quoted 7 lines

kernel/trace/trace_cstate.c line 56
Quoted 5 lines
kernel/trace/trace_cstate.c new file +5 -0
+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;
Ingo, isn't the trace_assign_type in your latest tree?

yeah, it is, and it should be used here instead of a direct cast.

Ingo