Re: Perf events warning..

[David Ahern <dsahern@gmail.com>]

On 5/14/12 4:20 PM, Peter Zijlstra wrote:
> On Fri, 2012-05-11 at 08:43 -0700, Linus Torvalds wrote:
>> Peter, Ingo, Arnaldo,
>>   google doesn't find a warning like this, so it can't be *too*
>> commonly reported.
>>
>> Anyway, doing some profiling of git "make test" (wonderful load for
>> doing lots of small processes that do lots of page faults etc), this
>> WARN_ON_ONCE() triggered:
>>
>>      ------------[ cut here ]------------
>>      WARNING: at kernel/events/core.c:2066 task_ctx_sched_out+0x63/0x70()
>>      Hardware name: System Product Name
>>      Pid: 18120, comm: git Not tainted 3.4.0-rc6-00089-g4a01c681d58f-dirty #3
>>      Call Trace:
>>       [<ffffffff810308c5>] warn_slowpath_common+0x75/0xb0
>>       [<ffffffff810309c5>] warn_slowpath_null+0x15/0x20
>>       [<ffffffff81096d63>] task_ctx_sched_out+0x63/0x70
>>       [<ffffffff8109af06>] perf_event_comm+0x1d6/0x2e0
>>       [<ffffffff81368ba8>] ? get_random_int+0x88/0xb0
>>       [<ffffffff8102e1e2>] ? __mmdrop+0x62/0x90
>>       [<ffffffff810e1f93>] set_task_comm+0x63/0x80
>>       [<ffffffff810e3206>] setup_new_exec+0x86/0x250
>>       [<ffffffff81126b69>] load_elf_binary+0x389/0x1930
>>       [<ffffffff81125222>] ? load_misc_binary+0x292/0x390
>>       [<ffffffff810bcbdd>] ? get_user_pages+0x4d/0x50
>>       [<ffffffff810e13b2>] ? get_arg_page+0xa2/0xd0
>>       [<ffffffff810e2b65>] search_binary_handler+0xd5/0x200
>>       [<ffffffff811267e0>] ? elf_map+0x170/0x170
>>       [<ffffffff810e300d>] do_execve_common.clone.39+0x37d/0x430
>>       [<ffffffff810e30d6>] do_execve+0x16/0x20
>>       [<ffffffff8100ab75>] sys_execve+0x45/0x70
>>       [<ffffffff816b10ac>] stub_execve+0x6c/0xc0
>>      ---[ end trace 6fccf3db70f1b560 ]---
>>
>> any comments/ideas?
>
> So far I can't make any of the things I came up stick. You ran something
> simple like: 'perf record -e cycles:pp -F 20000 make test' ? Or did you
> do something more interesting?

By chance I just hit this:
[   31.528795] WARNING: at 
/mnt/sw/kernel-2.6.git/arch/x86/kernel/cpu/perf_event.c:1054 
x86_pmu_start+0xdc/0x110()
[   31.528799] Hardware name: Bochs
[   31.528801] Modules linked in: nfs fscache auth_rpcgss nfs_acl lockd 
ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 
nf_defrag_ipv4 xt_state ip6table_filter nf_conntrack ip6_tables 
virtio_net ppdev i2c_piix4 parport_pc parport i2c_core sunrpc virtio_blk 
[last unloaded: scsi_wait_scan]
[   31.528825] Pid: 959, comm: find Not tainted 3.4.0-rc6+ #1
[   31.528827] Call Trace:
[   31.528835]  [<ffffffff8105792f>] warn_slowpath_common+0x7f/0xc0
[   31.528839]  [<ffffffff8105798a>] warn_slowpath_null+0x1a/0x20
[   31.528843]  [<ffffffff8102543c>] x86_pmu_start+0xdc/0x110
[   31.528847]  [<ffffffff81025af2>] x86_pmu_enable+0x212/0x270
[   31.528854]  [<ffffffff81116466>] perf_event_context_sched_in+0xe6/0x100
[   31.528857]  [<ffffffff81118083>] perf_event_comm+0x103/0x2b0
[   31.528863]  [<ffffffff81184342>] set_task_comm+0x72/0xe0
[   31.528867]  [<ffffffff81184a1b>] setup_new_exec+0x8b/0x240
[   31.528873]  [<ffffffff811cc8b7>] load_elf_binary+0x3e7/0x19a0
[   31.528879]  [<ffffffff811443c2>] ? get_user_pages+0x52/0x60
[   31.528883]  [<ffffffff81182708>] ? get_user_arg_ptr+0x38/0x80
[   31.528887]  [<ffffffff81182bae>] search_binary_handler+0xee/0x340
[   31.528891]  [<ffffffff811cc4d0>] ? load_elf_library+0x230/0x230
[   31.528895]  [<ffffffff811847ff>] do_execve_common+0x36f/0x410
[   31.528899]  [<ffffffff811848da>] do_execve+0x3a/0x40
[   31.528903]  [<ffffffff8101d477>] sys_execve+0x47/0x70
[   31.528908]  [<ffffffff815f226c>] stub_execve+0x6c/0xc0
[   31.528911] ---[ end trace ba6387065a9b9696 ]---

As for the something interesting part - not really: debugging the 
regression on 'perf stat --group -- find /usr >/dev/null'

David