Reply-To: shuah@kernel.org
Subject: Re: [PATCH 0/7] selftests/ftrace: Some improvements of ftracetest
To: Masami Hiramatsu <mhiramat@kernel.org>,
        linux-kselftest@vger.kernel.org, Steven Rostedt <rostedt@goodmis.org>
Cc: Ingo Molnar <mingo@redhat.com>, linux-kernel@vger.kernel.org,
        Shuah Khan <shuahkh@osg.samsung.com>, Shuah Khan <shuah@kernel.org>
References: <149551934796.30231.12544755801380678045.stgit@devbox>
From: Shuah Khan <shuah@kernel.org>
Message-ID: <4b0b2ac8-dfba-abd9-3dba-bbe73c22f79f@kernel.org>
Date: Wed, 7 Jun 2017 16:42:55 -0600
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
 Thunderbird/52.1.1
MIME-Version: 1.0
In-Reply-To: <149551934796.30231.12544755801380678045.stgit@devbox>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 8bit
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 9133
Lines: 171

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@kernel.org>
> 
> 

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