Re: [git pull] ftrace for v2.6.27

!MAILaRCHIVE_VOTE_RePLACE
Previous message: [thread] [date] [author]
Next message: [thread] [date] [author]
To: Ingo Molnar <mingo@...>, <linux-kernel@...>, Steven Rostedt <srostedt@...>
Date: Tuesday, August 12, 2008 - 9:48 pm

--Boundary-01=_G2joIBnNKNSB6T8
Content-Type: text/plain;
  charset="ansi_x3.4-1968"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline

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=20
77a2b37d227483fe52aead242652aee406c25bf0 (ftrace: startup tester on dynamic=
=20
tracing.) causes my laptop to fail to resume from S3 (it simply reboots abo=
ut=20
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=20
to ask git to revert it), but the problem goes away if I turn off=20
CONFIG_DYNAMIC_FTRACE.

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

Cheers,
Bruce

--Boundary-01=_G2joIBnNKNSB6T8
Content-Type: text/plain;
  charset="iso 8859-15";
  name="bad-commit.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
	filename="bad-commit.txt"

commit 77a2b37d227483fe52aead242652aee406c25bf0
Author: Steven Rostedt <srostedt@redhat.com>
Date:   Mon May 12 21:20:45 2008 +0200

    ftrace: startup tester on dynamic tracing.
   =20
    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 th=
at
    the function is traced.
   =20
    This patch also fixes a slight bug with the ftrace selftest, where
    tracer_enabled was not being set.
   =20
    Signed-off-by: Steven Rostedt <srostedt@redhat.com>
    Signed-off-by: Ingo Molnar <mingo@elte.hu>
    Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 953a36d..a842d96 100644
=2D-- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -55,6 +55,7 @@ struct dyn_ftrace {
 };
=20
 int ftrace_force_update(void);
+void ftrace_set_filter(unsigned char *buf, int len, int reset);
=20
 /* 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
=20
 static inline void tracer_disable(void)
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6d4d2e8..5e9389f 100644
=2D-- 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;
 }
=20
+/**
+ * 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 enable=
d.
+ * If @buf is NULL and reset is set, all functions will be enabled for tra=
cing.
+ */
+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
=2D-- 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, un=
signed long *count)
 }
=20
 #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 =3D ftrace_enabled;
+	int save_tracer_enabled =3D 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 =3D 1;
+	tracer_enabled =3D 1;
+
+	/* passed in by parameter to fool gcc from optimizing */
+	func();
+
+	/* update the records */
+	ret =3D 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 =3D 1;
+	trace->init(tr);
+	/* Sleep for a 1/10 of a second */
+	msleep(100);
+
+	/* we should have nothing in the buffer */
+	ret =3D trace_test_buffer(tr, &count);
+	if (ret)
+		goto out;
+
+	if (count) {
+		ret =3D -1;
+		printk(KERN_CONT ".. filter did not filter .. ");
+		goto out;
+	}
+
+	/* call our function again */
+	func();
+
+	/* sleep again */
+	msleep(100);
+
+	/* stop the tracing. */
+	tr->ctrl =3D 0;
+	trace->ctrl_update(tr);
+	ftrace_enabled =3D 0;
+
+	/* check the trace buffer */
+	ret =3D trace_test_buffer(tr, &count);
+	trace->reset(tr);
+
+	/* we should only have one item */
+	if (!ret && count !=3D 1) {
+		printk(KERN_CONT ".. filter failed ..");
+		ret =3D -1;
+		goto out;
+	}
+ out:
+	ftrace_enabled =3D save_ftrace_enabled;
+	tracer_enabled =3D 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 =3D ftrace_enabled;
+	int save_tracer_enabled =3D tracer_enabled;
=20
=2D	/* make sure functions have been recorded */
+	/* make sure msleep has been recorded */
+	msleep(1);
+
+	/* force the recorded functions to be traced */
 	ret =3D ftrace_force_update();
 	if (ret) {
 		printk(KERN_CONT ".. ftraced failed .. ");
@@ -119,6 +218,7 @@ trace_selftest_startup_function(struct tracer *trace, s=
truct trace_array *tr)
=20
 	/* start the tracing */
 	ftrace_enabled =3D 1;
+	tracer_enabled =3D 1;
=20
 	tr->ctrl =3D 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 =3D -1;
+		goto out;
 	}
=20
+	ret =3D trace_selftest_startup_dynamic_tracing(trace, tr,
+						     DYN_FTRACE_TEST_NAME);
+
+ out:
+	ftrace_enabled =3D save_ftrace_enabled;
+	tracer_enabled =3D save_tracer_enabled;
+
 	return ret;
 }
 #endif /* CONFIG_FTRACE */
@@ -415,6 +523,3 @@ trace_selftest_startup_sched_switch(struct tracer *trac=
e, struct trace_array *tr
 	return ret;
 }
 #endif /* CONFIG_CONTEXT_SWITCH_TRACER */
=2D
=2D#ifdef CONFIG_DYNAMIC_FTRACE
=2D#endif /* CONFIG_DYNAMIC_FTRACE */

--Boundary-01=_G2joIBnNKNSB6T8
Content-Type: text/x-log;
  charset="iso 8859-15";
  name="bisect.log"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
	filename="bisect.log"

# 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

--Boundary-01=_G2joIBnNKNSB6T8--
Previous message: [thread] [date] [author]
Next message: [thread] [date] [author]

Messages in current thread:
[git pull] ftrace for v2.6.27, Ingo Molnar, (Mon Jul 14, 10:22 am)
Re: [git pull] ftrace for v2.6.27, Bruce Duncan, (Tue Aug 12, 9:48 pm)
Re: [git pull] ftrace for v2.6.27, Steven Rostedt, (Wed Aug 13, 1:15 pm)
Re: [git pull] ftrace for v2.6.27, Bruce Duncan, (Wed Aug 13, 2:08 pm)
Re: [git pull] ftrace for v2.6.27, Ingo Molnar, (Fri Aug 15, 5:29 am)
Re: [git pull] ftrace for v2.6.27, Steven Rostedt, (Wed Aug 13, 11:11 am)
Re: [git pull] ftrace for v2.6.27, Ingo Molnar, (Wed Aug 13, 11:18 am)
Re: [git pull] ftrace for v2.6.27, Andi Kleen, (Wed Aug 13, 3:53 pm)
Re: [git pull] ftrace for v2.6.27, Ingo Molnar, (Wed Aug 13, 3:19 am)