Skip to contentSkip to conversation

ftrace: updates

PATCH Applied Steven Rostedt 2 participants 12 messages Jul 11, 2008

Subsystems (3)
Tracing ftrace Tracing OS noise / latency tracers
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

cover ftrace: updates

Working on the ftrace.txt file proved to show some bugs with ftrace. These are a list of patches that I have accumulated for ftrace that solve those bugs (as well as other things).

-- Steve

author maintainer
#1 lore raw

PATCH 1/8 ftrace: move sched_switch enable after markers

We have two markers now that are enabled on sched_switch. One that records the context switching and the other that records task wake ups. Currently we enable the tracing first and then set the markers. This causes some confusing traces:

# tracer: sched_switch
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |

       trace-cmd-3973  [00]   115.834817:   3973:120:R   +     3:  0:S
       trace-cmd-3973  [01]   115.834910:   3973:120:R   +     6:  0:S
       trace-cmd-3973  [02]   115.834910:   3973:120:R   +     9:  0:S
       trace-cmd-3973  [03]   115.834910:   3973:120:R   +    12:  0:S
       trace-cmd-3973  [02]   115.834910:   3973:120:R   +     9:  0:S
          <idle>-0     [02]   115.834910:      0:140:R ==>  3973:120:R

Here we see that trace-cmd with PID 3973 wakes up task 9 but the next line shows the idle task doing a context switch to task 3973.

Enabling the tracing to _after_ the markers are set creates a much saner output:

# tracer: sched_switch
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |

          <idle>-0     [02]  7922.634225:      0:140:R ==>  4790:120:R
       trace-cmd-4789  [03]  7922.634225:      0:140:R   +  4790:120:R
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_sched_switch.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace_sched_switch.c +2 -2
Index: linux-tip.git/kernel/trace/trace_sched_switch.c
===================================================================
@@ -227,14 +227,14 @@ void tracing_stop_cmdline_record(void)
 static void start_sched_trace(struct trace_array *tr)
 {
 	sched_switch_reset(tr);
-	tracer_enabled = 1;
 	tracing_start_cmdline_record();
+	tracer_enabled = 1;
 }
 
 static void stop_sched_trace(struct trace_array *tr)
 {
-	tracing_stop_cmdline_record();
 	tracer_enabled = 0;
+	tracing_stop_cmdline_record();
 }
 
 static void sched_switch_trace_init(struct trace_array *tr)
author maintainer
#2 lore raw

PATCH 2/8 ftrace: define function trace nop

In reply to Steven Rostedt

When CONFIG_FTRACE is not enabled, the tracing_start_functon_trace and tracing_stop_function_trace should be nops.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.h |   10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)
kernel/trace/trace.h +8 -2
Index: linux-tip.git/kernel/trace/trace.h
===================================================================
@@ -216,8 +216,6 @@ void trace_function(struct trace_array *
 		    unsigned long parent_ip,
 		    unsigned long flags);
 
-void tracing_start_function_trace(void);
-void tracing_stop_function_trace(void);
 void tracing_start_cmdline_record(void);
 void tracing_stop_cmdline_record(void);
 int register_tracer(struct tracer *type);

