Re: perf, kprobes: fuzzer generates huge number of WARNings

[Masami Hiramatsu]

On 2015/07/07 6:27, Vince Weaver wrote:
> Hello
> 
> I've been working on trying to get the perf_fuzzer to start fuzzing the 
> PERF_EVENT_IOC_SET_BPF so I've added some really hackish kprobe support.
> 
> However before I can get to the BPF testing the kprobe code generates a 
> constant stream of WARNINGS which make the machine more or less useless 
> until I stop it.  I've included a small selection here.
> 
> Is this expected?

Did you get same message without BPF hack? And also, could you tell us
your kernel version and configuration?

> 
> Vince
> 
> 
> [ 3521.350839] ftrace: Failed on adding breakpoints (6056):
> [ 3521.357877] ------------[ cut here ]------------
> [ 3521.363007] WARNING: CPU: 1 PID: 5080 at kernel/trace/ftrace.c:1951 ftrace_bug+0x245/0x320()
> [ 3521.449830] CPU: 1 PID: 5080 Comm: perf_fuzzer Not tainted 4.2.0-rc1+ #168
> [ 3521.457543] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 3521.465820]  ffffffff81a28cf6 ffff8800cd9f7b48 ffffffff816a10a3 0000000000000000
> [ 3521.474274]  0000000000000000 ffff8800cd9f7b88 ffffffff8106ec8a ffff8800cd9f7b68
> [ 3521.482680]  ffff880119bd7a80 ffffffff81196730 ffff880119bd7a80 00000000000017a8
> [ 3521.491143] Call Trace:
> [ 3521.494128]  [<ffffffff816a10a3>] dump_stack+0x45/0x57
> [ 3521.500016]  [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 3521.506810]  [<ffffffff81196730>] ? vm_insert_mixed+0x40/0x40
> [ 3521.513389]  [<ffffffff8106ed7a>] warn_slowpath_null+0x1a/0x20
> [ 3521.520025]  [<ffffffff81123425>] ftrace_bug+0x245/0x320
> [ 3521.526147]  [<ffffffff81052d5c>] ftrace_replace_code+0x24c/0x360
> [ 3521.533102]  [<ffffffff81123d3c>] ftrace_modify_all_code+0x9c/0x120
> [ 3521.540241]  [<ffffffff81052e80>] arch_ftrace_update_code+0x10/0x20
> [ 3521.547396]  [<ffffffff81123e30>] ftrace_run_update_code+0x20/0x80
> [ 3521.554425]  [<ffffffff811244df>] ftrace_startup_enable+0x2f/0x40
> [ 3521.561376]  [<ffffffff811256e6>] ftrace_startup+0xd6/0x230
> [ 3521.567772]  [<ffffffff81125c24>] register_ftrace_function+0x54/0x70
> [ 3521.575025]  [<ffffffff8113df07>] perf_ftrace_event_register+0x47/0x140
> [ 3521.582537]  [<ffffffff8113dba4>] perf_trace_init+0xc4/0x2c0
> [ 3521.589050]  [<ffffffff81152e8a>] perf_tp_event_init+0x2a/0x50
> [ 3521.595771]  [<ffffffff8115448b>] perf_try_init_event+0x8b/0xa0
> [ 3521.602572]  [<ffffffff8115bf63>] perf_init_event+0x133/0x160
> [ 3521.609181]  [<ffffffff8115be30>] ? perf_bp_event+0x90/0x90
> [ 3521.615647]  [<ffffffff8115c3ba>] perf_event_alloc+0x42a/0x680
> [ 3521.622388]  [<ffffffff8115c9d7>] SYSC_perf_event_open+0x3c7/0xd20
> [ 3521.629487]  [<ffffffff8105f86b>] ? __do_page_fault+0x1ab/0x3f0
> [ 3521.636320]  [<ffffffff8115d7a9>] SyS_perf_event_open+0x9/0x10
> [ 3521.643087]  [<ffffffff816a8df2>] entry_SYSCALL_64_fastpath+0x16/0x7a
> [ 3521.650521] ---[ end trace a413501925547ed5 ]---
> [ 3521.655960] ftrace failed to modify [<ffffffff81196730>] handle_mm_fault+0x0/0x1750
> [ 3521.664767]  actual: e8:cb:18:ef:1e

Hmm, this seems to happen when disarming kprobes from handle_mm_fault+0.
However, with this easy test, I couldn't reproduce it on the latest tip/master.

[root@localhost tracing]# echo p handle_mm_fault > kprobe_events
[root@localhost tracing]# echo 1 > events/kprobes/p_handle_mm_fault_0/enable
[root@localhost tracing]# echo 0 > events/kprobes/p_handle_mm_fault_0/enable

We'd better know how to reproduce this issue.

Thank you,

