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?
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
[ 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 ]---
On Mon, 6 Jul 2015 17:27:04 -0400 (EDT)
Vince Weaver <[email protected]> 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?
>
> 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, it was not expecting to see this address above in the mcount slot.
Did you have other tracing going on, or did you add a kprobe to
handle_mm_fault too?
-- Steve
> [ 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 ]---
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 [email protected]
> 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: [email protected]
On Mon, 6 Jul 2015, Steven Rostedt wrote:
> On Mon, 6 Jul 2015 17:27:04 -0400 (EDT)
> Vince Weaver <[email protected]> wrote:
> > [ 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, it was not expecting to see this address above in the mcount slot.
> Did you have other tracing going on, or did you add a kprobe to
> handle_mm_fault too?
it's fuzzing so there were potentially a large number of tracepoint events
active at the time. Only one kprobe event,
p:probe/VMW _text+1664816
and I forget what that actually mapped to originally.
Vince
On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
> 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?
It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
interest.
Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
hack, it just turned out to be a huge pain to figure out how to
manually create a valid BPF program in conjunction with a valid kprobe
event.
I did have to sprinkle printks in the kprobe and bpf code to find out
where various EINVAL returns were coming from, so potentially this is just
a problem of printks happening where they shouldn't. I'll remove those
changes and try to reproduce this tomorrow.
This is possibly a long standing issue, until now I never ran the fuzzer
as root so these particular code paths weren't tested.
Vince
On 2015/07/07 13:00, Vince Weaver wrote:
> On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
>
>> 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?
>
> It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
> interest.
Yes, I'm interested in.
> Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
> hack, it just turned out to be a huge pain to figure out how to
> manually create a valid BPF program in conjunction with a valid kprobe
> event.
>
> I did have to sprinkle printks in the kprobe and bpf code to find out
> where various EINVAL returns were coming from, so potentially this is just
> a problem of printks happening where they shouldn't. I'll remove those
> changes and try to reproduce this tomorrow.
OK, and also, if you have a chance, please run the ftracetest as below.
$ cd tools/testing/selftest/ftrace/
$ sudo ./ftracetest
This will do a series of basic tests on ftrace and report it.
> This is possibly a long standing issue, until now I never ran the fuzzer
> as root so these particular code paths weren't tested.
Thanks,
--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
> > It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
> > interest.
>
> Yes, I'm interested in.
I've put it here:
http://web.eece.maine.edu/~vweaver/junk/haswell-config
> OK, and also, if you have a chance, please run the ftracetest as below.
>
> $ cd tools/testing/selftest/ftrace/
> $ sudo ./ftracetest
>
> This will do a series of basic tests on ftrace and report it.
It won't run:
sudo ./ftracetest
Error: No ftrace directory found
probably because I am running 4.2-rc1 and have tracefs mounted under
/sys/kernel/tracing.
I guess the tester needs to be updated?
I'll see if I can get debugfs mounted too, but I had changed the setup so
perf would run.
When I recompiled my kernel to remove the extra debug messages and run my
fuzzer test I get a lot of these, probably because I have the kprobe
address hard-coded into the tester.
[ 290.067450] Could not insert probe at _text+1664816: -84
[ 290.074976] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.131191] Could not insert probe at _text+1664816: -84
[ 290.137555] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.170513] Could not insert probe at _text+1664816: -84
[ 290.176877] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.298940] Could not insert probe at _text+1664816: -84
[ 290.305224] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.349272] Could not insert probe at _text+1664816: -84
[ 290.355585] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.365738] Could not insert probe at _text+1664816: -84
[ 290.371992] Probing address(0xffffffff81196730) is not an instruction boundary.
[ 290.383820] perf interrupt took too long (448 > 266), lowering kernel.perf_event_max_sample_rate to 468250
[ 295.088511] perf interrupt took too long (485 > 0), lowering kernel.perf_event_max_sample_rate to 1639281051
[ 311.415309] INFO: rcu_sched detected stalls on CPUs/tasks: { 5} (detected by 6, t=5253 jiffies, g=1818, c=1817, q=534)
[ 311.427531] Task dump for CPU 5:
[ 311.431631] in:imklog R running task 0 1736 1 0x00000008
[ 311.439865] 0000000000000286 0000000100000005 0000000000000096 0000000200000000
[ 311.448549] 0000000000000286 ffffffff81c4b2e0 ffffffff81c4b2e0 ffffffff828da234
[ 311.457173] 0000000000001f2f 00007fa62335fe11 0000000000000071 ffffffff828da234
[ 311.465865] Call Trace:
[ 311.469098] [<ffffffff810c8886>] ? do_syslog+0x456/0x500
[ 311.475518] [<ffffffff810b02a0>] ? wait_woken+0x90/0x90
[ 311.481830] [<ffffffff81255bb4>] ? kmsg_read+0x44/0x60
[ 311.488040] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
[ 311.494433] [<ffffffff81003000>] ? calibrate_delay+0x8f0/0x8f0
[ 311.501356] [<ffffffff816a98e5>] ? retint_check+0x6/0x12
[ 313.873152] hrtimer: interrupt took 14075878236 ns
On Tue, 7 Jul 2015 11:06:55 -0400 (EDT)
Vince Weaver <[email protected]> wrote:
> On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
>
> > > It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
> > > interest.
> >
> > Yes, I'm interested in.
>
> I've put it here:
> http://web.eece.maine.edu/~vweaver/junk/haswell-config
>
> > OK, and also, if you have a chance, please run the ftracetest as below.
> >
> > $ cd tools/testing/selftest/ftrace/
> > $ sudo ./ftracetest
> >
> > This will do a series of basic tests on ftrace and report it.
>
> It won't run:
> sudo ./ftracetest
> Error: No ftrace directory found
>
> probably because I am running 4.2-rc1 and have tracefs mounted under
> /sys/kernel/tracing.
You could also just mount debugfs.
> I guess the tester needs to be updated?
Yes, it probably should be.
> I'll see if I can get debugfs mounted too, but I had changed the setup so
> perf would run.
>
>
> When I recompiled my kernel to remove the extra debug messages and run my
> fuzzer test I get a lot of these, probably because I have the kprobe
> address hard-coded into the tester.
Probably. If you recompiled the kernel, you need to find the new
address points.
-- Steve
>
> [ 290.067450] Could not insert probe at _text+1664816: -84
> [ 290.074976] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.131191] Could not insert probe at _text+1664816: -84
> [ 290.137555] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.170513] Could not insert probe at _text+1664816: -84
> [ 290.176877] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.298940] Could not insert probe at _text+1664816: -84
> [ 290.305224] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.349272] Could not insert probe at _text+1664816: -84
> [ 290.355585] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.365738] Could not insert probe at _text+1664816: -84
> [ 290.371992] Probing address(0xffffffff81196730) is not an instruction boundary.
> [ 290.383820] perf interrupt took too long (448 > 266), lowering kernel.perf_event_max_sample_rate to 468250
> [ 295.088511] perf interrupt took too long (485 > 0), lowering kernel.perf_event_max_sample_rate to 1639281051
> [ 311.415309] INFO: rcu_sched detected stalls on CPUs/tasks: { 5} (detected by 6, t=5253 jiffies, g=1818, c=1817, q=534)
> [ 311.427531] Task dump for CPU 5:
> [ 311.431631] in:imklog R running task 0 1736 1 0x00000008
> [ 311.439865] 0000000000000286 0000000100000005 0000000000000096 0000000200000000
> [ 311.448549] 0000000000000286 ffffffff81c4b2e0 ffffffff81c4b2e0 ffffffff828da234
> [ 311.457173] 0000000000001f2f 00007fa62335fe11 0000000000000071 ffffffff828da234
> [ 311.465865] Call Trace:
> [ 311.469098] [<ffffffff810c8886>] ? do_syslog+0x456/0x500
> [ 311.475518] [<ffffffff810b02a0>] ? wait_woken+0x90/0x90
> [ 311.481830] [<ffffffff81255bb4>] ? kmsg_read+0x44/0x60
> [ 311.488040] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
> [ 311.494433] [<ffffffff81003000>] ? calibrate_delay+0x8f0/0x8f0
> [ 311.501356] [<ffffffff816a98e5>] ? retint_check+0x6/0x12
> [ 313.873152] hrtimer: interrupt took 14075878236 ns
On Tue, 7 Jul 2015, Vince Weaver wrote:
> On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
>
> > > It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
> > > interest.
> >
> > Yes, I'm interested in.
>
> I've put it here:
> http://web.eece.maine.edu/~vweaver/junk/haswell-config
>
> > OK, and also, if you have a chance, please run the ftracetest as below.
> >
> > $ cd tools/testing/selftest/ftrace/
> > $ sudo ./ftracetest
> >
> > This will do a series of basic tests on ftrace and report it.
>
> It won't run:
> sudo ./ftracetest
> Error: No ftrace directory found
>
OK here are the results when I mounted debugfs in the right place.
sudo ./ftracetest
=== Ftrace unit tests ===
[1] Basic trace file check [PASS]
[2] Basic test for tracers [PASS]
[3] Basic trace clock test [PASS]
[4] Basic event tracing check [PASS]
[5] event tracing - enable/disable with event level files [PASS]
[6] event tracing - enable/disable with subsystem level files [PASS]
[7] event tracing - enable/disable with top level files [PASS]
[8] ftrace - function graph filters with stack tracer [UNSUPPORTED]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
+ grep -q function_graph available_tracers
+ [ ! -f set_ftrace_filter ]
+ disable_tracing
+ echo 0
+ clear_trace
+ echo
+ echo schedule
+ echo function_graph
+ [ ! -f stack_trace ]
+ echo Stack tracer not configured
Stack tracer not configured
+ do_reset
+ reset_tracer
+ echo nop
+ [ -e /proc/sys/kernel/stack_tracer_enabled ]
+ enable_tracing
+ echo 1
+ clear_trace
+ echo
+ echo
+ exit_unsupported
+ kill -s 40 2725
+ exit 0
[9] ftrace - function graph filters [PASS]
[10] ftrace - function profiler with function tracing [UNSUPPORTED]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/func_profiler.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/func_profiler.tc
+ grep -q function_graph available_tracers
+ [ ! -f set_ftrace_filter ]
+ [ ! -f function_profile_enabled ]
+ echo function_profile_enabled not found, function profiling enabled?
function_profile_enabled not found, function profiling enabled?
+ exit_unsupported
+ kill -s 40 2725
+ exit 0
[11] Kprobe dynamic event - adding and removing [FAIL]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/add_and_remove.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/add_and_remove.tc
+ [ -f kprobe_events ]
+ echo 0
+ echo
+ echo p:myevent do_fork
sh: echo: I/O error
[12] Kprobe dynamic event - busy event check [FAIL]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/busy_check.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/busy_check.tc
+ [ -f kprobe_events ]
+ echo 0
+ echo
+ echo p:myevent do_fork
sh: echo: I/O error
[13] Kprobe dynamic event with arguments [FAIL]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args.tc
+ [ -f kprobe_events ]
+ echo 0
+ echo
+ echo p:testprobe do_fork $stack $stack0 +0($stack)
sh: echo: I/O error
[14] Kprobe dynamic event with function tracer [FAIL]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_ftrace.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_ftrace.tc
+ [ -f kprobe_events ]
+ grep function available_tracers
blk function_graph function nop
+ echo nop
+ echo do_fork
sh: echo: I/O error
[15] Kretprobe dynamic event with arguments [FAIL]
execute:
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
+ .
/home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
+ [ -f kprobe_events ]
+ echo 0
+ echo
+ echo r:testprobe2 do_fork $retval
sh: echo: I/O error
# of passed: 8
# of failed: 5
# of unresolved: 0
# of untested: 0
# of unsupported: 2
# of xfailed: 0
# of undefined(test bug): 0
On Tue, 7 Jul 2015, Steven Rostedt wrote:
> On Tue, 7 Jul 2015 11:06:55 -0400 (EDT)
> Probably. If you recompiled the kernel, you need to find the new
> address points.
should these messages really be spamming the syslog?
I updated the kprobe to point to the right location again
(this is
and the fuzzer just generates infinite of these warnings. Maybe they
should be WARN_ONCE rather than plain WARN?
[ 5447.623713] ------------[ cut here ]------------
[ 5447.629160] WARNING: CPU: 1 PID: 4158 at kernel/kprobes.c:939 arm_kprobe+0xe3/0xf0()
[ 5447.637944] Failed to arm kprobe-ftrace at ffffffff81196670 (-19)
[ 5447.723237] CPU: 1 PID: 4158 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
[ 5447.732454] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 5447.740897] ffffffff81a2894e ffff8801161b3bf8 ffffffff816a0fd3 0000000000000000
[ 5447.749426] ffff8801161b3c48 ffff8801161b3c38 ffffffff8106ec8a 000000000000aed0
[ 5447.757931] ffff88011847b810 0000000000000000 ffff8800cd8b8000 ffffffff81d25640
[ 5447.766463] Call Trace:
[ 5447.769567] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
[ 5447.775569] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
[ 5447.782504] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
[ 5447.789111] [<ffffffff8118996a>] ? pcpu_alloc+0x36a/0x630
[ 5447.795466] [<ffffffff81196670>] ? vm_insert_mixed+0x40/0x40
[ 5447.802098] [<ffffffff81119083>] arm_kprobe+0xe3/0xf0
[ 5447.808095] [<ffffffff81119108>] enable_kprobe+0x78/0x80
[ 5447.814353] [<ffffffff81143489>] kprobe_register+0x59/0xe0
[ 5447.820805] [<ffffffff8113dc95>] perf_trace_init+0x1b5/0x2c0
[ 5447.827471] [<ffffffff81152e2a>] perf_tp_event_init+0x2a/0x50
[ 5447.834197] [<ffffffff8115442b>] perf_try_init_event+0x8b/0xa0
[ 5447.841012] [<ffffffff8115bec3>] perf_init_event+0x133/0x160
[ 5447.847658] [<ffffffff8115bd90>] ? perf_bp_event+0x90/0x90
[ 5447.854101] [<ffffffff8115c31a>] perf_event_alloc+0x42a/0x680
[ 5447.860840] [<ffffffff8115c937>] SYSC_perf_event_open+0x3c7/0xd20
[ 5447.867949] [<ffffffff8115d709>] SyS_perf_event_open+0x9/0x10
[ 5447.874702] [<ffffffff816a8d32>] entry_SYSCALL_64_fastpath+0x16/0x7a
[ 5447.882093] ---[ end trace 5d38212a775ec3f3 ]---
[ 5447.887538] ------------[ cut here ]------------
[ 5447.892984] WARNING: CPU: 1 PID: 4158 at kernel/kprobes.c:943 arm_kprobe+0xae/0xf0()
[ 5447.901755] Failed to init kprobe-ftrace (-19)
[ 5447.985337] CPU: 1 PID: 4158 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
[ 5447.994611] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 5448.003174] ffffffff81a2894e ffff8801161b3bf8 ffffffff816a0fd3 0000000000000000
[ 5448.011805] ffff8801161b3c48 ffff8801161b3c38 ffffffff8106ec8a ffffffff81125c1a
[ 5448.020424] ffff88011847b810 0000000000000000 ffff8800cd8b8000 ffffffff81d25640
[ 5448.029074] Call Trace:
[ 5448.032265] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
[ 5448.038342] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
[ 5448.045376] [<ffffffff81125c1a>] ? register_ftrace_function+0x4a/0x70
[ 5448.052930] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
[ 5448.059617] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
[ 5448.065951] [<ffffffff8111904e>] arm_kprobe+0xae/0xf0
[ 5448.072003] [<ffffffff81119108>] enable_kprobe+0x78/0x80
[ 5448.078341] [<ffffffff81143489>] kprobe_register+0x59/0xe0
[ 5448.084823] [<ffffffff8113dc95>] perf_trace_init+0x1b5/0x2c0
[ 5448.091484] [<ffffffff81152e2a>] perf_tp_event_init+0x2a/0x50
[ 5448.098212] [<ffffffff8115442b>] perf_try_init_event+0x8b/0xa0
[ 5448.105068] [<ffffffff8115bec3>] perf_init_event+0x133/0x160
[ 5448.111689] [<ffffffff8115bd90>] ? perf_bp_event+0x90/0x90
[ 5448.118116] [<ffffffff8115c31a>] perf_event_alloc+0x42a/0x680
[ 5448.124825] [<ffffffff8115c937>] SYSC_perf_event_open+0x3c7/0xd20
[ 5448.131946] [<ffffffff8115d709>] SyS_perf_event_open+0x9/0x10
[ 5448.138640] [<ffffffff816a8d32>] entry_SYSCALL_64_fastpath+0x16/0x7a
[ 5448.146065] ---[ end trace 5d38212a775ec3f4 ]---
[ 5448.228748] ------------[ cut here ]------------
[ 5448.234201] WARNING: CPU: 2 PID: 4247 at kernel/kprobes.c:955 disarm_kprobe+0xf8/0x100()
[ 5448.243366] Failed to init kprobe-ftrace (-19)
[ 5448.327114] CPU: 2 PID: 4247 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
[ 5448.336416] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 5448.344935] ffffffff81a2894e ffff8801187a79e8 ffffffff816a0fd3 0000000000000000
[ 5448.353549] ffff8801187a7a38 ffff8801187a7a28 ffffffff8106ec8a ffffffff81124f6a
[ 5448.362177] ffff88011847b810 ffff88011847b810 ffff88011847b800 ffff8801160c02a8
[ 5448.370824] Call Trace:
[ 5448.374033] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
[ 5448.380146] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
[ 5448.387148] [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
[ 5448.394880] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
[ 5448.401603] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
[ 5448.407920] [<ffffffff81119208>] disarm_kprobe+0xf8/0x100
[ 5448.414326] [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
[ 5448.420874] [<ffffffff811192f7>] disable_kprobe+0x27/0x50
[ 5448.427222] [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
[ 5448.434140] [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
[ 5448.440586] [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
[ 5448.448349] [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
[ 5448.455058] [<ffffffff81152e59>] tp_perf_event_destroy+0x9/0x10
[ 5448.461945] [<ffffffff81158f61>] _free_event+0xc1/0x250
[ 5448.468093] [<ffffffff811591fa>] put_event+0x10a/0x150
[ 5448.474167] [<ffffffff8115911b>] ? put_event+0x2b/0x150
[ 5448.480313] [<ffffffff81152db5>] ? perf_fasync+0x55/0x70
[ 5448.486552] [<ffffffff81159260>] perf_release+0x10/0x20
[ 5448.492735] [<ffffffff811df3ec>] __fput+0xdc/0x1e0
[ 5448.498420] [<ffffffff811df53e>] ____fput+0xe/0x10
[ 5448.504110] [<ffffffff8108c27b>] task_work_run+0x9b/0xb0
[ 5448.510315] [<ffffffff81071615>] do_exit+0x3a5/0xa90
[ 5448.516184] [<ffffffff8107d182>] ? get_signal+0xe2/0x720
[ 5448.522407] [<ffffffff81071da4>] do_group_exit+0x54/0xe0
[ 5448.528671] [<ffffffff8107d320>] get_signal+0x280/0x720
[ 5448.534830] [<ffffffff81013478>] do_signal+0x28/0xb50
[ 5448.540792] [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
[ 5448.548277] [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
[ 5448.554413] [<ffffffff81014002>] do_notify_resume+0x62/0x70
[ 5448.560950] [<ffffffff816a9a1e>] retint_signal+0x44/0x86
[ 5448.567208] ---[ end trace 5d38212a775ec3f5 ]---
[ 5448.572624] ------------[ cut here ]------------
[ 5448.578045] WARNING: CPU: 2 PID: 4247 at kernel/kprobes.c:959 disarm_kprobe+0xca/0x100()
[ 5448.587194] Failed to disarm kprobe-ftrace at ffffffff81196670 (-19)
[ 5448.672321] CPU: 2 PID: 4247 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
[ 5448.681431] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 5448.689813] ffffffff81a2894e ffff8801187a79e8 ffffffff816a0fd3 0000000000000000
[ 5448.698271] ffff8801187a7a38 ffff8801187a7a28 ffffffff8106ec8a ffffffff81124f6a
[ 5448.706783] ffff88011847b810 ffff88011847b810 ffff88011847b800 ffff8801160c02a8
[ 5448.715255] Call Trace:
[ 5448.718342] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
[ 5448.724346] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
[ 5448.731233] [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
[ 5448.738872] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
[ 5448.745467] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
[ 5448.751708] [<ffffffff81196670>] ? vm_insert_mixed+0x40/0x40
[ 5448.758336] [<ffffffff811191da>] disarm_kprobe+0xca/0x100
[ 5448.764683] [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
[ 5448.771186] [<ffffffff811192f7>] disable_kprobe+0x27/0x50
[ 5448.777504] [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
[ 5448.784424] [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
[ 5448.790863] [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
[ 5448.798558] [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
[ 5448.805285] [<ffffffff81152e59>] tp_perf_event_destroy+0x9/0x10
[ 5448.812218] [<ffffffff81158f61>] _free_event+0xc1/0x250
[ 5448.818384] [<ffffffff811591fa>] put_event+0x10a/0x150
[ 5448.824422] [<ffffffff8115911b>] ? put_event+0x2b/0x150
[ 5448.830593] [<ffffffff81152db5>] ? perf_fasync+0x55/0x70
[ 5448.836862] [<ffffffff81159260>] perf_release+0x10/0x20
[ 5448.843023] [<ffffffff811df3ec>] __fput+0xdc/0x1e0
[ 5448.848709] [<ffffffff811df53e>] ____fput+0xe/0x10
[ 5448.854382] [<ffffffff8108c27b>] task_work_run+0x9b/0xb0
[ 5448.860620] [<ffffffff81071615>] do_exit+0x3a5/0xa90
[ 5448.866469] [<ffffffff8107d182>] ? get_signal+0xe2/0x720
[ 5448.872714] [<ffffffff81071da4>] do_group_exit+0x54/0xe0
[ 5448.878990] [<ffffffff8107d320>] get_signal+0x280/0x720
[ 5448.885163] [<ffffffff81013478>] do_signal+0x28/0xb50
[ 5448.891117] [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
[ 5448.898586] [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
[ 5448.904712] [<ffffffff81014002>] do_notify_resume+0x62/0x70
[ 5448.911245] [<ffffffff816a9a1e>] retint_signal+0x44/0x86
[ 5448.917526] ---[ end trace 5d38212a775ec3f6 ]---
On Tue, Jul 07, 2015 at 12:00:12AM -0400, Vince Weaver wrote:
>
> Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
> hack, it just turned out to be a huge pain to figure out how to
> manually create a valid BPF program in conjunction with a valid kprobe
> event.
You mean automatically generating valid bpf program? That's definitely hard.
If you mean just few hardcoded programs then take them from samples or
from test_bpf ?
> I did have to sprinkle printks in the kprobe and bpf code to find out
> where various EINVAL returns were coming from, so potentially this is just
> a problem of printks happening where they shouldn't. I'll remove those
> changes and try to reproduce this tomorrow.
could you please elaborate on this further. Which EINVALs you talking about?
On Tue, 7 Jul 2015, Alexei Starovoitov wrote:
> On Tue, Jul 07, 2015 at 12:00:12AM -0400, Vince Weaver wrote:
> >
> > Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
> > hack, it just turned out to be a huge pain to figure out how to
> > manually create a valid BPF program in conjunction with a valid kprobe
> > event.
>
> You mean automatically generating valid bpf program? That's definitely hard.
> If you mean just few hardcoded programs then take them from samples or
> from test_bpf ?
there's already code in trinity that in theory autogenerates bpf programs,
but for now I was just trying to hook up a short known valid one.
it might not be possible to really test things though, as you need to be
root to create a kprobe and attach a BPF program, but my fuzzer when run
as root often does all kinds of other stuff that will crash a machine.
Is it ever planned to allow using bpf/kprobes without requiring full
CAP_ADMIN privledges?
> > I did have to sprinkle printks in the kprobe and bpf code to find out
> > where various EINVAL returns were coming from, so potentially this is just
> > a problem of printks happening where they shouldn't. I'll remove those
> > changes and try to reproduce this tomorrow.
>
> could you please elaborate on this further. Which EINVALs you talking about?
When you are trying to create a kprobe and bpf file there's about 10
different ways to get EINVAL as a return value and no way of knowing which
one you are hitting. I added printks so I could know what issue was
causing the einval. (from memory, the problems I hit were not zeroing out
the attr structure, having a wrong instruction count, and a few others).
Vince
On Tue, Jul 07, 2015 at 05:08:51PM -0400, Vince Weaver wrote:
> On Tue, 7 Jul 2015, Alexei Starovoitov wrote:
>
> > On Tue, Jul 07, 2015 at 12:00:12AM -0400, Vince Weaver wrote:
> > >
> > > Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
> > > hack, it just turned out to be a huge pain to figure out how to
> > > manually create a valid BPF program in conjunction with a valid kprobe
> > > event.
> >
> > You mean automatically generating valid bpf program? That's definitely hard.
> > If you mean just few hardcoded programs then take them from samples or
> > from test_bpf ?
>
> there's already code in trinity that in theory autogenerates bpf programs,
> but for now I was just trying to hook up a short known valid one.
>
> it might not be possible to really test things though, as you need to be
> root to create a kprobe and attach a BPF program, but my fuzzer when run
> as root often does all kinds of other stuff that will crash a machine.
> Is it ever planned to allow using bpf/kprobes without requiring full
> CAP_ADMIN privledges?
I suspect kprobes will forever be root only, whereas for bpf I'm thinking
to introduce CAP_BPF, but before that we need to finish constant blinding
and add address leak prevention. So not soon.
> > > I did have to sprinkle printks in the kprobe and bpf code to find out
> > > where various EINVAL returns were coming from, so potentially this is just
> > > a problem of printks happening where they shouldn't. I'll remove those
> > > changes and try to reproduce this tomorrow.
> >
> > could you please elaborate on this further. Which EINVALs you talking about?
>
> When you are trying to create a kprobe and bpf file there's about 10
> different ways to get EINVAL as a return value and no way of knowing which
> one you are hitting. I added printks so I could know what issue was
> causing the einval. (from memory, the problems I hit were not zeroing out
> the attr structure, having a wrong instruction count, and a few others).
I see. I guess anyone trying to use syscall directly will be facing such
issues, but libbpf that is being developed to be used by perf and others
should solve these problems.
Hi Vince,
On 2015/07/08 3:06, Vince Weaver wrote:
> On Tue, 7 Jul 2015, Steven Rostedt wrote:
>
>> On Tue, 7 Jul 2015 11:06:55 -0400 (EDT)
>> Probably. If you recompiled the kernel, you need to find the new
>> address points.
>
> should these messages really be spamming the syslog?
>
> I updated the kprobe to point to the right location again
> (this is
>
> and the fuzzer just generates infinite of these warnings. Maybe they
> should be WARN_ONCE rather than plain WARN?
>
> [ 5447.623713] ------------[ cut here ]------------
> [ 5447.629160] WARNING: CPU: 1 PID: 4158 at kernel/kprobes.c:939 arm_kprobe+0xe3/0xf0()
> [ 5447.637944] Failed to arm kprobe-ftrace at ffffffff81196670 (-19)
The corresponding code is
----
ret = ftrace_set_filter_ip(&kprobe_ftrace_ops,
(unsigned long)p->addr, 0, 0);
WARN(ret < 0, "Failed to arm kprobe-ftrace at %p (%d)\n", p->addr, ret);
----
-19 is -ENODEV, and it may be returned from ftrace_set_hash
(ftrace_set_filter_ip -> ftrace_set_addr -> ftrace_set_hash)
----
static int
ftrace_set_hash(struct ftrace_ops *ops, unsigned char *buf, int len,
unsigned long ip, int remove, int reset, int enable)
{
struct ftrace_hash **orig_hash;
struct ftrace_ops_hash old_hash_ops;
struct ftrace_hash *old_hash;
struct ftrace_hash *hash;
int ret;
if (unlikely(ftrace_disabled))
return -ENODEV;
----
the ftrace_disabled (I think it would better be renamed to ftrace_died...) is
set only if an unrecoverable error happened. So before this message you'll
see some other error messages.
Thank you,
> [ 5447.723237] CPU: 1 PID: 4158 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
> [ 5447.732454] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 5447.740897] ffffffff81a2894e ffff8801161b3bf8 ffffffff816a0fd3 0000000000000000
> [ 5447.749426] ffff8801161b3c48 ffff8801161b3c38 ffffffff8106ec8a 000000000000aed0
> [ 5447.757931] ffff88011847b810 0000000000000000 ffff8800cd8b8000 ffffffff81d25640
> [ 5447.766463] Call Trace:
> [ 5447.769567] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
> [ 5447.775569] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 5447.782504] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 5447.789111] [<ffffffff8118996a>] ? pcpu_alloc+0x36a/0x630
> [ 5447.795466] [<ffffffff81196670>] ? vm_insert_mixed+0x40/0x40
> [ 5447.802098] [<ffffffff81119083>] arm_kprobe+0xe3/0xf0
> [ 5447.808095] [<ffffffff81119108>] enable_kprobe+0x78/0x80
> [ 5447.814353] [<ffffffff81143489>] kprobe_register+0x59/0xe0
> [ 5447.820805] [<ffffffff8113dc95>] perf_trace_init+0x1b5/0x2c0
> [ 5447.827471] [<ffffffff81152e2a>] perf_tp_event_init+0x2a/0x50
> [ 5447.834197] [<ffffffff8115442b>] perf_try_init_event+0x8b/0xa0
> [ 5447.841012] [<ffffffff8115bec3>] perf_init_event+0x133/0x160
> [ 5447.847658] [<ffffffff8115bd90>] ? perf_bp_event+0x90/0x90
> [ 5447.854101] [<ffffffff8115c31a>] perf_event_alloc+0x42a/0x680
> [ 5447.860840] [<ffffffff8115c937>] SYSC_perf_event_open+0x3c7/0xd20
> [ 5447.867949] [<ffffffff8115d709>] SyS_perf_event_open+0x9/0x10
> [ 5447.874702] [<ffffffff816a8d32>] entry_SYSCALL_64_fastpath+0x16/0x7a
> [ 5447.882093] ---[ end trace 5d38212a775ec3f3 ]---
> [ 5447.887538] ------------[ cut here ]------------
> [ 5447.892984] WARNING: CPU: 1 PID: 4158 at kernel/kprobes.c:943 arm_kprobe+0xae/0xf0()
> [ 5447.901755] Failed to init kprobe-ftrace (-19)
> [ 5447.985337] CPU: 1 PID: 4158 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
> [ 5447.994611] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 5448.003174] ffffffff81a2894e ffff8801161b3bf8 ffffffff816a0fd3 0000000000000000
> [ 5448.011805] ffff8801161b3c48 ffff8801161b3c38 ffffffff8106ec8a ffffffff81125c1a
> [ 5448.020424] ffff88011847b810 0000000000000000 ffff8800cd8b8000 ffffffff81d25640
> [ 5448.029074] Call Trace:
> [ 5448.032265] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
> [ 5448.038342] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 5448.045376] [<ffffffff81125c1a>] ? register_ftrace_function+0x4a/0x70
> [ 5448.052930] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 5448.059617] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
> [ 5448.065951] [<ffffffff8111904e>] arm_kprobe+0xae/0xf0
> [ 5448.072003] [<ffffffff81119108>] enable_kprobe+0x78/0x80
> [ 5448.078341] [<ffffffff81143489>] kprobe_register+0x59/0xe0
> [ 5448.084823] [<ffffffff8113dc95>] perf_trace_init+0x1b5/0x2c0
> [ 5448.091484] [<ffffffff81152e2a>] perf_tp_event_init+0x2a/0x50
> [ 5448.098212] [<ffffffff8115442b>] perf_try_init_event+0x8b/0xa0
> [ 5448.105068] [<ffffffff8115bec3>] perf_init_event+0x133/0x160
> [ 5448.111689] [<ffffffff8115bd90>] ? perf_bp_event+0x90/0x90
> [ 5448.118116] [<ffffffff8115c31a>] perf_event_alloc+0x42a/0x680
> [ 5448.124825] [<ffffffff8115c937>] SYSC_perf_event_open+0x3c7/0xd20
> [ 5448.131946] [<ffffffff8115d709>] SyS_perf_event_open+0x9/0x10
> [ 5448.138640] [<ffffffff816a8d32>] entry_SYSCALL_64_fastpath+0x16/0x7a
> [ 5448.146065] ---[ end trace 5d38212a775ec3f4 ]---
> [ 5448.228748] ------------[ cut here ]------------
> [ 5448.234201] WARNING: CPU: 2 PID: 4247 at kernel/kprobes.c:955 disarm_kprobe+0xf8/0x100()
> [ 5448.243366] Failed to init kprobe-ftrace (-19)
> [ 5448.327114] CPU: 2 PID: 4247 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
> [ 5448.336416] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 5448.344935] ffffffff81a2894e ffff8801187a79e8 ffffffff816a0fd3 0000000000000000
> [ 5448.353549] ffff8801187a7a38 ffff8801187a7a28 ffffffff8106ec8a ffffffff81124f6a
> [ 5448.362177] ffff88011847b810 ffff88011847b810 ffff88011847b800 ffff8801160c02a8
> [ 5448.370824] Call Trace:
> [ 5448.374033] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
> [ 5448.380146] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 5448.387148] [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
> [ 5448.394880] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 5448.401603] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
> [ 5448.407920] [<ffffffff81119208>] disarm_kprobe+0xf8/0x100
> [ 5448.414326] [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
> [ 5448.420874] [<ffffffff811192f7>] disable_kprobe+0x27/0x50
> [ 5448.427222] [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
> [ 5448.434140] [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
> [ 5448.440586] [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
> [ 5448.448349] [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
> [ 5448.455058] [<ffffffff81152e59>] tp_perf_event_destroy+0x9/0x10
> [ 5448.461945] [<ffffffff81158f61>] _free_event+0xc1/0x250
> [ 5448.468093] [<ffffffff811591fa>] put_event+0x10a/0x150
> [ 5448.474167] [<ffffffff8115911b>] ? put_event+0x2b/0x150
> [ 5448.480313] [<ffffffff81152db5>] ? perf_fasync+0x55/0x70
> [ 5448.486552] [<ffffffff81159260>] perf_release+0x10/0x20
> [ 5448.492735] [<ffffffff811df3ec>] __fput+0xdc/0x1e0
> [ 5448.498420] [<ffffffff811df53e>] ____fput+0xe/0x10
> [ 5448.504110] [<ffffffff8108c27b>] task_work_run+0x9b/0xb0
> [ 5448.510315] [<ffffffff81071615>] do_exit+0x3a5/0xa90
> [ 5448.516184] [<ffffffff8107d182>] ? get_signal+0xe2/0x720
> [ 5448.522407] [<ffffffff81071da4>] do_group_exit+0x54/0xe0
> [ 5448.528671] [<ffffffff8107d320>] get_signal+0x280/0x720
> [ 5448.534830] [<ffffffff81013478>] do_signal+0x28/0xb50
> [ 5448.540792] [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
> [ 5448.548277] [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
> [ 5448.554413] [<ffffffff81014002>] do_notify_resume+0x62/0x70
> [ 5448.560950] [<ffffffff816a9a1e>] retint_signal+0x44/0x86
> [ 5448.567208] ---[ end trace 5d38212a775ec3f5 ]---
> [ 5448.572624] ------------[ cut here ]------------
> [ 5448.578045] WARNING: CPU: 2 PID: 4247 at kernel/kprobes.c:959 disarm_kprobe+0xca/0x100()
> [ 5448.587194] Failed to disarm kprobe-ftrace at ffffffff81196670 (-19)
> [ 5448.672321] CPU: 2 PID: 4247 Comm: perf_fuzzer Tainted: G W 4.2.0-rc1+ #169
> [ 5448.681431] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [ 5448.689813] ffffffff81a2894e ffff8801187a79e8 ffffffff816a0fd3 0000000000000000
> [ 5448.698271] ffff8801187a7a38 ffff8801187a7a28 ffffffff8106ec8a ffffffff81124f6a
> [ 5448.706783] ffff88011847b810 ffff88011847b810 ffff88011847b800 ffff8801160c02a8
> [ 5448.715255] Call Trace:
> [ 5448.718342] [<ffffffff816a0fd3>] dump_stack+0x45/0x57
> [ 5448.724346] [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [ 5448.731233] [<ffffffff81124f6a>] ? unregister_ftrace_function+0x1a/0x50
> [ 5448.738872] [<ffffffff8106ed06>] warn_slowpath_fmt+0x46/0x50
> [ 5448.745467] [<ffffffff816a686e>] ? mutex_unlock+0xe/0x10
> [ 5448.751708] [<ffffffff81196670>] ? vm_insert_mixed+0x40/0x40
> [ 5448.758336] [<ffffffff811191da>] disarm_kprobe+0xca/0x100
> [ 5448.764683] [<ffffffff811192a9>] __disable_kprobe+0x99/0xc0
> [ 5448.771186] [<ffffffff811192f7>] disable_kprobe+0x27/0x50
> [ 5448.777504] [<ffffffff81142863>] disable_trace_kprobe+0xc3/0xf0
> [ 5448.784424] [<ffffffff8114345d>] kprobe_register+0x2d/0xe0
> [ 5448.790863] [<ffffffff8113da83>] perf_trace_event_unreg.isra.1+0x33/0x90
> [ 5448.798558] [<ffffffff8113dddc>] perf_trace_destroy+0x3c/0x50
> [ 5448.805285] [<ffffffff81152e59>] tp_perf_event_destroy+0x9/0x10
> [ 5448.812218] [<ffffffff81158f61>] _free_event+0xc1/0x250
> [ 5448.818384] [<ffffffff811591fa>] put_event+0x10a/0x150
> [ 5448.824422] [<ffffffff8115911b>] ? put_event+0x2b/0x150
> [ 5448.830593] [<ffffffff81152db5>] ? perf_fasync+0x55/0x70
> [ 5448.836862] [<ffffffff81159260>] perf_release+0x10/0x20
> [ 5448.843023] [<ffffffff811df3ec>] __fput+0xdc/0x1e0
> [ 5448.848709] [<ffffffff811df53e>] ____fput+0xe/0x10
> [ 5448.854382] [<ffffffff8108c27b>] task_work_run+0x9b/0xb0
> [ 5448.860620] [<ffffffff81071615>] do_exit+0x3a5/0xa90
> [ 5448.866469] [<ffffffff8107d182>] ? get_signal+0xe2/0x720
> [ 5448.872714] [<ffffffff81071da4>] do_group_exit+0x54/0xe0
> [ 5448.878990] [<ffffffff8107d320>] get_signal+0x280/0x720
> [ 5448.885163] [<ffffffff81013478>] do_signal+0x28/0xb50
> [ 5448.891117] [<ffffffff810b78f6>] ? __lock_acquire.isra.31+0x3a6/0xf90
> [ 5448.898586] [<ffffffff810815a5>] ? sys_getppid+0x5/0x80
> [ 5448.904712] [<ffffffff81014002>] do_notify_resume+0x62/0x70
> [ 5448.911245] [<ffffffff816a9a1e>] retint_signal+0x44/0x86
> [ 5448.917526] ---[ end trace 5d38212a775ec3f6 ]---
>
>
--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
On 2015/07/08 6:21, Alexei Starovoitov wrote:
> On Tue, Jul 07, 2015 at 05:08:51PM -0400, Vince Weaver wrote:
>> On Tue, 7 Jul 2015, Alexei Starovoitov wrote:
>>
>>> On Tue, Jul 07, 2015 at 12:00:12AM -0400, Vince Weaver wrote:
>>>>
>>>> Well the BPF hack is in the fuzzer, not the kernel. And it's not really a
>>>> hack, it just turned out to be a huge pain to figure out how to
>>>> manually create a valid BPF program in conjunction with a valid kprobe
>>>> event.
>>>
>>> You mean automatically generating valid bpf program? That's definitely hard.
>>> If you mean just few hardcoded programs then take them from samples or
>>> from test_bpf ?
>>
>> there's already code in trinity that in theory autogenerates bpf programs,
>> but for now I was just trying to hook up a short known valid one.
>>
>> it might not be possible to really test things though, as you need to be
>> root to create a kprobe and attach a BPF program, but my fuzzer when run
>> as root often does all kinds of other stuff that will crash a machine.
>> Is it ever planned to allow using bpf/kprobes without requiring full
>> CAP_ADMIN privledges?
>
> I suspect kprobes will forever be root only, whereas for bpf I'm thinking
> to introduce CAP_BPF, but before that we need to finish constant blinding
> and add address leak prevention. So not soon.
Currently I don't plan to do that. Actually systemtap allows that, but
with much bigger blacklist. I think we can make a tool which also
allows user to add new events on the limited functions (white-list).
But anyway, since these can expose kernel function addresses to users,
it is highly recommended to limit users by some capabilities.
>>>> I did have to sprinkle printks in the kprobe and bpf code to find out
>>>> where various EINVAL returns were coming from, so potentially this is just
>>>> a problem of printks happening where they shouldn't. I'll remove those
>>>> changes and try to reproduce this tomorrow.
>>>
>>> could you please elaborate on this further. Which EINVALs you talking about?
>>
>> When you are trying to create a kprobe and bpf file there's about 10
>> different ways to get EINVAL as a return value and no way of knowing which
>> one you are hitting. I added printks so I could know what issue was
>> causing the einval. (from memory, the problems I hit were not zeroing out
>> the attr structure, having a wrong instruction count, and a few others).
Hmm I must fix some parts of kprobes by changing retval or showing more
precise messages.
Thanks!
> I see. I guess anyone trying to use syscall directly will be facing such
> issues, but libbpf that is being developed to be used by perf and others
> should solve these problems.
--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
On 2015/07/08 0:11, Vince Weaver wrote:
> On Tue, 7 Jul 2015, Vince Weaver wrote:
>
>> On Tue, 7 Jul 2015, Masami Hiramatsu wrote:
>>
>>>> It's a Hawell machine running 4.2-rc1. I can post the .config if it's of
>>>> interest.
>>>
>>> Yes, I'm interested in.
>>
>> I've put it here:
>> http://web.eece.maine.edu/~vweaver/junk/haswell-config
>>
>>> OK, and also, if you have a chance, please run the ftracetest as below.
>>>
>>> $ cd tools/testing/selftest/ftrace/
>>> $ sudo ./ftracetest
>>>
>>> This will do a series of basic tests on ftrace and report it.
>>
>> It won't run:
>> sudo ./ftracetest
>> Error: No ftrace directory found
>>
>
> OK here are the results when I mounted debugfs in the right place.
Thanks, I've found do_fork does not exist anymore... that caused the
failure.
Unsupported results are just because of the lack of function profiler
from kconfig.
Thank you for reporting!
>
> sudo ./ftracetest
> === Ftrace unit tests ===
> [1] Basic trace file check [PASS]
> [2] Basic test for tracers [PASS]
> [3] Basic trace clock test [PASS]
> [4] Basic event tracing check [PASS]
> [5] event tracing - enable/disable with event level files [PASS]
> [6] event tracing - enable/disable with subsystem level files [PASS]
> [7] event tracing - enable/disable with top level files [PASS]
> [8] ftrace - function graph filters with stack tracer [UNSUPPORTED]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
> + grep -q function_graph available_tracers
> + [ ! -f set_ftrace_filter ]
> + disable_tracing
> + echo 0
> + clear_trace
> + echo
> + echo schedule
> + echo function_graph
> + [ ! -f stack_trace ]
> + echo Stack tracer not configured
> Stack tracer not configured
> + do_reset
> + reset_tracer
> + echo nop
> + [ -e /proc/sys/kernel/stack_tracer_enabled ]
> + enable_tracing
> + echo 1
> + clear_trace
> + echo
> + echo
> + exit_unsupported
> + kill -s 40 2725
> + exit 0
> [9] ftrace - function graph filters [PASS]
> [10] ftrace - function profiler with function tracing [UNSUPPORTED]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/func_profiler.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/ftrace/func_profiler.tc
> + grep -q function_graph available_tracers
> + [ ! -f set_ftrace_filter ]
> + [ ! -f function_profile_enabled ]
> + echo function_profile_enabled not found, function profiling enabled?
> function_profile_enabled not found, function profiling enabled?
> + exit_unsupported
> + kill -s 40 2725
> + exit 0
> [11] Kprobe dynamic event - adding and removing [FAIL]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/add_and_remove.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/add_and_remove.tc
> + [ -f kprobe_events ]
> + echo 0
> + echo
> + echo p:myevent do_fork
> sh: echo: I/O error
> [12] Kprobe dynamic event - busy event check [FAIL]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/busy_check.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/busy_check.tc
> + [ -f kprobe_events ]
> + echo 0
> + echo
> + echo p:myevent do_fork
> sh: echo: I/O error
> [13] Kprobe dynamic event with arguments [FAIL]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args.tc
> + [ -f kprobe_events ]
> + echo 0
> + echo
> + echo p:testprobe do_fork $stack $stack0 +0($stack)
> sh: echo: I/O error
> [14] Kprobe dynamic event with function tracer [FAIL]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_ftrace.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_ftrace.tc
> + [ -f kprobe_events ]
> + grep function available_tracers
> blk function_graph function nop
> + echo nop
> + echo do_fork
> sh: echo: I/O error
> [15] Kretprobe dynamic event with arguments [FAIL]
> execute:
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
> + .
> /home/vince/research/linux-kernel/linux-git/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
> + [ -f kprobe_events ]
> + echo 0
> + echo
> + echo r:testprobe2 do_fork $retval
> sh: echo: I/O error
>
> # of passed: 8
> # of failed: 5
> # of unresolved: 0
> # of untested: 0
> # of unsupported: 2
> # of xfailed: 0
> # of undefined(test bug): 0
>
>
--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]