@@ -234,6 +232,14 @@ void update_max_tr_single(struct trace_a
 
 extern cycle_t ftrace_now(int cpu);
 
+#ifdef CONFIG_FTRACE
+void tracing_start_function_trace(void);
+void tracing_stop_function_trace(void);
+#else
+# define tracing_start_function_trace()		do { } while (0)
+# define tracing_stop_function_trace()		do { } while (0)
+#endif
+
 #ifdef CONFIG_CONTEXT_SWITCH_TRACER
 typedef void
 (*tracer_switch_func_t)(void *private,
author maintainer
#3 lore raw

PATCH 3/8 ftrace: trace schedule

In reply to Steven Rostedt

After the sched_clock code has been removed from sched.c we can now trace the scheduler. The scheduler has a lot of functions that would be worth tracing.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/Makefile |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/Makefile +1 -1
Index: linux-tip.git/kernel/Makefile
===================================================================
@@ -11,7 +11,7 @@ obj-y     = sched.o fork.o exec_domain.o
 	    hrtimer.o rwsem.o nsproxy.o srcu.o semaphore.o \
 	    notifier.o ksysfs.o pm_qos_params.o sched_clock.o
 
-CFLAGS_REMOVE_sched.o = -pg -mno-spe
+CFLAGS_REMOVE_sched.o = -mno-spe
 
 ifdef CONFIG_FTRACE
 # Do not trace debug files and internal ftrace files
author maintainer
#4 lore raw

PATCH 4/8 ftrace: check proper config for preempt type

In reply to Steven Rostedt

There is no CONFIG_PREEMPT_DESKTOP. Use the proper entry CONFIG_PREEMPT.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace.c +1 -1
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
@@ -1341,7 +1341,7 @@ print_trace_header(struct seq_file *m, s
 		   "server",
 #elif defined(CONFIG_PREEMPT_VOLUNTARY)
 		   "desktop",
-#elif defined(CONFIG_PREEMPT_DESKTOP)
+#elif defined(CONFIG_PREEMPT)
 		   "preempt",
 #else
 		   "unknown",
author maintainer
#5 lore raw

PATCH 5/8 ftrace: start wakeup tracing after setting function tracer

In reply to Steven Rostedt

Enabling the wakeup tracer before enabling the function tracing causes some strange results due to the dynamic enabling of the functions.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_sched_wakeup.c |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
kernel/trace/trace_sched_wakeup.c +2 -1
Index: linux-tip.git/kernel/trace/trace_sched_wakeup.c
===================================================================
@@ -352,9 +352,10 @@ static void start_wakeup_tracer(struct t
 	 */
 	smp_wmb();
 
-	tracer_enabled = 1;
 	register_ftrace_function(&trace_ops);
 
+	tracer_enabled = 1;
+
 	return;
 fail_deprobe_wake_new:
 	marker_probe_unregister("kernel_sched_wakeup_new",
author maintainer
#6 lore raw

PATCH 6/8 ftrace: use current CPU for function startup

In reply to Steven Rostedt

This is more of a clean up. Currently the function tracer initializes the tracer with which ever CPU was last used for tracing. This value isn't realy useful for function tracing, but at least it should be something other than a random number.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_functions.c |    3 +++
 1 file changed, 3 insertions(+)
kernel/trace/trace_functions.c +3 -0
Index: linux-tip.git/kernel/trace/trace_functions.c
===================================================================
@@ -28,7 +28,10 @@ static void function_reset(struct trace_
 
 static void start_function_trace(struct trace_array *tr)
 {
+	tr->cpu = get_cpu();
 	function_reset(tr);
+	put_cpu();
+
 	tracing_start_cmdline_record();
 	tracing_start_function_trace();
 }
author maintainer
#7 lore raw

PATCH 7/8 ftrace: add ftrace_kill_atomic

In reply to Steven Rostedt

It has been suggested that I add a way to disable the function tracer on an oops. This code adds a ftrace_kill_atomic. It is not meant to be used in normal situations. It will disable the ftrace tracer, but will not perform the nice shutdown that requires scheduling.

Signed-off-by Steven Rostedt <[email protected]>
---
 include/linux/ftrace.h |    1 +
 kernel/trace/ftrace.c  |   15 +++++++++++++++
 2 files changed, 16 insertions(+)
include/linux/ftrace.h +1 -0
Index: linux-tip.git/include/linux/ftrace.h
===================================================================
@@ -89,6 +89,7 @@ void ftrace_enable_daemon(void);
 
 /* totally disable ftrace - can not re-enable after this */
 void ftrace_kill(void);
+void ftrace_kill_atomic(void);
 
 static inline void tracer_disable(void)
 {
kernel/trace/ftrace.c +15 -0
Index: linux-tip.git/kernel/trace/ftrace.c
===================================================================
@@ -1602,6 +1602,21 @@ core_initcall(ftrace_dynamic_init);
 #endif /* CONFIG_DYNAMIC_FTRACE */
 
 /**
+ * ftrace_kill_atomic - kill ftrace from critical sections
+ *
+ * This function should be used by panic code. It stops ftrace
+ * but in a not so nice way. If you need to simply kill ftrace
+ * from a non-atomic section, use ftrace_kill.
+ */
+void ftrace_kill_atomic(void)
+{
+	ftrace_disabled = 1;
+	ftrace_enabled = 0;
+	ftraced_suspend = -1;
+	clear_ftrace_function();
+}
+
+/**
  * ftrace_kill - totally shutdown ftrace
  *
  * This is a safety measure. If something was detected that seems
author maintainer
#8 lore raw

PATCH 8/8 ftrace: separate out the function enabled variable

In reply to Steven Rostedt

Currently the function tracer uses the global tracer_enabled variable that is used to keep track if the tracer is enabled or not. The function tracing startup needs to be separated out, otherwise the internal happenings of the tracer startup is also recorded.

This patch creates a ftrace_function_enabled variable to all the starting of the function traces to happen after everything has been started.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.c |   22 +++++++++++++++++++---
 1 file changed, 19 insertions(+), 3 deletions(-)
kernel/trace/trace.c +19 -3
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
@@ -96,6 +96,9 @@ static DEFINE_PER_CPU(struct trace_array
 /* tracer_enabled is used to toggle activation of a tracer */
 static int			tracer_enabled = 1;
 
+/* function tracing enabled */
+int				ftrace_function_enabled;
+
 /*
  * trace_nr_entries is the number of entries that is allocated
  * for a buffer. Note, the number of entries is always rounded

@@ -134,6 +137,7 @@ static notrace void no_trace_init(struct
 {
 	int cpu;
 
+	ftrace_function_enabled = 0;
 	if(tr->ctrl)
 		for_each_online_cpu(cpu)
 			tracing_reset(tr->data[cpu]);

@@ -985,7 +989,7 @@ function_trace_call(unsigned long ip, un
 	long disabled;
 	int cpu;
 
-	if (unlikely(!tracer_enabled))
+	if (unlikely(!ftrace_function_enabled))
 		return;
 
 	if (skip_trace(ip))

@@ -1010,11 +1014,15 @@ static struct ftrace_ops trace_ops __rea
 
 void tracing_start_function_trace(void)
 {
+	ftrace_function_enabled = 0;
 	register_ftrace_function(&trace_ops);
+	if (tracer_enabled)
+		ftrace_function_enabled = 1;
 }
 
 void tracing_stop_function_trace(void)
 {
+	ftrace_function_enabled = 0;
 	unregister_ftrace_function(&trace_ops);
 }
 #endif

@@ -1850,8 +1858,10 @@ __tracing_open(struct inode *inode, stru
 		m->private = iter;
 
 		/* stop the trace while dumping */
-		if (iter->tr->ctrl)
+		if (iter->tr->ctrl) {
 			tracer_enabled = 0;
+			ftrace_function_enabled = 0;
+		}
 
 		if (iter->trace && iter->trace->open)
 			iter->trace->open(iter);

@@ -1884,8 +1894,14 @@ int tracing_release(struct inode *inode,
 		iter->trace->close(iter);
 
 	/* reenable tracing if it was previously enabled */
-	if (iter->tr->ctrl)
+	if (iter->tr->ctrl) {
 		tracer_enabled = 1;
+		/*
+		 * It is safe to enable function tracing even if it
+		 * isn't used
+		 */
+		ftrace_function_enabled = 1;
+	}
 	mutex_unlock(&trace_types_lock);
 
 	seq_release(inode, file);
Applied
#9 lore raw
In reply to Steven Rostedt
Quoted 3 lines · Steven Rostedt

Working on the ftrace.txt file proved to show some bugs with ftrace. These are a list of patches that I have accumulated for ftrace that solve those bugs (as well as other things).

applied them to tip/tracing/ftrace:

Steven Rostedt (8):
ftrace: move sched_switch enable after markers
ftrace: define function trace nop
ftrace: trace schedule
ftrace: check proper config for preempt type
ftrace: start wakeup tracing after setting function tracer
ftrace: use current CPU for function startup
ftrace: add ftrace_kill_atomic
ftrace: separate out the function enabled variable

thanks Steven!

Ingo

#10 lore raw
Quoted 8 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

Working on the ftrace.txt file proved to show some bugs with ftrace. These are a list of patches that I have accumulated for ftrace that solve those bugs (as well as other things).

applied them to tip/tracing/ftrace:

Quoted 9 lines

Steven Rostedt (8):
ftrace: move sched_switch enable after markers
ftrace: define function trace nop
ftrace: trace schedule
ftrace: check proper config for preempt type
ftrace: start wakeup tracing after setting function tracer
ftrace: use current CPU for function startup
ftrace: add ftrace_kill_atomic
ftrace: separate out the function enabled variable

found a build bug in testing - find the fix below.

Ingo

-------------->
commit b2613e370dbeb69edbff989382fa54f2395aa471

Author: Ingo Molnar <[email protected]>
Date:   Fri Jul 11 16:44:27 2008 +0200

ftrace: build fix for ftraced_suspend

fix:

kernel/trace/ftrace.c:1615: error: 'ftraced_suspend' undeclared (first use in this function) kernel/trace/ftrace.c:1615: error: (Each undeclared identifier is reported only once kernel/trace/ftrace.c:1615: error: for each function it appears in.)

Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/trace/ftrace.c |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)
kernel/trace/ftrace.c +2 -0
index 1359632..4231a3d 100644
@@ -1612,7 +1612,9 @@ void ftrace_kill_atomic(void)
 {
 	ftrace_disabled = 1;
 	ftrace_enabled = 0;
+#ifdef CONFIG_DYNAMIC_FTRACE
 	ftraced_suspend = -1;
+#endif
 	clear_ftrace_function();
 }