> [ 3521.669202] ftrace record flags: ec000002
> [ 3521.673993]  (2) R   tramp: 0xffffffffa0090000 expected tramp: ffffffffa0090000
> 
> 
> [ 3521.834024] ------------[ cut here ]------------
> [ 3521.839442] WARNING: CPU: 2 PID: 5177 at kernel/kprobes.c:955 disarm_kprobe+0xf8/0x100()
> [ 3521.848577] Failed to init kprobe-ftrace (-19)
> [ 3521.931384] CPU: 2 PID: 5177 Comm: perf_fuzzer Tainted: G        W       4.2.0-rc1+ #168
> [ 3521.940498] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 3521.948854]  ffffffff81a28976 ffff8800bf6d7a48 ffffffff816a10a3 0000000000000000
> [ 3521.957335]  ffff8800bf6d7a98 ffff8800bf6d7a88 ffffffff8106ec8a ffffffff81124f6a
> [ 3521.965839]  ffff8800cd4e2010 ffff8800cd4e2010 ffff8800cd4e2000 ffff8800cd28a000
> [ 3521.974275] Call Trace:
> [ 3521.977335]  [<ffffffff816a10a3>] dump_stack+0x45/0x57
> [ 3521.983302]  [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 3521.990170]  [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
> [ 3521.997784]  [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 3522.004418]  [<ffffffff816a693e>] ? mutex_unlock+0xe/0x10
> [ 3522.010640]  [<ffffffff81119208>] disarm_kprobe+0xf8/0x100
> [ 3522.016972]  [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
> [ 3522.023491]  [<ffffffff811192f7>] disable_kprobe+0x27/0x50
> [ 3522.029827]  [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
> [ 3522.036708]  [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
> [ 3522.043102]  [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
> [ 3522.050808]  [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
> [ 3522.057482]  [<ffffffff81152eb9>] tp_perf_event_destroy+0x9/0x10
> [ 3522.064354]  [<ffffffff81158fc1>] _free_event+0xc1/0x250
> [ 3522.070474]  [<ffffffff8115917b>] ? put_event+0x2b/0x150
> [ 3522.076625]  [<ffffffff811592ef>] free_event+0x1f/0x50
> [ 3522.082531]  [<ffffffff8115d9f5>] perf_event_exit_task+0x245/0x300
> [ 3522.089575]  [<ffffffff81071622>] do_exit+0x3b2/0xa90
> [ 3522.095444]  [<ffffffff8107d182>] ? get_signal+0xe2/0x720
> [ 3522.101659]  [<ffffffff81071da4>] do_group_exit+0x54/0xe0
> [ 3522.107892]  [<ffffffff8107d320>] get_signal+0x280/0x720
> [ 3522.114046]  [<ffffffff81013478>] do_signal+0x28/0xb50
> [ 3522.119984]  [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
> [ 3522.127411]  [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
> [ 3522.133563]  [<ffffffff81014002>] do_notify_resume+0x62/0x70
> [ 3522.140084]  [<ffffffff816a9ade>] retint_signal+0x44/0x86
> [ 3522.146349] ---[ end trace a413501925547ed6 ]---
> 
> 
> 
> [ 3522.157157] WARNING: CPU: 2 PID: 5177 at kernel/kprobes.c:959 disarm_kprobe+0xca/0x100()
> [ 3522.166266] Failed to disarm kprobe-ftrace at ffffffff81196730 (-19)
> [ 3522.251364] CPU: 2 PID: 5177 Comm: perf_fuzzer Tainted: G        W       4.2.0-rc1+ #168
> [ 3522.260488] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 3522.268953]  ffffffff81a28976 ffff8800bf6d7a48 ffffffff816a10a3 0000000000000000
> [ 3522.277482]  ffff8800bf6d7a98 ffff8800bf6d7a88 ffffffff8106ec8a ffffffff81124f6a
> [ 3522.285993]  ffff8800cd4e2010 ffff8800cd4e2010 ffff8800cd4e2000 ffff8800cd28a000
> [ 3522.294520] Call Trace:
> [ 3522.297594]  [<ffffffff816a10a3>] dump_stack+0x45/0x57
> [ 3522.303535]  [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 3522.310379]  [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
> [ 3522.318026]  [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 3522.324637]  [<ffffffff816a693e>] ? mutex_unlock+0xe/0x10
> [ 3522.330859]  [<ffffffff81196730>] ? vm_insert_mixed+0x40/0x40
> [ 3522.337459]  [<ffffffff811191da>] disarm_kprobe+0xca/0x100
> [ 3522.343792]  [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
> [ 3522.350304]  [<ffffffff811192f7>] disable_kprobe+0x27/0x50
> [ 3522.356692]  [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
> [ 3522.363510]  [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
> [ 3522.369907]  [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
> [ 3522.377620]  [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
> [ 3522.384337]  [<ffffffff81152eb9>] tp_perf_event_destroy+0x9/0x10
> [ 3522.391215]  [<ffffffff81158fc1>] _free_event+0xc1/0x250
> [ 3522.397348]  [<ffffffff8115917b>] ? put_event+0x2b/0x150
> [ 3522.403478]  [<ffffffff811592ef>] free_event+0x1f/0x50
> [ 3522.409443]  [<ffffffff8115d9f5>] perf_event_exit_task+0x245/0x300
> [ 3522.416466]  [<ffffffff81071622>] do_exit+0x3b2/0xa90
> [ 3522.422351]  [<ffffffff8107d182>] ? get_signal+0xe2/0x720
> [ 3522.428555]  [<ffffffff81071da4>] do_group_exit+0x54/0xe0
> [ 3522.434803]  [<ffffffff8107d320>] get_signal+0x280/0x720
> [ 3522.440974]  [<ffffffff81013478>] do_signal+0x28/0xb50
> [ 3522.446949]  [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
> [ 3522.454420]  [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
> [ 3522.460592]  [<ffffffff81014002>] do_notify_resume+0x62/0x70
> [ 3522.467079]  [<ffffffff816a9ade>] retint_signal+0x44/0x86
> [ 3522.473343] ---[ end trace a413501925547ed7 ]---
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 


-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@xxxxxxxxxxx
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/