1. 24 Oct, 2018 2 commits
    • Andi Kleen's avatar
      perf script: Make itrace script default to all calls · 4eb06815
      Andi Kleen authored
      By default 'perf script' for itrace outputs sampled instructions or
      branches. In my experience this is confusing to users because it's hard
      to correlate with real program behavior. The sampling makes sense for
      tools like 'perf report' that actually sample to reduce the run time,
      but run time is normally not a problem for 'perf script'.  It's better
      to give an accurate representation of the program flow.
      
      Default 'perf script' to output all calls for itrace. That's a much saner
      default. The old behavior can be still requested with 'perf script'
      --itrace=ibxwpe100000
      
      v2: Fix ETM build failure
      v3: Really fix ETM build failure (Kim Phillips)
      Signed-off-by: default avatarAndi Kleen <ak@linux.intel.com>
      Acked-by: default avatarJiri Olsa <jolsa@kernel.org>
      Cc: Kim Phillips <kim.phillips@arm.com>
      Cc: Leo Yan <leo.yan@linaro.org>
      Link: http://lkml.kernel.org/r/20180920180540.14039-3-andi@firstfloor.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      4eb06815
    • Andi Kleen's avatar
      perf script: Add --insn-trace for instruction decoding · b585ebdb
      Andi Kleen authored
      Add a --insn-trace short hand option for decoding and disassembling
      instruction streams for intel_pt. This automatically pipes the output
      into the xed disassembler to generate disassembled instructions.  This
      just makes this use model much nicer to use.
      
      Before
      
        % perf record -e intel_pt// ...
        % perf script --itrace=i0ns --ns -F +insn,-event,-period | xed -F insn: -A -64
         swapper 0 [000] 17276.429606186: ffffffff81010486 pt_config ([kernel.kallsyms])    nopl  %eax, (%rax,%rax,1)
         swapper 0 [000] 17276.429606186: ffffffff8101048b pt_config ([kernel.kallsyms])    add $0x10, %rsp
         swapper 0 [000] 17276.429606186: ffffffff8101048f pt_config ([kernel.kallsyms])    popq  %rbx
         swapper 0 [000] 17276.429606186: ffffffff81010490 pt_config ([kernel.kallsyms])    popq  %rbp
         swapper 0 [000] 17276.429606186: ffffffff81010491 pt_config ([kernel.kallsyms])    popq  %r12
         swapper 0 [000] 17276.429606186: ffffffff81010493 pt_config ([kernel.kallsyms])    popq  %r13
         swapper 0 [000] 17276.429606186: ffffffff81010495 pt_config ([kernel.kallsyms])    popq  %r14
         swapper 0 [000] 17276.429606186: ffffffff81010497 pt_config ([kernel.kallsyms])    popq  %r15
         swapper 0 [000] 17276.429606186: ffffffff81010499 pt_config ([kernel.kallsyms])    retq
         swapper 0 [000] 17276.429606186: ffffffff8101063e pt_event_add ([kernel.kallsyms])         cmpl  $0x1, 0x1b0(%rbx)
         swapper 0 [000] 17276.429606186: ffffffff81010645 pt_event_add ([kernel.kallsyms])         mov $0xffffffea, %eax
         swapper 0 [000] 17276.429606186: ffffffff8101064a pt_event_add ([kernel.kallsyms])         mov $0x0, %edx
         swapper 0 [000] 17276.429606186: ffffffff8101064f pt_event_add ([kernel.kallsyms])         popq  %rbx
         swapper 0 [000] 17276.429606186: ffffffff81010650 pt_event_add ([kernel.kallsyms])         cmovnz %edx, %eax
         swapper 0 [000] 17276.429606186: ffffffff81010653 pt_event_add ([kernel.kallsyms])         jmp 0xffffffff81010635
         swapper 0 [000] 17276.429606186: ffffffff81010635 pt_event_add ([kernel.kallsyms])         retq
         swapper 0 [000] 17276.429606186: ffffffff8115e687 event_sched_in.isra.107 ([kernel.kallsyms])       test %eax, %eax
      
      Now:
      
        % perf record -e intel_pt// ...
        % perf script --insn-trace --xed
        ... same output ...
      
      XED needs to be installed with:
      
        $ git clone https://github.com/intelxed/mbuild.git mbuild
        $ git clone https://github.com/intelxed/xed
        $ cd xed
        $ ./mfile.py
        $ ./mfile.py examples
        $ sudo ./mfile.py --prefix=/usr/local install
        $ sudo cp obj/examples/xed /usr/local/bin
        $ xed | head -3
        ERROR: required argument(s) were missing
        Copyright (C) 2017, Intel Corporation. All rights reserved.
        XED version: [v10.0-328-g7d62c8c49b7b]
        $
      Signed-off-by: default avatarAndi Kleen <ak@linux.intel.com>
      Tested-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      Acked-by: default avatarJiri Olsa <jolsa@kernel.org>
      Link: http://lkml.kernel.org/r/20180920180540.14039-2-andi@firstfloor.org
      [ Fixed up whitespace damage, added the 'mfile.py examples + cp obj/examples/xed ... ]
      Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      b585ebdb
  2. 23 Oct, 2018 16 commits
  3. 22 Oct, 2018 8 commits
    • Adrian Hunter's avatar
      perf scripts python: call-graph-from-sql.py: Use SPDX license identifier · 3e71c70c
      Adrian Hunter authored
      Use SPDX license identifier in call-graph-from-sql.py.
      Signed-off-by: default avatarAdrian Hunter <adrian.hunter@intel.com>
      Cc: Andi Kleen <ak@linux.intel.com>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Link: http://lkml.kernel.org/r/20181001062853.28285-2-adrian.hunter@intel.comSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      3e71c70c
    • Arnaldo Carvalho de Melo's avatar
      perf trace: Introduce per-event maximum number of events property · a9c5e6c1
      Arnaldo Carvalho de Melo authored
      Call it 'nr', as in this context it should be expressive enough, i.e.:
      
        # perf trace -e sched:*waking/nr=8,call-graph=fp/
           0.000 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                             try_to_wake_up ([kernel.kallsyms])
                                             sched_clock ([kernel.kallsyms])
           3.933 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                             try_to_wake_up ([kernel.kallsyms])
                                             sched_clock ([kernel.kallsyms])
           3.970 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          20.069 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          37.170 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          53.267 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          70.365 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          75.781 Web Content/3649 sched:sched_waking:comm=JS Helper pid=3670 prio=120 target_cpu=000
                                             try_to_wake_up ([kernel.kallsyms])
                                             try_to_wake_up ([kernel.kallsyms])
                                             wake_up_q ([kernel.kallsyms])
                                             futex_wake ([kernel.kallsyms])
                                             do_futex ([kernel.kallsyms])
                                             __x64_sys_futex ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
                                             pthread_cond_signal@@GLIBC_2.3.2 (/usr/lib64/libpthread-2.26.so)
        #
      
        # perf trace -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
           0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> trace:3367 [120]
           0.046 :0/0 sched:sched_switch:swapper/1:0 [120] S ==> kworker/u16:58:2722 [120]
         570.670 irq/50-iwlwifi/680 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051ef00 len=66
                                             __dev_queue_xmit ([kernel.kallsyms])
        1106.141 jbd2/dm-0-8/476 block:block_plug:[jbd2/dm-0-8]
        1106.175 jbd2/dm-0-8/476 block:block_unplug:[jbd2/dm-0-8] 1
        1618.088 kworker/u16:30/2694 block:block_plug:[kworker/u16:30]
        1810.000 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051ef00 len=52
                                             __dev_queue_xmit ([kernel.kallsyms])
        3857.974 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051f900 len=52
                                             __dev_queue_xmit ([kernel.kallsyms])
        4790.277 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
        4790.448 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
        #
      
      The global --max-events has precendence:
      
        # trace --max-events 3 -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
           0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> qemu-system-x86:2252 [120]
           0.029 qemu-system-x8/2252 sched:sched_switch:qemu-system-x86:2252 [120] D ==> swapper/0:0 [120]
          58.047 DNS Res~er #14/31661 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff9346966af100 len=84
                                             __dev_queue_xmit ([kernel.kallsyms])
                                             __libc_send (/usr/lib64/libpthread-2.26.so)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-s4jswltvh660ughvg9nwngah@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      a9c5e6c1
    • Milian Wolff's avatar
      perf script: Flush output stream after events in verbose mode · 7ee40678
      Milian Wolff authored
      When the perf script output is written to a terminal stream, the normal
      output of `perf script` would get buffered, but its debug output would
      be written directly. This made it quite hard to figure out where a given
      debug output is coming from.
      
      We can improve on this by flushing the output buffer after processing an
      event. To see the value, compare the following output for a `perf script
      -v` run:
      
      Before this patch:
      ```
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      unwind: find_proc_info dso /usr/lib/ld-2.28.so
      unwind: reg 6, val 0
      unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      unwind: find_proc_info dso /usr/lib/ld-2.28.so
      unwind: reg 6, val 0
      unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      unwind: find_proc_info dso /usr/lib/ld-2.28.so
      unwind: reg 6, val 0
      unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      ... lots and lots of verbose debug output
      cpp-inlining 24617 90229.122036534:          1 cycles:uppp:
                  7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
      
      cpp-inlining 24617 90229.122043974:          1 cycles:uppp:
                  7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
      ...
      ```
      
      After this patch:
      ```
      ...
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      unwind: find_proc_info dso /usr/lib/ld-2.28.so
      unwind: reg 6, val 0
      unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
      cpp-inlining 24617 90229.122036534:          1 cycles:uppp:
                  7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
      
      unwind: reg 16, val 7faf7dfdc000
      unwind: reg 7, val 7ffc80811e30
      unwind: find_proc_info dso /usr/lib/ld-2.28.so
      unwind: reg 6, val 0
      unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
      cpp-inlining 24617 90229.122043974:          1 cycles:uppp:
                  7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
      ...
      ```
      
      This new output format makes it much easier to use perf script output
      for debugging purposes, e.g. to investigate broken dwarf unwinding.
      Signed-off-by: default avatarMilian Wolff <milian.wolff@kdab.com>
      Acked-by: default avatarJiri Olsa <jolsa@kernel.org>
      Link: http://lkml.kernel.org/r/20181021191424.16183-2-milian.wolff@kdab.comSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      7ee40678
    • Milian Wolff's avatar
      perf script: Allow extended console debug output · c1c9b969
      Milian Wolff authored
      The script tool isn't using a browser, yet use_browser wasn't set
      explicitly to zero. This in turn lead to confusing output such as:
      
        ```
        $ perf script -vvv ...
        ...
        overlapping maps in /home/milian/foobar (disable tui for more info)
        ...
        ```
      
      Explicitly set use_browser to 0 now, which gives us the extended
      debug information now in perf script as expected.
      Signed-off-by: default avatarMilian Wolff <milian.wolff@kdab.com>
      Acked-by: default avatarJiri Olsa <jolsa@kernel.org>
      Tested-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      Link: http://lkml.kernel.org/r/20181021191424.16183-1-milian.wolff@kdab.comSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      c1c9b969
    • Jiri Olsa's avatar
      perf stat: Poll for monitored tasks being alive · cbb5df7e
      Jiri Olsa authored
      Adding the check for tasks we monitor via -p/-t options, and finish stat
      if there's no longer task to monitor.
      Requested-by: default avatarStephane Eranian <eranian@google.com>
      Signed-off-by: default avatarJiri Olsa <jolsa@kernel.org>
      Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
      Cc: Jin Yao <yao.jin@linux.intel.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Tested-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      Link: http://lkml.kernel.org/r/20181022093015.9106-1-jolsa@kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      cbb5df7e
    • Arnaldo Carvalho de Melo's avatar
      perf trace: Drop thread refcount in trace__event_handler() · a937c665
      Arnaldo Carvalho de Melo authored
      We must pair:
      
         thread = machine__findnew_thread();
      
      with thread__put(thread). Fix it.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Fixes: c4191e55 ("perf trace: Show comm and tid for tracepoint events")
      Link: https://lkml.kernel.org/n/tip-dkxsb8cwg87rmkrzrbns1o4z@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      a937c665
    • Arnaldo Carvalho de Melo's avatar
      perf trace: Drop addr_location refcounts · 4291bf5c
      Arnaldo Carvalho de Melo authored
      When we use machine__resolve() we grab a reference to
      addr_location.thread (and in the future to other elements there) via
      machine__findnew_thread(), so we must pair that with
      addr_location__put(), else we'll never drop that thread when it exits
      and no other remaining data structures have pointers to it. Fix it.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-ivg9hifzeuokb1f5jxc2wob4@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      4291bf5c
    • Arnaldo Carvalho de Melo's avatar
      perf evsel: Mark a evsel as disabled when asking the kernel do disable it · b7e8452b
      Arnaldo Carvalho de Melo authored
      Because there may be more such events in the ring buffer that should be
      discarded when an app decides to stop considering them.
      
      At some point we'll do this with eBPF, this way we stop them at origin,
      before they are placed in the ring buffer.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-uzufuxws4hufigx07ue1dpv6@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      b7e8452b
  4. 19 Oct, 2018 4 commits
    • Arnaldo Carvalho de Melo's avatar
      perf evsel: Introduce per event max_events property · 2fda5ada
      Arnaldo Carvalho de Melo authored
      This simply adds the field to 'struct perf_evsel' and allows setting
      it via the event parser, to test it lets trace trace:
      
      First look at where in a function that receives an evsel we can put a probe
      to read how evsel->max_events was setup:
      
        # perf probe -x ~/bin/perf -L trace__event_handler
        <trace__event_handler@/home/acme/git/perf/tools/perf/builtin-trace.c:0>
              0  static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
                                                union perf_event *event __maybe_unused,
                                                struct perf_sample *sample)
              3  {
              4         struct thread *thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
              5         int callchain_ret = 0;
      
              7         if (sample->callchain) {
              8                 callchain_ret = trace__resolve_callchain(trace, evsel, sample, &callchain_cursor);
              9                 if (callchain_ret == 0) {
             10                         if (callchain_cursor.nr < trace->min_stack)
             11                                 goto out;
             12                         callchain_ret = 1;
                                }
                        }
      
      See what variables we can probe at line 7:
      
        # perf probe -x ~/bin/perf -V trace__event_handler:7
        Available variables at trace__event_handler:7
                @<trace__event_handler+89>
                        int     callchain_ret
                        struct perf_evsel*      evsel
                        struct perf_sample*     sample
                        struct thread*  thread
                        struct trace*   trace
                        union perf_event*       event
      
      Add a probe at that line asking for evsel->max_events to be collected and named
      as "max_events":
      
        # perf probe -x ~/bin/perf trace__event_handler:7 'max_events=evsel->max_events'
        Added new event:
          probe_perf:trace__event_handler (on trace__event_handler:7 in /home/acme/bin/perf with max_events=evsel->max_events)
      
        You can now use it in all perf tools, such as:
      
        	perf record -e probe_perf:trace__event_handler -aR sleep 1
      
      Now use 'perf trace', here aliased to just 'trace' and trace trace, i.e.
      the first 'trace' is tracing just that 'probe_perf:trace__event_handler' event,
      while the traced trace is tracing all scheduler tracepoints, will stop at two
      events (--max-events 2) and will just set evsel->max_events for all the sched
      tracepoints to 9, we will see the output of both traces intermixed:
      
        # trace -e *perf:*event_handler trace --max-events 2 -e sched:*/nr=9/
             0.000 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=000
             0.009 :0/0 sched:sched_wakeup:comm=rcu_sched pid=10 prio=120 target_cpu=000
             0.000 trace/23949 probe_perf:trace__event_handler:(48c34a) max_events=0x9
             0.046 trace/23949 probe_perf:trace__event_handler:(48c34a) max_events=0x9
        #
      
      Now, if the traced trace sends its output to /dev/null, we'll see just
      what the first level trace outputs: that evsel->max_events is indeed
      being set to 9:
      
        # trace -e *perf:*event_handler trace -o /dev/null --max-events 2 -e sched:*/nr=9/
             0.000 trace/23961 probe_perf:trace__event_handler:(48c34a) max_events=0x9
             0.030 trace/23961 probe_perf:trace__event_handler:(48c34a) max_events=0x9
        #
      
      Now that we can set evsel->max_events, we can go to the next step, honour that
      per-event property in 'perf trace'.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Milian Wolff <milian.wolff@kdab.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-og00yasj276joem6e14l1eas@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      2fda5ada
    • Arnaldo Carvalho de Melo's avatar
      perf trace: Introduce --max-events · 5067a8cd
      Arnaldo Carvalho de Melo authored
      Allow stopping tracing after a number of events take place, considering
      strace-like syscalls formatting as one event per enter/exit pair or when
      in a multi-process tracing session a syscall is interrupted and printed
      ending with '...'.
      
      Examples included in the documentation:
      
      Trace the first 4 open, openat or open_by_handle_at syscalls (in the future more syscalls may match here):
      
        $ perf trace -e open* --max-events 4
        [root@jouet perf]# trace -e open* --max-events 4
        2272.992 ( 0.037 ms): gnome-shell/1370 openat(dfd: CWD, filename: /proc/self/stat) = 31
        2277.481 ( 0.139 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
        3026.398 ( 0.076 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
        4294.665 ( 0.015 ms): sed/15879 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
        $
      
      Trace the first minor page fault when running a workload:
      
        # perf trace -F min --max-stack=7 --max-events 1 sleep 1
           0.000 ( 0.000 ms): sleep/18006 minfault [__clear_user+0x1a] => 0x5626efa56080 (?k)
                                             __clear_user ([kernel.kallsyms])
                                             load_elf_binary ([kernel.kallsyms])
                                             search_binary_handler ([kernel.kallsyms])
                                             __do_execve_file.isra.33 ([kernel.kallsyms])
                                             __x64_sys_execve ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64 ([kernel.kallsyms])
        #
      
      Trace the next min page page fault to take place on the first CPU:
      
        # perf trace -F min --call-graph=dwarf --max-events 1 --cpu 0
           0.000 ( 0.000 ms): Web Content/17136 minfault [js::gc::Chunk::fetchNextDecommittedArena+0x4b] => 0x7fbe6181b000 (?.)
                                             js::gc::FreeSpan::initAsEmpty (inlined)
                                             js::gc::Arena::setAsNotAllocated (inlined)
                                             js::gc::Chunk::fetchNextDecommittedArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::Chunk::allocateArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::GCRuntime::allocateArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::ArenaLists::allocateFromArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::GCRuntime::tryNewTenuredThing<JSString, (js::AllowGC)1> (inlined)
                                             js::AllocateString<JSString, (js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                             js::Allocate<JSThinInlineString, (js::AllowGC)1> (inlined)
                                             JSThinInlineString::new_<(js::AllowGC)1> (inlined)
                                             AllocateInlineString<(js::AllowGC)1, unsigned char> (inlined)
                                             js::ConcatStrings<(js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                             [0x18b26e6bc2bd] (/tmp/perf-17136.map)
      
      Tracing the next four ext4 operations on a specific CPU:
      
        # perf trace -e ext4:*/call-graph=fp/ --max-events 4 --cpu 3
           0.000 mutt/3849 ext4:ext4_es_lookup_extent_enter:dev 253,2 ino 57277 lblk 0
                                             ext4_es_lookup_extent ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.097 mutt/3849 ext4:ext4_es_lookup_extent_exit:dev 253,2 ino 57277 found 0 [0/0) 0
                                             ext4_es_lookup_extent ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.141 mutt/3849 ext4:ext4_ext_map_blocks_enter:dev 253,2 ino 57277 lblk 0 len 1 flags
                                             ext4_ext_map_blocks ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.184 mutt/3849 ext4:ext4_ext_load_extent:dev 253,2 ino 57277 lblk 1516511 pblk 18446744071750013657
                                             __read_extent_tree_block ([kernel.kallsyms])
                                             __read_extent_tree_block ([kernel.kallsyms])
                                             ext4_find_extent ([kernel.kallsyms])
                                             ext4_ext_map_blocks ([kernel.kallsyms])
                                             ext4_map_blocks ([kernel.kallsyms])
                                             ext4_mpage_readpages ([kernel.kallsyms])
                                             read_pages ([kernel.kallsyms])
                                             __do_page_cache_readahead ([kernel.kallsyms])
                                             ondemand_readahead ([kernel.kallsyms])
                                             generic_file_read_iter ([kernel.kallsyms])
                                             __vfs_read ([kernel.kallsyms])
                                             vfs_read ([kernel.kallsyms])
                                             ksys_read ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64 ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Milian Wolff <milian.wolff@kdab.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Rudá Moura <ruda.moura@gmail.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-sweh107bs7ol5bzls0m4tqdz@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      5067a8cd
    • Arnaldo Carvalho de Melo's avatar
      tools lib subcmd: Introduce OPTION_ULONG · 4ba8b3eb
      Arnaldo Carvalho de Melo authored
      For completeness, will be used in 'perf trace --max-events'.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Andi Kleen <ak@linux.intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Josh Poimboeuf <jpoimboe@redhat.com>
      Cc: Kim Phillips <kim.phillips@arm.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-glaj3pwespxfj2fdjs9a20b6@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      4ba8b3eb
    • Hongxu Jia's avatar
      perf arm64: Fix generate system call table failed with /tmp mounted with noexec · 389373d3
      Hongxu Jia authored
      When /tmp is mounted with noexec, mksyscalltbl fails.
      
        [snip]
        |perf-1.0/tools/perf/arch/arm64/entry/syscalls//mksyscalltbl:
        /tmp/create-table-6VGPSt: Permission denied
        [snip]
      
      Add variable TMPDIR as prefix dir of the temporary file, if it is set,
      replace default /tmp.
      Signed-off-by: default avatarHongxu Jia <hongxu.jia@windriver.com>
      Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
      Cc: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Cc: Kim Phillips <kim.phillips@arm.com>
      Cc: Michael Ellerman <mpe@ellerman.id.au>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Cc: Ravi Bangoria <ravi.bangoria@linux.vnet.ibm.com>
      Cc: Sébastien Boisvert <sboisvert@gydle.com>
      Cc: Thomas Richter <tmricht@linux.vnet.ibm.com>
      Fixes: 2b588243 ("perf arm64: Generate system call table from asm/unistd.h")
      LPU-Reference: 1539851173-14959-1-git-send-email-hongxu.jia@windriver.com
      Link: https://lkml.kernel.org/n/tip-1qrgq840ci0c5cy4oww957ge@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      389373d3
  5. 18 Oct, 2018 6 commits
  6. 17 Oct, 2018 1 commit
    • Arnaldo Carvalho de Melo's avatar
      perf tools: Stop fallbacking to kallsyms for vdso symbols lookup · edeb0c90
      Arnaldo Carvalho de Melo authored
      David reports that:
      
      <quote>
      Perf has this hack where it uses the kernel symbol map as a backup when
      a symbol can't be found in the user's symbol table(s).
      
      This causes problems because the tests driving this code path use
      machine__kernel_ip(), and that is completely meaningless on Sparc.  On
      sparc64 the kernel and user live in physically separate virtual address
      spaces, rather than a shared one.  And the kernel lives at a virtual
      address that overlaps common userspace addresses.  So this test passes
      almost all the time when a user symbol lookup fails.
      
      The consequence of this is that, if the unfound user virtual address in
      the sample doesn't match up to a kernel symbol either, we trigger things
      like this code in builtin-top.c:
      
      	if (al.sym == NULL && al.map != NULL) {
      		const char *msg = "Kernel samples will not be resolved.\n";
      		/*
      		 * As we do lazy loading of symtabs we only will know if the
      		 * specified vmlinux file is invalid when we actually have a
      		 * hit in kernel space and then try to load it. So if we get
      		 * here and there are _no_ symbols in the DSO backing the
      		 * kernel map, bail out.
      		 *
      		 * We may never get here, for instance, if we use -K/
      		 * --hide-kernel-symbols, even if the user specifies an
      		 * invalid --vmlinux ;-)
      		 */
      		if (!machine->kptr_restrict_warned && !top->vmlinux_warned &&
      		    __map__is_kernel(al.map) && map__has_symbols(al.map)) {
      			if (symbol_conf.vmlinux_name) {
      				char serr[256];
      				dso__strerror_load(al.map->dso, serr, sizeof(serr));
      				ui__warning("The %s file can't be used: %s\n%s",
      					    symbol_conf.vmlinux_name, serr, msg);
      			} else {
      				ui__warning("A vmlinux file was not found.\n%s",
      					    msg);
      			}
      
      			if (use_browser <= 0)
      				sleep(5);
      			top->vmlinux_warned = true;
      		}
      	}
      
      When I fire up a compilation on sparc, this triggers immediately.
      
      I'm trying to figure out what the "backup to kernel map" code is
      accomplishing.
      
      I see some language in the current code and in the changes that have
      happened in this area talking about vdso.  Does that really happen?
      
      The vdso is mapped into userspace virtual addresses, not kernel ones.
      
      More history.  This didn't cause problems on sparc some time ago,
      because the kernel IP check used to be "ip < 0" :-) Sparc kernel
      addresses are not negative.  But now with machine__kernel_ip(), which
      works using the symbol table determined kernel address range, it does
      trigger.
      
      What it all boils down to is that on architectures like sparc,
      machine__kernel_ip() should always return false in this scenerio, and
      therefore this kind of logic:
      
      		if (cpumode == PERF_RECORD_MISC_USER && machine &&
      		    mg != &machine->kmaps &&
      		    machine__kernel_ip(machine, al->addr)) {
      
      is basically invalid.  PERF_RECORD_MISC_USER implies no kernel address
      can possibly match for the sample/event in question (no matter how
      hard you try!) :-)
      </>
      
      So, I thought something had changed and in the past we would somehow
      find that address in the kallsyms, but I couldn't find anything to back
      that up, the patch introducing this is over a decade old, lots of things
      changed, so I was just thinking I was missing something.
      
      I tried a gtod busy loop to generate vdso activity and added a 'perf
      probe' at that branch, on x86_64 to see if it ever gets hit:
      
      Made thread__find_map() noinline, as 'perf probe' in lines of inline
      functions seems to not be working, only at function start. (Masami?)
      
        # perf probe -x ~/bin/perf -L thread__find_map:57
        <thread__find_map@/home/acme/git/perf/tools/perf/util/event.c:57>
           57                 if (cpumode == PERF_RECORD_MISC_USER && machine &&
           58                     mg != &machine->kmaps &&
           59                     machine__kernel_ip(machine, al->addr)) {
           60                         mg = &machine->kmaps;
           61                         load_map = true;
           62                         goto try_again;
                              }
                      } else {
                              /*
                               * Kernel maps might be changed when loading
                               * symbols so loading
                               * must be done prior to using kernel maps.
                               */
           69                 if (load_map)
           70                         map__load(al->map);
           71                 al->addr = al->map->map_ip(al->map, al->addr);
      
        # perf probe -x ~/bin/perf thread__find_map:60
        Added new event:
          probe_perf:thread__find_map (on thread__find_map:60 in /home/acme/bin/perf)
      
        You can now use it in all perf tools, such as:
      
      	perf record -e probe_perf:thread__find_map -aR sleep 1
      
        #
      
        Then used this to see if, system wide, those probe points were being hit:
      
        # perf trace -e *perf:thread*/max-stack=8/
        ^C[root@jouet ~]#
      
        No hits when running 'perf top' and:
      
        # cat gtod.c
        #include <sys/time.h>
      
        int main(void)
        {
      	struct timeval tv;
      
      	while (1)
      		gettimeofday(&tv, 0);
      
      	return 0;
        }
        [root@jouet c]# ./gtod
        ^C
      
        Pressed 'P' in 'perf top' and the [vdso] samples are there:
      
        62.84%  [vdso]                    [.] __vdso_gettimeofday
         8.13%  gtod                      [.] main
         7.51%  [vdso]                    [.] 0x0000000000000914
         5.78%  [vdso]                    [.] 0x0000000000000917
         5.43%  gtod                      [.] _init
         2.71%  [vdso]                    [.] 0x000000000000092d
         0.35%  [kernel]                  [k] native_io_delay
         0.33%  libc-2.26.so              [.] __memmove_avx_unaligned_erms
         0.20%  [vdso]                    [.] 0x000000000000091d
         0.17%  [i2c_i801]                [k] i801_access
         0.06%  firefox                   [.] free
         0.06%  libglib-2.0.so.0.5400.3   [.] g_source_iter_next
         0.05%  [vdso]                    [.] 0x0000000000000919
         0.05%  libpthread-2.26.so        [.] __pthread_mutex_lock
         0.05%  libpixman-1.so.0.34.0     [.] 0x000000000006d3a7
         0.04%  [kernel]                  [k] entry_SYSCALL_64_trampoline
         0.04%  libxul.so                 [.] style::dom_apis::query_selector_slow
         0.04%  [kernel]                  [k] module_get_kallsym
         0.04%  firefox                   [.] malloc
         0.04%  [vdso]                    [.] 0x0000000000000910
      
        I added a 'perf probe' to thread__find_map:69, and that surely got tons
        of hits, i.e. for every map found, just to make sure the 'perf probe'
        command was really working.
      
        In the process I noticed a bug, we're only have records for '[vdso]' for
        pre-existing commands, i.e. ones that are running when we start 'perf top',
        when we will generate the PERF_RECORD_MMAP by looking at /perf/PID/maps.
      
        I.e. like this, for preexisting processes with a vdso map, again,
        tracing for all the system, only pre-existing processes get a [vdso] map
        (when having one):
      
        [root@jouet ~]# perf probe -x ~/bin/perf __machine__addnew_vdso
        Added new event:
        probe_perf:__machine__addnew_vdso (on __machine__addnew_vdso in /home/acme/bin/perf)
      
        You can now use it in all perf tools, such as:
      
      	perf record -e probe_perf:__machine__addnew_vdso -aR sleep 1
      
        [root@jouet ~]# perf trace -e probe_perf:__machine__addnew_vdso/max-stack=8/
           0.000 probe_perf:__machine__addnew_vdso:(568eb3)
                                             __machine__addnew_vdso (/home/acme/bin/perf)
                                             map__new (/home/acme/bin/perf)
                                             machine__process_mmap2_event (/home/acme/bin/perf)
                                             machine__process_event (/home/acme/bin/perf)
                                             perf_event__process (/home/acme/bin/perf)
                                             perf_tool__process_synth_event (/home/acme/bin/perf)
                                             perf_event__synthesize_mmap_events (/home/acme/bin/perf)
                                             __event__synthesize_thread (/home/acme/bin/perf)
      
      The kernel is generating a PERF_RECORD_MMAP for vDSOs, but somehow
      'perf top' is not getting those records while 'perf record' is:
      
        # perf record ~acme/c/gtod
        ^C[ perf record: Woken up 1 times to write data ]
        [ perf record: Captured and wrote 0.076 MB perf.data (1499 samples) ]
      
        # perf report -D | grep PERF_RECORD_MMAP2
        71293612401913 0x11b48 [0x70]: PERF_RECORD_MMAP2 25484/25484: [0x400000(0x1000) @ 0 fd:02 1137 541179306]: r-xp /home/acme/c/gtod
        71293612419012 0x11be0 [0x70]: PERF_RECORD_MMAP2 25484/25484: [0x7fa4a2783000(0x227000) @ 0 fd:00 3146370 854107250]: r-xp /usr/lib64/ld-2.26.so
        71293612432110 0x11c50 [0x60]: PERF_RECORD_MMAP2 25484/25484: [0x7ffcdb53a000(0x2000) @ 0 00:00 0 0]: r-xp [vdso]
        71293612509944 0x11cb0 [0x70]: PERF_RECORD_MMAP2 25484/25484: [0x7fa4a23cd000(0x3b6000) @ 0 fd:00 3149723 262067164]: r-xp /usr/lib64/libc-2.26.so
        #
        # perf script | grep vdso | head
            gtod 25484 71293.612768: 2485554 cycles:ppp:  7ffcdb53a914 [unknown] ([vdso])
            gtod 25484 71293.613576: 2149343 cycles:ppp:  7ffcdb53a917 [unknown] ([vdso])
            gtod 25484 71293.614274: 1814652 cycles:ppp:  7ffcdb53aca8 __vdso_gettimeofday+0x98 ([vdso])
            gtod 25484 71293.614862: 1669070 cycles:ppp:  7ffcdb53acc5 __vdso_gettimeofday+0xb5 ([vdso])
            gtod 25484 71293.615404: 1451589 cycles:ppp:  7ffcdb53acc5 __vdso_gettimeofday+0xb5 ([vdso])
            gtod 25484 71293.615999: 1269941 cycles:ppp:  7ffcdb53ace6 __vdso_gettimeofday+0xd6 ([vdso])
            gtod 25484 71293.616405: 1177946 cycles:ppp:  7ffcdb53a914 [unknown] ([vdso])
            gtod 25484 71293.616775: 1121290 cycles:ppp:  7ffcdb53ac47 __vdso_gettimeofday+0x37 ([vdso])
            gtod 25484 71293.617150: 1037721 cycles:ppp:  7ffcdb53ace6 __vdso_gettimeofday+0xd6 ([vdso])
            gtod 25484 71293.617478:  994526 cycles:ppp:  7ffcdb53ace6 __vdso_gettimeofday+0xd6 ([vdso])
        #
      
      The patch is the obvious one and with it we also continue to resolve
      vdso symbols for pre-existing processes in 'perf top' and for all
      processes in 'perf record' + 'perf report/script'.
      Suggested-by: default avatarDavid Miller <davem@davemloft.net>
      Acked-by: default avatarDavid Miller <davem@davemloft.net>
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-cs7skq9pp0kjypiju6o7trse@git.kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      edeb0c90
  7. 16 Oct, 2018 3 commits
    • Jiri Olsa's avatar
      perf tools: Pass build flags to traceevent build · 298faf53
      Jiri Olsa authored
      So the extra user build flags are propagated to libtraceevent.
      Signed-off-by: default avatarJiri Olsa <jolsa@kernel.org>
      Cc: "Herton R. Krzesinski" <herton@redhat.com>
      Cc: Steven Rostedt (VMware) <rostedt@goodmis.org>
      Cc: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
      Cc: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
      Link: http://lkml.kernel.org/r/20181016150614.21260-3-jolsa@kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      298faf53
    • Milian Wolff's avatar
      perf report: Don't crash on invalid inline debug information · d4046e8e
      Milian Wolff authored
      When the function name for an inline frame is invalid, we must not try
      to demangle this symbol, otherwise we crash with:
      
        #0  0x0000555555895c01 in bfd_demangle ()
        #1  0x0000555555823262 in demangle_sym (dso=0x555555d92b90, elf_name=0x0, kmodule=0) at util/symbol-elf.c:215
        #2  dso__demangle_sym (dso=dso@entry=0x555555d92b90, kmodule=<optimized out>, kmodule@entry=0, elf_name=elf_name@entry=0x0) at util/symbol-elf.c:400
        #3  0x00005555557fef4b in new_inline_sym (funcname=0x0, base_sym=0x555555d92b90, dso=0x555555d92b90) at util/srcline.c:89
        #4  inline_list__append_dso_a2l (dso=dso@entry=0x555555c7bb00, node=node@entry=0x555555e31810, sym=sym@entry=0x555555d92b90) at util/srcline.c:264
        #5  0x00005555557ff27f in addr2line (dso_name=dso_name@entry=0x555555d92430 "/home/milian/.debug/.build-id/f7/186d14bb94f3c6161c010926da66033d24fce5/elf", addr=addr@entry=2888, file=file@entry=0x0,
            line=line@entry=0x0, dso=dso@entry=0x555555c7bb00, unwind_inlines=unwind_inlines@entry=true, node=0x555555e31810, sym=0x555555d92b90) at util/srcline.c:313
        #6  0x00005555557ffe7c in addr2inlines (sym=0x555555d92b90, dso=0x555555c7bb00, addr=2888, dso_name=0x555555d92430 "/home/milian/.debug/.build-id/f7/186d14bb94f3c6161c010926da66033d24fce5/elf")
            at util/srcline.c:358
      
      So instead handle the case where we get invalid function names for
      inlined frames and use a fallback '??' function name instead.
      
      While this crash was originally reported by Hadrien for rust code, I can
      now also reproduce it with trivial C++ code. Indeed, it seems like
      libbfd fails to interpret the debug information for the inline frame
      symbol name:
      
        $ addr2line -e /home/milian/.debug/.build-id/f7/186d14bb94f3c6161c010926da66033d24fce5/elf -if b48
        main
        /usr/include/c++/8.2.1/complex:610
        ??
        /usr/include/c++/8.2.1/complex:618
        ??
        /usr/include/c++/8.2.1/complex:675
        ??
        /usr/include/c++/8.2.1/complex:685
        main
        /home/milian/projects/kdab/rnd/hotspot/tests/test-clients/cpp-inlining/main.cpp:39
      
      I've reported this bug upstream and also attached a patch there which
      should fix this issue:
      
      https://sourceware.org/bugzilla/show_bug.cgi?id=23715Reported-by: default avatarHadrien Grasland <grasland@lal.in2p3.fr>
      Signed-off-by: default avatarMilian Wolff <milian.wolff@kdab.com>
      Cc: Jin Yao <yao.jin@linux.intel.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Fixes: a64489c5 ("perf report: Find the inline stack for a given address")
      [ The above 'Fixes:' cset is where originally the problem was
        introduced, i.e.  using a2l->funcname without checking if it is NULL,
        but this current patch fixes the current codebase, i.e. multiple csets
        were applied after a64489c5 before the problem was reported by Hadrien ]
      Link: http://lkml.kernel.org/r/20180926135207.30263-3-milian.wolff@kdab.comSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
      d4046e8e
    • Greg Kroah-Hartman's avatar
      Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/sparc · b955a910
      Greg Kroah-Hartman authored
      David writes:
        "Sparc fixes
      
         1) Revert the %pOF change, it causes regressions.
      
         2) Wire up io_pgetevents().
      
         3) Fix perf events on single-PCR sparc64 cpus.
      
         4) Do proper perf event throttling like arm and x86."
      
      * git://git.kernel.org/pub/scm/linux/kernel/git/davem/sparc:
        Revert "sparc: Convert to using %pOFn instead of device_node.name"
        sparc64: Set %l4 properly on trap return after handling signals.
        sparc64: Make proc_id signed.
        sparc: Throttle perf events properly.
        sparc: Fix single-pcr perf event counter management.
        sparc: Wire up io_pgetevents system call.
        sunvdc: Remove VLA usage
      b955a910