perf sched: Introduce timehist command - v2

'perf sched timehist' provides an analysis of scheduling events.

Example usage:
    perf sched record -- sleep 1
    perf sched timehist

By default it shows the individual schedule events, including the time between
sched-in events for the task, the task scheduling delay (time between wakeup
and actually running) and run time for the task:

           time cpu  task name[tid/pid]    b/n time sch delay  run time
  ------------- ---- -------------------- --------- --------- ---------
   79371.874569 [11] gcc[31949]               0.014     0.000     1.148
   79371.874591 [10] gcc[31951]               0.000     0.000     0.024
   79371.874603 [10] migration/10[59]         3.350     0.004     0.011
   79371.874604 [11] <idle>                   1.148     0.000     0.035
   79371.874723 [05] <idle>                   0.016     0.000     1.383
   79371.874746 [05] gcc[31949]               0.153     0.078     0.022
...

Times are in msec.usec.

If callchains were recorded they are appended to the line with a default stack depth of 5:

   79371.874569 [11] gcc[31949]                  0.000014  0.000000  0.001148  wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork
   79371.874591 [10] gcc[31951]                  0.000000  0.000000  0.000024  __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec
   79371.874603 [10] migration/10[59]            0.003350  0.000004  0.000011  smpboot_thread_fn kthread ret_from_fork
   79371.874604 [11] <idle>                      0.001148  0.000000  0.000035  cpu_startup_entry start_secondary
   79371.874723 [05] <idle>                      0.000016  0.000000  0.001383  cpu_startup_entry start_secondary
   79371.874746 [05] gcc[31949]                  0.000153  0.000078  0.000022  do_wait sys_wait4 system_call_fastpath __GI___waitpid

--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.

Similar to perf-trace -s and -S can be used to dump a statistical summary
without or with events (respectively). Statistics include min run time,
average run time and max run time. Stats are also shown for run time by
cpu.

The cpu-visual option provides a visual aid for sched switches by cpu:
...
   79371.874569 [11]            s      gcc[31949]                  0.000014  0.000000  0.001148
   79371.874591 [10]           s       gcc[31951]                  0.000000  0.000000  0.000024
   79371.874603 [10]           s       migration/10[59]            0.003350  0.000004  0.000011
   79371.874604 [11]            i      <idle>                      0.001148  0.000000  0.000035
   79371.874723 [05]      i            <idle>                      0.000016  0.000000  0.001383
   79371.874746 [05]      s            gcc[31949]                  0.000153  0.000078  0.000022
...

Additional options:
- -w option can be used to include a dump of wakeup events
- -c comm to only display events and stats for the given comm (csv list)
- -p/-t to only display events and stats for given pid/tid (csv list)

v3:
- moved run time stats to stats struct
- changed summary function to use machine__for_each_thread

v2:
- Addressed Namhyung's comments
- changed times to be in msec.usec versus sec.usec to be consistent with
  other perf commands

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Pekka Enberg <penberg@kernel.org>
perf sched: Add documentation for timehist options

Add entry to perf-sched documentation for timehist command and its
options.

v3: Updated summary regarding several commands - and the error noted
    by Namhyung missed in v2

v2: Addressed comments by Namhyung

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Pekka Enberg <penberg@kernel.org>
perf sched timehist: Add support for context-switch event

Context switch events are 64 bytes; sched_switch events are 136 bytes.  Both
indicate scheduling changes, so allow user to leverage the smaller event. If
both events exist in a data file, then context-switch event is ignored.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Pekka Enberg <penberg@kernel.org>
perf sched timehist: Add pstree option

Add option to show parent-child relationships based on events processed. Run
time per task is shown in msec. Useful for finding repetitive script bombs
that launch a lot of repetitive tasks.

perf sched timehist -T
...
       11.089 msec          make[10592]
        0.732 msec                  pwd[10593]
        1.953 msec                  grep[10594]
        1.848 msec                  sh[10595]
        1.775 msec                  sh[10596]
        1.748 msec                  sh[10597]
        2.059 msec                  sh[10598]
        2.208 msec                          make[10603]
        2.693 msec                                  rm[10605]
        0.690 msec                                  rm[10607]
...

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
perf tool: Fix bug in thread__fork

Commit 1902efe7f for the new comm infra added the wrong check for return
code on thread__set_comm. err == 0 is normal, so don't return at that
point unless err != 0.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
perf probe: Improve error message when function not found

When requesting a function from a userspace library the error message to
the user is less than helpful. e.g.,

    perf probe -x /lib64/libpthread-2.14.90.so -a 'lock_full=__pthread_mutex_lock_full'
    no symbols found in /lib64/libpthread-2.14.90.so, maybe install a debug package?
    Failed to load map.
       Error: Failed to add events. (-22)

yet the symbol really does exist but is a local symbol which is filtered:

nm /lib64/libpthread-2.14.90.so | grep __pthread_mutex_lock_full
0000000000005700 t __pthread_mutex_lock_full

With this patch:
    perf probe -x /lib64/libpthread-2.14.90.so -a 'lock_full=__pthread_mutex_lock_full'

    no symbols found in /lib64/libpthread-2.14.90.so, maybe install a debug package?
    Failed to find function in /lib64/libpthread-2.14.90.so. Perhaps it is a local variable?
      Error: Failed to add events. (-22)

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Srikar Dronamraju <srikar@linux.vnet.ibm.com>
perf probe: Allow user to specify address within executable

