Skip to contentSkip to conversation

Add histograms of potential and effective wakeup latencies

PATCH In review Carsten Emde 2 participants 2 messages Sep 15, 2009

Subsystems (4)
Documentation Tracing Scheduler Tracing OS noise / latency tracers
lore
Share & tools
lore

Carsten Emde

author
#0 lore raw

PATCH 1/1 Add histograms of potential and effective wakeup latencies

Resuscitated and enhanced the kernel latency histograms provided originally by Yi Yang and adapted and converted by Steven Rostedt.

Latency histograms in the current version
- can be enabled online and independently
- have virtually no performance penalty when configured but not enabled
- have very little performance penalty when enabled
- use already available wakeup and switch tracepoints
- give corresponding results with the related tracer
- allow to record wakeup latency histograms of a single process
- record the process where the highest wakeup latency occurred
- are documented in Documentation/trace/histograms.txt

Signed-off-by Carsten Emde <[email protected]>
kernel/trace/Kconfig +48 -8
Index: linux-2.6.31-rc9-rt9.1/kernel/trace/Kconfig
===================================================================
@@ -167,6 +167,21 @@ config IRQSOFF_TRACER
 	  enabled. This option and the preempt-off timing option can be
 	  used together or separately.)
 
+config INTERRUPT_OFF_HIST
+	bool "Interrupts-off Latency Histogram"
+	depends on IRQSOFF_TRACER
+	help
+	  This option generates a continuously updated histogram (one per cpu)
+	  of the duration of time periods with interrupts disabled. The
+	  histogram is disabled by default. To enable it, write a non-zero
+	  number to the related file in
+
+	      /sys/kernel/debug/tracing/latency_hist/enable/preemptirqsoff
+
+	  If PREEMPT_OFF_HIST is also selected, an additional histogram (one
+	  per cpu) is generated that accumulates the duration of time periods
+	  when both interrupts and preemption are disabled.
+
 config PREEMPT_TRACER
 	bool "Preemption-off Latency Tracer"
 	default n

@@ -189,14 +204,20 @@ config PREEMPT_TRACER
 	  enabled. This option and the irqs-off timing option can be
 	  used together or separately.)
 
-config SYSPROF_TRACER
-	bool "Sysprof Tracer"
-	depends on X86
-	select GENERIC_TRACER
-	select CONTEXT_SWITCH_TRACER
-	help
-	  This tracer provides the trace needed by the 'Sysprof' userspace
-	  tool.
+config PREEMPT_OFF_HIST
+	bool "Preemption-off Latency Histogram"
+	depends on PREEMPT_TRACER
+	help
+	  This option generates a continuously updated histogram (one per cpu)
+	  of the duration of time periods with preemption disabled. The
+	  histogram is disabled by default. To enable it, write a non-zero
+	  number to
+
+	      /sys/kernel/debug/tracing/latency_hist/enable/preemptirqsoff
+
+	  If INTERRUPT_OFF_HIST is also selected, an additional histogram (one
+	  per cpu) is generated that accumulates the duration of time periods
+	  when both interrupts and preemption are disabled.
 
 config SCHED_TRACER
 	bool "Scheduling Latency Tracer"

@@ -207,6 +228,25 @@ config SCHED_TRACER
 	  This tracer tracks the latency of the highest priority task
 	  to be scheduled in, starting from the point it has woken up.
 
+config WAKEUP_LATENCY_HIST
+	bool "Scheduling Latency Histogram"
+	depends on SCHED_TRACER
+	help
+	  This option generates a continuously updated histogram (one per cpu)
+	  of the scheduling latency of the highest priority task. The histogram
+	  is disabled by default. To enable it, write a non-zero number to
+
+	      /sys/kernel/debug/tracing/latency_hist/enable/wakeup
+
+config SYSPROF_TRACER
+	bool "Sysprof Tracer"
+	depends on X86
+	select GENERIC_TRACER
+	select CONTEXT_SWITCH_TRACER
+	help
+	  This tracer provides the trace needed by the 'Sysprof' userspace
+	  tool.
+
 config ENABLE_DEFAULT_TRACERS
 	bool "Trace process context switches and events"
 	depends on !GENERIC_TRACER
