Re: [git pull] ftrace for v2.6.27

[Bruce Duncan]

Hi Ingo, Steven, everyone,

[ Please CC me in replies ]

I have just tracked down a regression in 2.6.27-rc2 wrt 2.6.26. Commit 
77a2b37d227483fe52aead242652aee406c25bf0 (ftrace: startup tester on dynamic 
tracing.) causes my laptop to fail to resume from S3 (it simply reboots about 
a second after the resume starts and the display never shows anything).

The patch doesn't revert with patch -R (I don't know if there's a cleverer way 
to ask git to revert it), but the problem goes away if I turn off 
CONFIG_DYNAMIC_FTRACE.

The commit and bisect log are attached. Please can you help me to debug this?

Cheers,
Bruce
commit 77a2b37d227483fe52aead242652aee406c25bf0
Author: Steven Rostedt <srostedt@xxxxxxxxxx>
Date:   Mon May 12 21:20:45 2008 +0200

    ftrace: startup tester on dynamic tracing.
    
    This patch adds a startup self test on dynamic code modification
    and filters. The test filters on a specific function, makes sure that
    no other function is traced, exectutes the function, then makes sure that
    the function is traced.
    
    This patch also fixes a slight bug with the ftrace selftest, where
    tracer_enabled was not being set.
    
    Signed-off-by: Steven Rostedt <srostedt@xxxxxxxxxx>
    Signed-off-by: Ingo Molnar <mingo@xxxxxxx>
    Signed-off-by: Thomas Gleixner <tglx@xxxxxxxxxxxxx>

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 953a36d..a842d96 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -55,6 +55,7 @@ struct dyn_ftrace {
 };
 
 int ftrace_force_update(void);
+void ftrace_set_filter(unsigned char *buf, int len, int reset);
 
 /* defined in arch */
 extern int ftrace_ip_converted(unsigned long ip);
@@ -70,6 +71,7 @@ extern void ftrace_call(void);
 extern void mcount_call(void);
 #else
 # define ftrace_force_update() ({ 0; })
+# define ftrace_set_filter(buf, len, reset) do { } while (0)
 #endif
 
 static inline void tracer_disable(void)
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6d4d2e8..5e9389f 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -1010,6 +1010,25 @@ ftrace_filter_write(struct file *file, const char __user *ubuf,
 	return ret;
 }
 
+/**
+ * ftrace_set_filter - set a function to filter on in ftrace
+ * @buf - the string that holds the function filter text.
+ * @len - the length of the string.
+ * @reset - non zero to reset all filters before applying this filter.
+ *
+ * Filters denote which functions should be enabled when tracing is enabled.
+ * If @buf is NULL and reset is set, all functions will be enabled for tracing.
+ */
+notrace void ftrace_set_filter(unsigned char *buf, int len, int reset)
+{
+	mutex_lock(&ftrace_filter_lock);
+	if (reset)
+		ftrace_filter_reset();
+	if (buf)
+		ftrace_match(buf, len);
+	mutex_unlock(&ftrace_filter_lock);
+}
+
 static int notrace
 ftrace_filter_release(struct inode *inode, struct file *file)
 {
diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
index c01874c..4c8a1b2 100644
--- a/kernel/trace/trace_selftest.c
+++ b/kernel/trace/trace_selftest.c
@@ -99,6 +99,100 @@ static int trace_test_buffer(struct trace_array *tr, unsigned long *count)
 }
 
 #ifdef CONFIG_FTRACE
