Re: [PATCH 0/7] selftests/ftrace: Some improvements of ftracetest
From: Shuah Khan
Date: Wed Jun 07 2017 - 18:43:04 EST
On 05/23/2017 12:02 AM, Masami Hiramatsu wrote:
> Hi,
>
> This series improves ftracetest mainly to run on 4.9 stable
> tree kernel. There still some issues remains (it seems some
> fixes are not merged), but a half of issues are fixed.
>
> NOTE: One patch will modify ftrace README to check the
> availability of the maxactive option, which should have
> been implemented with the function-added patch.
>
> With this series, only 1 test actually failed on 4.9.29.
> (and 3 unsupported, since it is too old to support it)
>
> Tue May 23 05:56:24 UTC 2017
> === 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 - restricts events based on pid [PASS]
> [7] event tracing - enable/disable with subsystem level files [PASS]
> [8] event tracing - enable/disable with top level files [PASS]
> [9] ftrace - function graph filters with stack tracer [PASS]
> [10] ftrace - function graph filters [PASS]
> [11] ftrace - function glob filters [PASS]
> [12] ftrace - function pid filters [PASS]
> [13] ftrace - test for function event triggers [PASS]
> [14] ftrace - function profiler with function tracing [PASS]
> [15] ftrace - test reading of set_ftrace_filter [FAIL]
> [16] ftrace - test for function traceon/off triggers [PASS]
> [17] Test creation and deletion of trace instances while setting an event [PASS]
> [18] Test creation and deletion of trace instances [PASS]
> [19] Kprobe dynamic event - adding and removing [PASS]
> [20] Kprobe dynamic event - busy event check [PASS]
> [21] Kprobe dynamic event with arguments [PASS]
> [22] Kprobes event arguments with types [PASS]
> [23] Kprobe dynamic event with function tracer [PASS]
> [24] Kretprobe dynamic event with arguments [PASS]
> [25] Kretprobe dynamic event with maxactive [UNSUPPORTED]
> [26] event trigger - test event enable/disable trigger [PASS]
> [27] event trigger - test trigger filter [PASS]
> [28] event trigger - test histogram modifiers [PASS]
> [29] event trigger - test histogram trigger [PASS]
> [30] event trigger - test multiple histogram triggers [PASS]
> [31] event trigger - test snapshot-trigger [PASS]
> [32] event trigger - test stacktrace-trigger [PASS]
> [33] event trigger - test traceon/off trigger [PASS]
> [34] (instance) Basic test for tracers [PASS]
> [35] (instance) Basic trace clock test [PASS]
> [36] (instance) event tracing - enable/disable with event level files [PASS]
> [37] (instance) event tracing - restricts events based on pid [PASS]
> [38] (instance) event tracing - enable/disable with subsystem level files [PASS]
> [39] (instance) ftrace - test for function event triggers [UNSUPPORTED]
> [40] (instance) ftrace - test for function traceon/off triggers [UNSUPPORTED]
> [41] (instance) event trigger - test event enable/disable trigger [PASS]
> [42] (instance) event trigger - test trigger filter [PASS]
> [43] (instance) event trigger - test histogram modifiers [PASS]
> [44] (instance) event trigger - test histogram trigger [PASS]
> [45] (instance) event trigger - test multiple histogram triggers [PASS]
>
> # of passed: 41
> # of failed: 1
> # of unresolved: 0
> # of untested: 0
> # of unsupported: 3
> # of xfailed: 0
> # of undefined(test bug): 0
>
>
>> [15] ftrace - test reading of set_ftrace_filter [FAIL]
> was caused by the difference of the result of
> "dd bs=1 if=set_ftrace_filter" and "cat set_ftrace_filter",
> which has been fixed on upstream by commit fcdc71257923
> ("ftrace: Fix indexing of t_hash_start() from t_next()")
> but backporting it onto 4.9.y stable tree didn't fix that.
>
>
> Thank you,
>
> ---
>
> Masami Hiramatsu (7):
> selftests/ftrace: Skip full-glob-matching filter test on older kernel
> selftests/ftrace: Reduce trace buffer checking overhead
> ftrace/kprobes: selftests: Check kretprobe maxactive is supported
> selftests/ftrace: Reset ftrace filter on older kernel
> selftests/ftrace: Add instance indication in test log
> selftests/ftrace: Use top-level available_filter_function
> selftests/ftrace: Return unsupported if it detects older kernel
>
>
> kernel/trace/trace.c | 3 +-
> tools/testing/selftests/ftrace/ftracetest | 2 +
> .../ftrace/test.d/event/toplevel-enable.tc | 8 ++++--
> .../ftrace/test.d/ftrace/func-filter-glob.tc | 28 ++++++++++++--------
> .../ftrace/test.d/ftrace/func_event_triggers.tc | 9 ++++++
> .../test.d/ftrace/func_traceonoff_triggers.tc | 13 +++++++++
> .../ftrace/test.d/instances/instance-event.tc | 5 +++-
> .../ftrace/test.d/kprobe/kretprobe_maxactive.tc | 1 +
> 8 files changed, 53 insertions(+), 16 deletions(-)
>
> --
> Masami Hiramatsu (Linaro) <mhiramat@xxxxxxxxxx>
>
>
Hi Masami/Steve,
I applied this series to linux-kselftest next. I am seeing these
errors when ftracetest runs.
Is this a known problem? Has this been fixed? I am guessing this
problem is in the tracing sub-system. I ran the test on linux-kselftest
next which is based on 4.12-rc4
Am I missing a trace sub-system fix.
[ 5507.393998] ------------[ cut here ]------------
[ 5507.394010] WARNING: CPU: 2 PID: 30258 at kernel/trace/ring_buffer.c:4215 ring_buffer_reset_cpu+0x798/0xd00
[ 5507.394013] Modules linked in: binfmt_misc x86_pkg_temp_thermal coretemp kvm_intel kvm irqbypass ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd cryptd glue_helper snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_timer lpc_ich mac_hid tpm_tis tpm_tis_core parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs xor hid_generic usbhid hid raid6_pq dm_mirror dm_region_hash dm_log usb_storage i915 iosf_mbi i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops r8169 drm mii wmi video
[ 5507.394194] CPU: 2 PID: 30258 Comm: ftracetest Tainted: G W 4.12.0-rc4 #16
[ 5507.394198] Hardware name: System76, Inc. Wild Dog Performance/H87-PLUS, BIOS 0705 12/05/2013
[ 5507.394202] task: ffff88033c7e0000 task.stack: ffff880378798000
[ 5507.394207] RIP: 0010:ring_buffer_reset_cpu+0x798/0xd00
[ 5507.394211] RSP: 0018:ffff88037879f9c8 EFLAGS: 00010006
[ 5507.394218] RAX: ffff88038f410a00 RBX: ffff88038f418480 RCX: 0000000000000282
[ 5507.394222] RDX: 1ffff10071e83091 RSI: 00000000e018b669 RDI: ffff88038f418488
[ 5507.394226] RBP: ffff88037879fa08 R08: ffff88038f418550 R09: ffffffff83a8ef00
[ 5507.394230] R10: ffff88037879f928 R11: ffffffff834940e0 R12: 0000000000000007
[ 5507.394234] R13: ffff88038f418490 R14: ffff88038f410a00 R15: ffff88037d18ac00
[ 5507.394239] FS: 00007f0787844700(0000) GS:ffff88038f880000(0000) knlGS:0000000000000000
[ 5507.394242] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5507.394246] CR2: 0000561f7a0e5bb8 CR3: 00000003637eb000 CR4: 00000000001406e0
[ 5507.394250] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 5507.394253] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 5507.394257] Call Trace:
[ 5507.394272] tracing_reset_online_cpus+0xd2/0x160
[ 5507.394283] tracing_open+0x18b/0x200
[ 5507.394295] do_dentry_open+0x630/0xba0
[ 5507.394301] ? generic_permission+0x4f/0x320
[ 5507.394310] ? tracing_snapshot_open+0x2e0/0x2e0
[ 5507.394323] vfs_open+0xf1/0x270
[ 5507.394329] ? may_open+0xc7/0x2e0
[ 5507.394339] path_openat+0xccc/0x2610
[ 5507.394360] ? path_lookupat+0x880/0x880
[ 5507.394366] ? entry_SYSCALL_64_fastpath+0x18/0xad
[ 5507.394386] ? debug_check_no_locks_freed+0x280/0x280
[ 5507.394413] do_filp_open+0x17c/0x260
[ 5507.394421] ? may_open_dev+0xc0/0xc0
[ 5507.394444] ? _raw_spin_unlock+0x27/0x30
[ 5507.394452] ? __alloc_fd+0x191/0x4b0
[ 5507.394475] do_sys_open+0x175/0x350
[ 5507.394479] ? do_sys_open+0x175/0x350
[ 5507.394488] ? filp_open+0x60/0x60
[ 5507.394498] ? trace_hardirqs_on_thunk+0x1a/0x1c
[ 5507.394510] SyS_open+0x1e/0x20
[ 5507.394516] entry_SYSCALL_64_fastpath+0x18/0xad
[ 5507.394521] RIP: 0033:0x7f0787373a70
[ 5507.394524] RSP: 002b:00007fffab7a9f68 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
[ 5507.394532] RAX: ffffffffffffffda RBX: 0000561f7a0e60f0 RCX: 00007f0787373a70
[ 5507.394535] RDX: 00000000000001b6 RSI: 0000000000000241 RDI: 0000561f7a0ef058
[ 5507.394539] RBP: 0000000000000046 R08: 0000561f7a0e6158 R09: 0000561f7a0ef001
[ 5507.394543] R10: 0000561f7a0e8260 R11: 0000000000000246 R12: 0000000000000020
[ 5507.394547] R13: 0000561f7a0ef010 R14: 0000561f7a0e5b90 R15: 00007fffab7aa1a0
[ 5507.394571] Code: 41 5f 5d c3 48 8d 7b 08 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 51 05 00 00 48 8b 43 08 f0 ff 40 08 <0f> ff eb b2 48 89 d7 89 c6 4c 89 45 c0 48 89 4d c8 48 89 55 d0
[ 5507.394761] ---[ end trace ea9d726487ff6f82 ]---
thanks,
-- Shuah