WARNING at __ftrace_hash_rec_update()

WARNING at __ftrace_hash_rec_update()

[Rabin Vincent]

On v3.1-7810-g094803e (current linus git), I'm able to trigger the below
FTRACE_WARN_ON() by running the following sequence of commands.
DYNAMIC_FTRACE is enabled.

ftrace.c:1384:
	if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
		return;
	rec->flags--;

$ mount -t debugfs nodev /debug
$ cd /debug/tracing/
$ echo 0 > tracing_on 
$ echo function > current_tracer 
$ echo > set_ftrace_filter 
$ echo 1 > tracing_on 
$ cat trace
# tracer: function
#
#           TASK-PID    CPU#    TIMESTAMP  FUNCTION
#              | |       |          |         |
$ echo > set_ftrace_filter 
[   52.066435] ------------[ cut here ]------------
[   52.066824] WARNING: at /home/rabin/kernel/kernel/trace/ftrace.c:1384 __ftrace_hash_rec_update.part.27+0x157/0x1a7()
[   52.067794] Modules linked in:
[   52.068260] Pid: 445, comm: bash Not tainted 3.1.0-07810-g094803e #29
[   52.068702] Call Trace:
[   52.068884]  [<ffffffff8106fb26>] ? __ftrace_hash_rec_update.part.27+0x157/0x1a7
[   52.069599]  [<ffffffff81032347>] warn_slowpath_common+0x83/0x9b
[   52.070122]  [<ffffffff810758d9>] ? trace_parser_put+0xd/0xf
[   52.070812]  [<ffffffff81032379>] warn_slowpath_null+0x1a/0x1c
[   52.071515]  [<ffffffff8106fb26>] __ftrace_hash_rec_update.part.27+0x157/0x1a7
[   52.072385]  [<ffffffff8106fce2>] ftrace_hash_move+0x2e/0x151
[   52.073075]  [<ffffffff810bd028>] ? virt_to_head_page+0xe/0x31
[   52.073748]  [<ffffffff810befd7>] ? kfree+0x5e/0xd7
[   52.074349]  [<ffffffff8106feb8>] ftrace_regex_release+0xb3/0x107
[   52.075098]  [<ffffffff810c5085>] fput+0x8b/0x132
[   52.075649]  [<ffffffff810c24cf>] filp_close+0x63/0x6f
[   52.076301]  [<ffffffff810d043e>] sys_dup3+0x130/0x158
[   52.076898]  [<ffffffff810d04c4>] sys_dup2+0x5e/0x65
[   52.077440]  [<ffffffff81298db3>] ia32_do_call+0x13/0x13
[   52.078097] ---[ end trace c723c025d087b7e9 ]---
$ cat trace
# tracer: function
#
# WARNING: FUNCTION TRACING IS CORRUPTED
#          MAY BE MISSING FUNCTION EVENTS
#           TASK-PID    CPU#    TIMESTAMP  FUNCTION
#              | |       |          |         |

Re: WARNING at __ftrace_hash_rec_update()

[Steven Rostedt]

On Tue, 2011-11-01 at 19:45 +0530, Rabin Vincent wrote:
> On v3.1-7810-g094803e (current linus git), I'm able to trigger the below
> FTRACE_WARN_ON() by running the following sequence of commands.
> DYNAMIC_FTRACE is enabled.
> 
> ftrace.c:1384:
> 	if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
> 		return;
> 	rec->flags--;
> 

Thanks for reporting. Can you try this patch please.

-- Steve


diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 0fcc6ca..9af2ea6 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -1210,7 +1210,8 @@ ftrace_hash_move(struct ftrace_ops *ops, int enable,
 	if (!src->count) {
 		free_ftrace_hash_rcu(*dst);
 		rcu_assign_pointer(*dst, EMPTY_HASH);
-		return 0;
+		/* still need to update the function records */
+		goto out;
 	}
 
 	/*

Re: WARNING at __ftrace_hash_rec_update()

[Rabin Vincent]

On Fri, Nov 04, 2011 at 08:31:34PM -0400, Steven Rostedt wrote:
> On Tue, 2011-11-01 at 19:45 +0530, Rabin Vincent wrote:
> > On v3.1-7810-g094803e (current linus git), I'm able to trigger the below
> > FTRACE_WARN_ON() by running the following sequence of commands.
> > DYNAMIC_FTRACE is enabled.
> > 
> > ftrace.c:1384:
> > 	if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
> > 		return;
> > 	rec->flags--;
> > 
> 
> Thanks for reporting. Can you try this patch please.

Works for me, thanks.  It needed a ret=0 which I see you've already
added in your official submission.

[tip:perf/core] ftrace: Fix hash record accounting bug

[tip-bot for Steven Rostedt]

Commit-ID:  d4d34b981a5327eec956c6cb4cce397ce6f57279
Gitweb:     http://git.kernel.org/tip/d4d34b981a5327eec956c6cb4cce397ce6f57279
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Fri, 4 Nov 2011 20:32:39 -0400
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 7 Nov 2011 13:48:05 -0500

ftrace: Fix hash record accounting bug

If the set_ftrace_filter is cleared by writing just whitespace to
it, then the filter hash refcounts will be decremented but not
updated. This causes two bugs:

1) No functions will be enabled for tracing when they all should be

2) If the users clears the set_ftrace_filter twice, it will crash ftrace:

------------[ cut here ]------------
WARNING: at /home/rostedt/work/git/linux-trace.git/kernel/trace/ftrace.c:1384 __ftrace_hash_rec_update.part.27+0x157/0x1a7()
Modules linked in:
Pid: 2330, comm: bash Not tainted 3.1.0-test+ #32
Call Trace:
 [<ffffffff81051828>] warn_slowpath_common+0x83/0x9b
 [<ffffffff8105185a>] warn_slowpath_null+0x1a/0x1c
 [<ffffffff810ba362>] __ftrace_hash_rec_update.part.27+0x157/0x1a7
 [<ffffffff810ba6e8>] ? ftrace_regex_release+0xa7/0x10f
 [<ffffffff8111bdfe>] ? kfree+0xe5/0x115
 [<ffffffff810ba51e>] ftrace_hash_move+0x2e/0x151
 [<ffffffff810ba6fb>] ftrace_regex_release+0xba/0x10f
 [<ffffffff8112e49a>] fput+0xfd/0x1c2
 [<ffffffff8112b54c>] filp_close+0x6d/0x78
 [<ffffffff8113a92d>] sys_dup3+0x197/0x1c1
 [<ffffffff8113a9a6>] sys_dup2+0x4f/0x54
 [<ffffffff8150cac2>] system_call_fastpath+0x16/0x1b
---[ end trace 77a3a7ee73794a02 ]---

Link: http://lkml.kernel.org/r/20111101141420.GA4918@debian

Reported-by: Rabin Vincent <rabin@rab.in>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 0fcc6ca..7caa450 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -1210,7 +1210,9 @@ ftrace_hash_move(struct ftrace_ops *ops, int enable,
 	if (!src->count) {
 		free_ftrace_hash_rcu(*dst);
 		rcu_assign_pointer(*dst, EMPTY_HASH);
-		return 0;
+		/* still need to update the function records */
+		ret = 0;
+		goto out;
 	}
 
 	/*

[tip:perf/core] ftrace: Fix hash record accounting bug

[tip-bot for Steven Rostedt]

Commit-ID:  ddf6e0e50723b62ac76ed18eb53e9417c6eefba7
Gitweb:     http://git.kernel.org/tip/ddf6e0e50723b62ac76ed18eb53e9417c6eefba7
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Fri, 4 Nov 2011 20:32:39 -0400
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 5 Dec 2011 13:28:47 -0500

ftrace: Fix hash record accounting bug

If the set_ftrace_filter is cleared by writing just whitespace to
it, then the filter hash refcounts will be decremented but not
updated. This causes two bugs:

1) No functions will be enabled for tracing when they all should be

2) If the users clears the set_ftrace_filter twice, it will crash ftrace:

------------[ cut here ]------------
WARNING: at /home/rostedt/work/git/linux-trace.git/kernel/trace/ftrace.c:1384 __ftrace_hash_rec_update.part.27+0x157/0x1a7()
Modules linked in:
Pid: 2330, comm: bash Not tainted 3.1.0-test+ #32
Call Trace:
 [<ffffffff81051828>] warn_slowpath_common+0x83/0x9b
 [<ffffffff8105185a>] warn_slowpath_null+0x1a/0x1c
 [<ffffffff810ba362>] __ftrace_hash_rec_update.part.27+0x157/0x1a7
 [<ffffffff810ba6e8>] ? ftrace_regex_release+0xa7/0x10f
 [<ffffffff8111bdfe>] ? kfree+0xe5/0x115
 [<ffffffff810ba51e>] ftrace_hash_move+0x2e/0x151
 [<ffffffff810ba6fb>] ftrace_regex_release+0xba/0x10f
 [<ffffffff8112e49a>] fput+0xfd/0x1c2
 [<ffffffff8112b54c>] filp_close+0x6d/0x78
 [<ffffffff8113a92d>] sys_dup3+0x197/0x1c1
 [<ffffffff8113a9a6>] sys_dup2+0x4f/0x54
 [<ffffffff8150cac2>] system_call_fastpath+0x16/0x1b
---[ end trace 77a3a7ee73794a02 ]---

Link: http://lkml.kernel.org/r/20111101141420.GA4918@debian

Reported-by: Rabin Vincent <rabin@rab.in>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 1276b3c..b1e8943 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -1211,7 +1211,9 @@ ftrace_hash_move(struct ftrace_ops *ops, int enable,
 	if (!src->count) {
 		free_ftrace_hash_rcu(*dst);
 		rcu_assign_pointer(*dst, EMPTY_HASH);
-		return 0;
+		/* still need to update the function records */
+		ret = 0;
+		goto out;
 	}
 
 	/*