+
+#ifdef CONFIG_DYNAMIC_FTRACE
+
+#define DYN_FTRACE_TEST_NAME trace_selftest_dynamic_test_func
+#define __STR(x) #x
+#define STR(x) __STR(x)
+static int DYN_FTRACE_TEST_NAME(void)
+{
+	/* used to call mcount */
+	return 0;
+}
+
+/* Test dynamic code modification and ftrace filters */
+int trace_selftest_startup_dynamic_tracing(struct tracer *trace,
+					   struct trace_array *tr,
+					   int (*func)(void))
+{
+	unsigned long count;
+	int ret;
+	int save_ftrace_enabled = ftrace_enabled;
+	int save_tracer_enabled = tracer_enabled;
+
+	/* The ftrace test PASSED */
+	printk(KERN_CONT "PASSED\n");
+	pr_info("Testing dynamic ftrace: ");
+
+	/* enable tracing, and record the filter function */
+	ftrace_enabled = 1;
+	tracer_enabled = 1;
+
+	/* passed in by parameter to fool gcc from optimizing */
+	func();
+
+	/* update the records */
+	ret = ftrace_force_update();
+	if (ret) {
+		printk(KERN_CONT ".. ftraced failed .. ");
+		return ret;
+	}
+
+	/* filter only on our function */
+	ftrace_set_filter(STR(DYN_FTRACE_TEST_NAME),
+			  sizeof(STR(DYN_FTRACE_TEST_NAME)), 1);
+
+	/* enable tracing */
+	tr->ctrl = 1;
+	trace->init(tr);
+	/* Sleep for a 1/10 of a second */
+	msleep(100);
+
+	/* we should have nothing in the buffer */
+	ret = trace_test_buffer(tr, &count);
+	if (ret)
+		goto out;
+
+	if (count) {
+		ret = -1;
+		printk(KERN_CONT ".. filter did not filter .. ");
+		goto out;
+	}
+
+	/* call our function again */
+	func();
+
+	/* sleep again */
+	msleep(100);
+
+	/* stop the tracing. */
+	tr->ctrl = 0;
+	trace->ctrl_update(tr);
+	ftrace_enabled = 0;
+
+	/* check the trace buffer */
+	ret = trace_test_buffer(tr, &count);
+	trace->reset(tr);
+
+	/* we should only have one item */
+	if (!ret && count != 1) {
+		printk(KERN_CONT ".. filter failed ..");
+		ret = -1;
+		goto out;
+	}
+ out:
+	ftrace_enabled = save_ftrace_enabled;
+	tracer_enabled = save_tracer_enabled;
+
+	/* Enable tracing on all functions again */
+	ftrace_set_filter(NULL, 0, 1);
+
+	return ret;
+}
+#else
+# define trace_selftest_startup_dynamic_tracing(trace, tr, func) ({ 0; })
+#endif /* CONFIG_DYNAMIC_FTRACE */
 /*
  * Simple verification test of ftrace function tracer.
  * Enable ftrace, sleep 1/10 second, and then read the trace
@@ -109,8 +203,13 @@ trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
 {
 	unsigned long count;
 	int ret;
+	int save_ftrace_enabled = ftrace_enabled;
+	int save_tracer_enabled = tracer_enabled;
 
-	/* make sure functions have been recorded */
+	/* make sure msleep has been recorded */
+	msleep(1);
+
+	/* force the recorded functions to be traced */
 	ret = ftrace_force_update();
 	if (ret) {
 		printk(KERN_CONT ".. ftraced failed .. ");
@@ -119,6 +218,7 @@ trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
 
 	/* start the tracing */
 	ftrace_enabled = 1;
+	tracer_enabled = 1;
 
 	tr->ctrl = 1;
 	trace->init(tr);
@@ -136,8 +236,16 @@ trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
 	if (!ret && !count) {
 		printk(KERN_CONT ".. no entries found ..");
 		ret = -1;
+		goto out;
 	}
 
+	ret = trace_selftest_startup_dynamic_tracing(trace, tr,
+						     DYN_FTRACE_TEST_NAME);
+
+ out:
+	ftrace_enabled = save_ftrace_enabled;
+	tracer_enabled = save_tracer_enabled;
+
 	return ret;
 }
 #endif /* CONFIG_FTRACE */
@@ -415,6 +523,3 @@ trace_selftest_startup_sched_switch(struct tracer *trace, struct trace_array *tr
 	return ret;
 }
 #endif /* CONFIG_CONTEXT_SWITCH_TRACER */