kernel/trace/Makefile +3 -0
Index: linux-2.6.31-rc9-rt9.1/kernel/trace/Makefile
===================================================================
@@ -35,6 +35,9 @@ obj-$(CONFIG_FUNCTION_TRACER) += trace_f
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
+obj-$(CONFIG_INTERRUPT_OFF_HIST) += latency_hist.o
+obj-$(CONFIG_PREEMPT_OFF_HIST) += latency_hist.o
+obj-$(CONFIG_WAKEUP_LATENCY_HIST) += latency_hist.o
 obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
kernel/trace/trace_irqsoff.c +11 -0
Index: linux-2.6.31-rc9-rt9.1/kernel/trace/trace_irqsoff.c
===================================================================
@@ -17,6 +17,7 @@
 #include <linux/fs.h>
 
 #include "trace.h"
+#include <trace/events/hist.h>
 
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;

@@ -247,11 +248,13 @@ void start_critical_timings(void)
 {
 	if (preempt_trace() || irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+	trace_preemptirqsoff_hist(TRACE_START, 1);
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);
 
 void stop_critical_timings(void)
 {
+	trace_preemptirqsoff_hist(TRACE_STOP, 0);
 	if (preempt_trace() || irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }

@@ -261,6 +264,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings)
 #ifdef CONFIG_PROVE_LOCKING
 void time_hardirqs_on(unsigned long a0, unsigned long a1)
 {
+	trace_preemptirqsoff_hist(IRQS_ON, 0);
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(a0, a1);
 }

@@ -269,6 +273,7 @@ void time_hardirqs_off(unsigned long a0,
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(a0, a1);
+	trace_preemptirqsoff_hist(IRQS_OFF, 1);
 }
 
 #else /* !CONFIG_PROVE_LOCKING */

@@ -302,6 +307,7 @@ inline void print_irqtrace_events(struct
  */
 void trace_hardirqs_on(void)
 {
+	trace_preemptirqsoff_hist(IRQS_ON, 0);
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }

@@ -311,11 +317,13 @@ void trace_hardirqs_off(void)
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+	trace_preemptirqsoff_hist(IRQS_OFF, 1);
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+	trace_preemptirqsoff_hist(IRQS_ON, 0);
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(CALLER_ADDR0, caller_addr);
 }

@@ -325,6 +333,7 @@ void trace_hardirqs_off_caller(unsigned 
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(CALLER_ADDR0, caller_addr);
+	trace_preemptirqsoff_hist(IRQS_OFF, 1);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);
 

@@ -334,12 +343,14 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller)
 #ifdef CONFIG_PREEMPT_TRACER
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
+	trace_preemptirqsoff_hist(PREEMPT_ON, 0);
 	if (preempt_trace())
 		stop_critical_timing(a0, a1);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
+	trace_preemptirqsoff_hist(PREEMPT_OFF, 1);
 	if (preempt_trace())
 		start_critical_timing(a0, a1);
 }
