Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com>
Date:   Thu, 9 Jan 2020 12:10:59 -0300
To:     Jann Horn <jannh@google.com>
Cc:     Andi Kleen <ak@linux.intel.com>,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.com>,
        Mark Rutland <mark.rutland@arm.com>,
        Alexander Shishkin <alexander.shishkin@linux.intel.com>,
        Jiri Olsa <jolsa@redhat.com>,
        Namhyung Kim <namhyung@kernel.org>,
        kernel list <linux-kernel@vger.kernel.org>
Subject: Re: "perf ftrace" segfault because ->cpus!=NULL but ->all_cpus==NULL
Message-ID: <20200109151059.GB8602@kernel.org>
References: <CAG48ez0eULP6pH26H9ac-YYa88_RSGt6v_hDhsrZ92iZoRdsoQ@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <CAG48ez0eULP6pH26H9ac-YYa88_RSGt6v_hDhsrZ92iZoRdsoQ@mail.gmail.com>
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Em Thu, Jan 09, 2020 at 12:37:14PM +0100, Jann Horn escreveu:
> I was clumsily trying to use "perf ftrace" from git master (I might
> very well be using it wrong), and it's falling over with a NULL deref.
> I don't really understand the perf code, but it looks to me like it
> might be related to Andi Kleen's refactoring that introduced
> evlist->all_cpus?
 
> I think the problem is that evlist_close() assumes that ->cpus!=NULL
> implies ->all_cpus!=NULL, but perf_evlist__propagate_maps() doesn't
> set ->all_cpus if the evlist is empty.
 
> Here's the crash I encountered:

I've reproduced it and Jiri provided a patch, I'll test it, meanwhile
you could alternatively drop an 'f' and try 'perf trace' + 'perf probe'
instead, perhaps that could be enough, some examples:

[root@quaco ~]# perf probe kmem_cache_alloc
Added new event:
  probe:kmem_cache_alloc (on kmem_cache_alloc)

You can now use it in all perf tools, such as:

	perf record -e probe:kmem_cache_alloc -aR sleep 1

[root@quaco ~]# 

Bump the ring buffer size with -m for high freq events, limit the
backtrace size at the kernel so as to reduce the flow of events, limit
the number of events:

[root@quaco ~]# perf trace -m1024 -e probe:kmem_cache_alloc/max-stack=8/ --max-events=4
     0.000 :0/0 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       __build_skb ([kernel.kallsyms])
                                       __napi_alloc_skb ([kernel.kallsyms])
                                       r8152_poll ([r8152])
                                       net_rx_action ([kernel.kallsyms])
                                       __do_softirq ([kernel.kallsyms])
                                       irq_exit ([kernel.kallsyms])
                                       do_IRQ ([kernel.kallsyms])
     0.869 :0/0 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       __build_skb ([kernel.kallsyms])
                                       __napi_alloc_skb ([kernel.kallsyms])
                                       r8152_poll ([r8152])
                                       net_rx_action ([kernel.kallsyms])
                                       __do_softirq ([kernel.kallsyms])
                                       irq_exit ([kernel.kallsyms])
                                       do_IRQ ([kernel.kallsyms])
    37.427 :0/0 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       __build_skb ([kernel.kallsyms])
                                       __napi_alloc_skb ([kernel.kallsyms])
                                       r8152_poll ([r8152])
                                       net_rx_action ([kernel.kallsyms])
                                       __do_softirq ([kernel.kallsyms])
                                       irq_exit ([kernel.kallsyms])
                                       do_IRQ ([kernel.kallsyms])
    37.450 :0/0 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       __build_skb ([kernel.kallsyms])
                                       __napi_alloc_skb ([kernel.kallsyms])
                                       r8152_poll ([r8152])
                                       net_rx_action ([kernel.kallsyms])
                                       __do_softirq ([kernel.kallsyms])
                                       irq_exit ([kernel.kallsyms])
                                       do_IRQ ([kernel.kallsyms])
[root@quaco ~]#


Mix and match with syscall names, using globs, limit stacks for multiple
events, i.e. you can use 'perf probe kmem_*' to add all kernel functions
with that prefix, for instance:

[root@quaco ~]# perf trace -m1024 -e inotify*,stat*,probe:kmem_*/max-stack=8/ --max-events=4
     0.000 (         ): :0/0 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       __build_skb ([kernel.kallsyms])
                                       __netdev_alloc_skb ([kernel.kallsyms])
                                       br_send_bpdu.isra.0.constprop.0 ([bridge])
                                       br_send_config_bpdu ([bridge])
                                       br_transmit_config.part.0 ([bridge])
                                       br_config_bpdu_generation ([bridge])
                                       br_hello_timer_expired ([bridge])
    51.901 (         ): weechat/6630 stat(filename: 0xc5be4063, statbuf: 0x7ffdfe73f050)                ...
    51.905 (         ): weechat/6630 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       getname_flags ([kernel.kallsyms])
                                       user_path_at_empty ([kernel.kallsyms])
                                       vfs_statx ([kernel.kallsyms])
                                       __do_sys_newstat ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       __xstat64 (/usr/lib64/libc-2.29.so)
    51.901 ( 0.018 ms): weechat/6630  ... [continued]: stat())                                             = 0
[root@quaco ~]#

Are you interested only in some specific syscall? Use
switch-on/switch-off to mark when to show events when to stop showing,
works for any event, even one that you mark in the middle of some
function and then at some other point in time, need to make it work with
plain syscall names:

[root@quaco ~]# perf trace -m1024 -e syscalls:sys_*_newstat,probe:kmem_*/max-stack=8/ --max-events=4 --switch-on=syscalls:sys_enter_newstat --switch-off=syscalls:sys_exit_newstat
     0.000 weechat/6630 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       getname_flags ([kernel.kallsyms])
                                       user_path_at_empty ([kernel.kallsyms])
                                       vfs_statx ([kernel.kallsyms])
                                       __do_sys_newstat ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       __xstat64 (/usr/lib64/libc-2.29.so)
    75.843 :9367/9367 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       getname_flags ([kernel.kallsyms])
                                       user_path_at_empty ([kernel.kallsyms])
                                       vfs_statx ([kernel.kallsyms])
                                       __do_sys_newstat ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       __xstat64 (/usr/lib64/libc-2.29.so)
   768.592 NetworkManager/9368 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       getname_flags ([kernel.kallsyms])
                                       user_path_at_empty ([kernel.kallsyms])
                                       vfs_statx ([kernel.kallsyms])
                                       __do_sys_newstat ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       __xstat64 (/usr/lib64/libc-2.29.so)
   999.927 weechat/6630 probe:kmem_cache_alloc(__probe_ip: -1842593216)
                                       kmem_cache_alloc ([kernel.kallsyms])
                                       getname_flags ([kernel.kallsyms])
                                       user_path_at_empty ([kernel.kallsyms])
                                       vfs_statx ([kernel.kallsyms])
                                       __do_sys_newstat ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       __xstat64 (/usr/lib64/libc-2.29.so)
[root@quaco ~]#

- Arnaldo