-
-#ifdef CONFIG_DYNAMIC_FTRACE
-#endif /* CONFIG_DYNAMIC_FTRACE */
# bad: [6e86841d05f371b5b9b86ce76c02aaee83352298] Linux 2.6.27-rc1
# good: [bce7f793daec3e65ec5c5705d2457b81fe7b5725] Linux 2.6.26
git-bisect start 'v2.6.27-rc1' 'v2.6.26'
# bad: [d20b27478d6ccf7c4c8de4f09db2bdbaec82a6c0] V4L/DVB (8415): gspca: Infinite loop in i2c_w() of etoms.
git-bisect bad d20b27478d6ccf7c4c8de4f09db2bdbaec82a6c0
# bad: [666484f0250db2e016948d63b3ef33e202e3b8d0] Merge branch 'core/softirq' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
git-bisect bad 666484f0250db2e016948d63b3ef33e202e3b8d0
# good: [d59fdcf2ac501de99c3dfb452af5e254d4342886] Merge commit 'v2.6.26' into x86/core
git-bisect good d59fdcf2ac501de99c3dfb452af5e254d4342886
# good: [a3da5bf84a97d48cfaf66c6842470fc403da5121] Merge branch 'x86/for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
git-bisect good a3da5bf84a97d48cfaf66c6842470fc403da5121
# bad: [6712e299b7dc78aa4971b85e803435ee6d49a9dd] Merge branch 'tracing/ftrace' into auto-ftrace-next
git-bisect bad 6712e299b7dc78aa4971b85e803435ee6d49a9dd
# bad: [4823ed7eadf35e4b57ce581327e21d39585f1f32] ftrace: fix setting of pos in read_pipe
git-bisect bad 4823ed7eadf35e4b57ce581327e21d39585f1f32
# bad: [9ff9cdb2d3b0971f89e899b3420aadd91bddc215] ftrace: cleanups
git-bisect bad 9ff9cdb2d3b0971f89e899b3420aadd91bddc215
# good: [c7aafc549766b87819285d3480648fc652a47bc4] ftrace: cleanups
git-bisect good c7aafc549766b87819285d3480648fc652a47bc4
# skip: [f9896bf30928922a3913a3810a4ab7908da6cfe7] ftrace: add raw output
git-bisect skip f9896bf30928922a3913a3810a4ab7908da6cfe7
# skip: [8c523a9d82dbc4f3f7d972df8c0f1eacd83d0d55] ftrace: clean-up-pipe-iteration
git-bisect skip 8c523a9d82dbc4f3f7d972df8c0f1eacd83d0d55
# skip: [cb0f12aae8d085140d37ada351aa5a8e76c3f9b0] ftrace: bin-output
git-bisect skip cb0f12aae8d085140d37ada351aa5a8e76c3f9b0
# skip: [cdd31cd2d7a0dcbec2cce3974f7129dd4fc8c879] ftrace: remove-idx-sync
git-bisect skip cdd31cd2d7a0dcbec2cce3974f7129dd4fc8c879
# skip: [f0a920d5752e1788c0cba2add103076bcc0f7a49] ftrace: add trace_special()
git-bisect skip f0a920d5752e1788c0cba2add103076bcc0f7a49
# skip: [53c37c17aafcf50f7c6fddaf01dda8f9d7e31ddf] ftrace: fast, scalable, synchronized timestamps
git-bisect skip 53c37c17aafcf50f7c6fddaf01dda8f9d7e31ddf
# skip: [dcb6308f2b56720599f6b9d5a01c33e67e69bde4] ftrace, locking fix
git-bisect skip dcb6308f2b56720599f6b9d5a01c33e67e69bde4
# skip: [088b1e427dbba2af93cb6a7d39258c10ff58dd27] ftrace: pipe fixes
git-bisect skip 088b1e427dbba2af93cb6a7d39258c10ff58dd27
# bad: [750ed1a40783432d0dcb0e6c2e813a12615d7664] ftrace: timestamp syncing, prepare
git-bisect bad 750ed1a40783432d0dcb0e6c2e813a12615d7664
# bad: [1d4db00a5e30c7b8f8dc2a1b19e886fd942be143] ftrace: reset selftests
git-bisect bad 1d4db00a5e30c7b8f8dc2a1b19e886fd942be143
# bad: [4e3c3333f3bd7eedfd21b1155b3c7cd24fc7f754] ftrace: fix time offset
git-bisect bad 4e3c3333f3bd7eedfd21b1155b3c7cd24fc7f754
# bad: [77a2b37d227483fe52aead242652aee406c25bf0] ftrace: startup tester on dynamic tracing.
git-bisect bad 77a2b37d227483fe52aead242652aee406c25bf0
# good: [7bd2f24c2f769e3f8f1d4fc8b9fddf689825f6a7] ftrace: add README
git-bisect good 7bd2f24c2f769e3f8f1d4fc8b9fddf689825f6a7

Attachment: smime.p7s
Description: S/MIME cryptographic signature