init/main.c +8 -2
Index: linux-2.6.31-rc9-rt9.1/init/main.c
===================================================================
@@ -936,7 +936,7 @@ static int __init kernel_init(void * unu
 	WARN_ON(irqs_disabled());
 #endif
 
-#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + defined(CONFIG_STACK_TRACER) + defined(CONFIG_WAKEUP_LATENCY_HIST) + defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + defined(CONFIG_LOCKDEP) + (defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD)))
+#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + defined(CONFIG_STACK_TRACER) + defined(CONFIG_INTERRUPT_OFF_HIST) + defined(CONFIG_PREEMPT_OFF_HIST) + defined(CONFIG_WAKEUP_LATENCY_HIST) + defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + defined(CONFIG_LOCKDEP) + (defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD)))
 
 #if DEBUG_COUNT > 0
 	printk(KERN_ERR "*****************************************************************************\n");

@@ -956,9 +956,15 @@ static int __init kernel_init(void * unu
 #ifdef CONFIG_PREEMPT_TRACER
 	printk(KERN_ERR "*        CONFIG_PREEMPT_TRACER                                              *\n");
 #endif
-#ifdef CONFIG_FTRACE
+#if defined(CONFIG_FTRACE) && !defined(CONFIG_FTRACE_MCOUNT_RECORD)
 	printk(KERN_ERR "*        CONFIG_FTRACE                                                      *\n");
 #endif
+#ifdef CONFIG_INTERRUPT_OFF_HIST
+	printk(KERN_ERR "*        CONFIG_INTERRUPT_OFF_HIST                                          *\n");
+#endif
+#ifdef CONFIG_PREEMPT_OFF_HIST
+	printk(KERN_ERR "*        CONFIG_PREEMPT_OFF_HIST                                            *\n");
+#endif
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 	printk(KERN_ERR "*        CONFIG_WAKEUP_LATENCY_HIST                                         *\n");
 #endif
kernel/sched.c +5 -0
Index: linux-2.6.31-rc9-rt9.1/kernel/sched.c
===================================================================
@@ -717,6 +717,11 @@ struct rq {
 #endif
 };
 
+struct task_struct *rq_curr(struct rq *rq)
+{
+	return rq->curr;
+}
+
 static DEFINE_PER_CPU_SHARED_ALIGNED(struct rq, runqueues);
 
 static inline void check_preempt_curr(struct rq *rq, struct task_struct *p, int sync)
kernel/trace/latency_hist.c new file +822 -0

822 lines not on this page · raw message

Documentation/trace/histograms.txt new file +156 -0

156 lines not on this page · raw message

include/trace/events/hist.h new file +37 -0
Index: linux-2.6.31-rc9-rt9.1/include/trace/events/hist.h
===================================================================
@@ -0,0 +1,37 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM hist
+
+#if !defined(_TRACE_HIST_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_HIST_H
+
+#include "latency_hist.h"
+#include <linux/tracepoint.h>
+
+#if !defined(CONFIG_PREEMPT_OFF_HIST) && !defined(CONFIG_INTERRUPT_OFF_HIST)
+#define trace_preemptirqsoff_hist(a,b)
+#else
+TRACE_EVENT(preemptirqsoff_hist,
+
+	TP_PROTO(int reason, int starthist),
+
+	TP_ARGS(reason, starthist),
+
+	TP_STRUCT__entry(
+		__field(	int,	reason	)
+		__field(	int,	starthist	)
+	),
+
+	TP_fast_assign(
+		__entry->reason		= reason;
+		__entry->starthist	= starthist;
+	),
+
+	TP_printk("reason=%s starthist=%s", getaction(__entry->reason),
+		  __entry->starthist ? "start" : "stop")
+);
+#endif
+
+#endif /* _TRACE_HIST_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
include/trace/events/latency_hist.h new file +30 -0
Index: linux-2.6.31-rc9-rt9.1/include/trace/events/latency_hist.h
===================================================================
@@ -0,0 +1,30 @@
+#ifndef _LATENCY_HIST_H
+#define _LATENCY_HIST_H
+
+enum hist_action {
+	IRQS_ON,
+	PREEMPT_ON,
+	TRACE_STOP,
+	IRQS_OFF,
+	PREEMPT_OFF,
+	TRACE_START,
+};
+
+static char *actions[] = {
+	"IRQS_ON",
+	"PREEMPT_ON",
+	"TRACE_STOP",
+	"IRQS_OFF",
+	"PREEMPT_OFF",
+	"TRACE_START",
+};
+
+static inline char *getaction(int action)
+{
+	if (action >= 0 && action <= sizeof(actions)/sizeof(actions[0]))
+		return(actions[action]);
+	return("unknown");
+}
+
+#endif /* _LATENCY_HIST_H */
+
include/linux/sched.h +1 -0
Index: linux-2.6.31-rc9-rt9.1/include/linux/sched.h
===================================================================
@@ -1969,6 +1969,7 @@ extern int sched_setscheduler_nocheck(st
 extern struct task_struct *idle_task(int cpu);
 extern struct task_struct *curr_task(int cpu);
 extern void set_curr_task(int cpu, struct task_struct *p);
+extern struct task_struct *rq_curr(struct rq *rq);
 
 void yield(void);
 void __yield(void);
maintainer Acked-by on v1 1/1
#1 lore raw
Quoted 13 lines · Carsten Emde

Resuscitated and enhanced the kernel latency histograms provided originally by Yi Yang and adapted and converted by Steven Rostedt.

Latency histograms in the current version
- can be enabled online and independently
- have virtually no performance penalty when configured but not enabled
- have very little performance penalty when enabled
- use already available wakeup and switch tracepoints
- give corresponding results with the related tracer
- allow to record wakeup latency histograms of a single process
- record the process where the highest wakeup latency occurred
- are documented in Documentation/trace/histograms.txt

Quoted 1 line
Signed-off-by Carsten Emde <[email protected]>

I did a quick scan of the patch and this looks much nicer.

Good work!

Acked-by Steven Rostedt <[email protected]>

-- Steve