Message-ID: <20170607185628.452a11a1@gandalf.local.home>
Date:   Wed, 7 Jun 2017 18:56:28 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Shuah Khan <shuah@...nel.org>
Cc:     Masami Hiramatsu <mhiramat@...nel.org>,
        linux-kselftest@...r.kernel.org, Ingo Molnar <mingo@...hat.com>,
        linux-kernel@...r.kernel.org, Shuah Khan <shuahkh@....samsung.com>
Subject: Re: [PATCH 0/7] selftests/ftrace: Some improvements of ftracetest

On Wed, 7 Jun 2017 16:42:55 -0600
Shuah Khan <shuah@...nel.org> wrote:

> 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@...nel.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.

No this is new to me. Just to confirm, you see this on 4.12-rc4 right?
Can you send me your config.

Thanks!

-- Steve

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

Powered by blists - more mailing lists