WARNING at __ftrace_hash_rec_update()

DISCUSSION Rabin Vincent 3 participants 5 messages Nov 1, 2011 – Dec 6, 2011

Subsystems (2)

Tracing ftrace

lore

Share & tools

lore

Rabin Vincent

author

2011-11-01 14:16 UTC #0 lore raw

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
#              | |       |          |         |

Steven Rostedt

maintainer

2011-11-05 00:31 UTC #1 lore raw

Quoted 9 lines · 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--;

Thanks for reporting. Can you try this patch please.

-- Steve

kernel/trace/ftrace.c +2 -1

index 0fcc6ca..9af2ea6 100644
@@ -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;
 	}
 
 	/*

Rabin Vincent

author

2011-11-11 10:15 UTC #2 lore raw

Quoted 5 lines · Steven Rostedt

Quoted 4 lines · 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.

Quoted 7 lines

Quoted 5 lines
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-bot for Steven Rostedt

2011-11-18 23:14 UTC #3 lore raw

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

In reply to Rabin Vincent

Commit-ID:  d4d34b981a5327eec956c6cb4cce397ce6f57279
Gitweb:     http://git.kernel.org/tip/d4d34b981a5327eec956c6cb4cce397ce6f57279
Author:     Steven Rostedt <[email protected]>
AuthorDate: Fri, 4 Nov 2011 20:32:39 -0400
Committer:  Steven Rostedt <[email protected]>
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 open here

Reported-by Rabin Vincent <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/ftrace.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

kernel/trace/ftrace.c +3 -1

index 0fcc6ca..7caa450 100644
@@ -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;
 	}
 
 	/*