Allow user to specify an address within an executable. This is useful, for
example, in probing local functions. If the function name begins with 0x
then try to convert the supplied name to an address. If succuessful then
treat the function name as the address within the executable to be probed.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Srikar Dronamraju <srikar@linux.vnet.ibm.com>
perf tool: Ensure forward progress unwinding frames

The dwarf option for callstacks is getting stuck on the unwind and showing
repeated frames. For example,

qemu-system-x86 13759 [001] 287663.084957: syscalls:sys_enter_futex: uaddr: 0x7f770a958700, op: 0x00000081, val: 0x00000001, utime: 0x7f75ea
            7f7705fd23ea __lll_unlock_wake (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)
            ...
            (Last frame repeats 126 times)

Catch that the same frame is hit multiple times and break out of the loop.

With this patch:

qemu-system-x86 13759 [001] 287663.084967: syscalls:sys_exit_futex: 0x1
            7f7705fd23ea __lll_unlock_wake (/lib64/libpthread-2.14.90.so)
            7f7705fcf045 _L_unlock_649 (/lib64/libpthread-2.14.90.so)

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Revert "perf record: Unify data output code into perf_record__write function"

This reverts commit 6233dd5efdf9e2c2da1b003cfb70307b7b2028e8.
perf record: mmap output file - v6

When recording raw_syscalls for the entire system, e.g.,
    perf record -e raw_syscalls:*,sched:sched_switch -a -- sleep 1

you end up with a negative feedback loop as perf itself calls write() fairly
often. This patch handles the problem by mmap'ing the file in chunks of 64M at
a time and copies events from the event buffers to the file avoiding write
system calls.

Before (with write syscall):

    perf record -o /tmp/perf.data -e raw_syscalls:*,sched:sched_switch -a -- sleep 1
    [ perf record: Woken up 0 times to write data ]
    [ perf record: Captured and wrote 81.843 MB /tmp/perf.data (~3575786 samples) ]

After (using mmap):

    perf record -o /tmp/perf.data -e raw_syscalls:*,sched:sched_switch -a -- sleep 1
    [ perf record: Woken up 31 times to write data ]
    [ perf record: Captured and wrote 8.203 MB /tmp/perf.data (~358388 samples) ]

In addition to perf-trace benefits using mmap lowers the overhead of
perf-record. For example,

  perf stat -i -- perf record -g -o /tmp/perf.data openssl speed aes

shows a drop in time, CPU cycles, and instructions all drop by more than a
factor of 3. Jiri also ran a test that showed a big improvement.

v5: Addressed misc comments from Jiri, Adrian and Arnaldo. Added -O shortcut
    for --out-pages. Added -O 0 as a means to fall back to write

v4: Refactoring per Ingo's comments

v3: Removed use of bytes_at_mmap_start at the stat() that set it
    Added user option to control the size of the mmap for writing file.

v2: Removed msync call before munmap per Jiri's suggestion

Acked-by: Ingo Molnar <mingo@kernel.org>
Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Stephane Eranian <eranian@google.com>
perf record: Handle memcopy failures

Signed-off-by: David Ahern <dsahern@gmail.com>
perf record: Delete file if a failure occurs writing the perf data file

If perf fails to write data to the data file (e.g., ENOSPC error) it fails
with the message:
  failed to write perf data, error: No space left on device

and stops — killing the workload too. The file is an unknown state. Trying
to read it (e.g., perf report) fails with a SIGBUS error.

Fix by deleting the file on a failure.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Stephane Eranian <eranian@google.com>
perf tool: Add option to ignore path when looking up DSOs

Similar to gdb option to look or solibs in a single directory.

Signed-off-by: David Ahern <dsahern@gmail.com>
perf header: move perf_header__getbuffer64 up in header.c

Needed in next patch. Code move only.

Signed-off-by: David Ahern <dsahern@gmail.com>
perf: add reference time as feature in header

Adds perf_clock to time-of-day references to env in the header.
Adds the infrastructure within header.c to write out the reference
times and read them back.

Signed-off-by: David Ahern <dsahern@gmail.com>
perf tool: Add time-based utility functions

Signed-off-by: David Ahern <dsahern@gmail.com>
perf tool: Add method for creating perf_clock to tod reference

Uses posix clock to get a perf_clock timestamp. Requires either kernel
side support or module to be loaded.

ioctl variant saved as commented out code

Signed-off-by: David Ahern <dsahern@gmail.com>
perf record: Add time-of-day option

Invoked the perf-session method to get a perf_clock to time-of-day
reference.

Signed-off-by: David Ahern <dsahern@gmail.com>
perf script: add time-of-day option for displaying events

Leverages reference time stored in session header to convert perf_clock
timestamps to time-of-day. Default format is %H:%M:%S and the format can
be changed via the --tod argument to any string recognized by strftime.

This version does *not* use any tracepoints to keep the correlation
between perf_clock and time-of-day up to date. Time discrepancies can
happen if ntpd or a user changes the wallclock.

Signed-off-by: David Ahern <dsahern@gmail.com>
perf sched timehist: Use time-of-day for timestamps if possible

Signed-off-by: David Ahern <dsahern@gmail.com>