perf/urgent fixes for 'perf sched timehist' and samples/bpf/ testing

Hi Ingo,

Please consider pulling,

- Arnaldo

P.S.: Some of the container test builds now include building samples/bpf/ with:

  $ make O=/tmp/build/linux allmodconfig
  $ make O=/tmp/build/linux headers_install
  $ make O=/tmp/build/linux samples/bpf/

In distributions having at least clang/llvm 3.8+ with the 'bpf' target.

Examples include debian:experimental, fedora:rawhide and opensuse:tumbleweed, more to come as I go over rebuilding the containers looking for more suitable environments.

This will help in finding regressions in this area, now using tools/lib/bpf/.

Test results at the end of this message, as usual.

The following changes since commit 1134c2b5cb840409ffd966d8c2a9468f64e6a494:

perf/x86: Fix overlap counter scheduling bug (2016-12-22 17:45:43 +0100)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tags/perf-urgent-for-mingo-20161222

for you to fetch changes up to bdd75729e5d279d734e8d3fb41ef4818ac1598ab:

perf sched timehist: Fix invalid period calculation (2016-12-22 16:35:46 -0300)

----------------------------------------------------------------
perf/urgent fixes:

Fixes for 'perf sched timehist': (Namhyung Kim)

- Define a larger initial alignment value for the COMM column and make it be more consistently honoured, for instance in the header.

- Fix invalid period calculation when using the --time option to select a time slice, when events outside that slice were being considered for the per cpu idle stats summary.

----------------------------------------------------------------
Namhyung Kim (4):
perf sched timehist: Honour 'comm_width' when aligning the headers perf sched timehist: Enlarge default 'comm_width'
perf sched timehist: Remove hardcoded 'comm_width' check at print_summary perf sched timehist: Fix invalid period calculation

 tools/perf/builtin-sched.c | 14 ++++++--------
 1 file changed, 6 insertions(+), 8 deletions(-)

  # uname -a
  Linux jouet 4.9.0+ #2 SMP Wed Dec 21 11:54:44 BRT 2016 x86_64 x86_64 x86_64 GNU/Linux
  # perf test
   1: vmlinux symtab matches kallsyms            : Ok
   2: Detect openat syscall event                : Ok
   3: Detect openat syscall event on all cpus    : Ok
   4: Read samples using the mmap interface      : Ok
   5: Parse event definition strings             : Ok
   6: PERF_RECORD_* events & perf_sample fields  : Ok
   7: Parse perf pmu format                      : Ok
   8: DSO data read                              : Ok
   9: DSO data cache                             : Ok
  10: DSO data reopen                            : Ok
  11: Roundtrip evsel->name                      : Ok
  12: Parse sched tracepoints fields             : Ok
  13: syscalls:sys_enter_openat event fields     : Ok
  14: Setup struct perf_event_attr               : Ok
  15: Match and link multiple hists              : Ok
  16: 'import perf' in python                    : Ok
  17: Breakpoint overflow signal handler         : Ok
  18: Breakpoint overflow sampling               : Ok
  19: Number of exit events of a simple workload : Ok
  20: Software clock events period values        : Ok
  21: Object code reading                        : Ok
  22: Sample parsing                             : Ok
  23: Use a dummy software event to keep tracking: Ok
  24: Parse with no sample_id_all bit set        : Ok
  25: Filter hist entries                        : Ok
  26: Lookup mmap thread                         : Ok
  27: Share thread mg                            : Ok
  28: Sort output of hist entries                : Ok
  29: Cumulate child hist entries                : Ok
  30: Track with sched_switch                    : Ok
  31: Filter fds with revents mask in a fdarray  : Ok
  32: Add fd to a fdarray, making it autogrow    : Ok
  33: kmod_path__parse                           : Ok
  34: Thread map                                 : Ok
  35: LLVM search and compile                    :
  35.1: Basic BPF llvm compile                    : Ok
  35.2: kbuild searching                          : Ok
  35.3: Compile source for BPF prologue generation: Ok
  35.4: Compile source for BPF relocation         : Ok
  36: Session topology                           : Ok
  37: BPF filter                                 :
  37.1: Basic BPF filtering                      : Ok
  37.2: BPF prologue generation                  : Ok
  37.3: BPF relocation checker                   : Ok
  38: Synthesize thread map                      : Ok
  39: Remove thread map                          : Ok
  40: Synthesize cpu map                         : Ok
  41: Synthesize stat config                     : Ok
  42: Synthesize stat                            : Ok
  43: Synthesize stat round                      : Ok
  44: Synthesize attr update                     : Ok
  45: Event times                                : Ok
  46: Read backward ring buffer                  : Ok
  47: Print cpu map                              : Ok
  48: Probe SDT events                           : Ok
  49: is_printable_array                         : Ok
  50: Print bitmap                               : Ok
  51: perf hooks                                 : Ok
  52: builtin clang support                      : Skip (not compiled in)
  53: x86 rdpmc                                  : Ok
  54: Convert perf time to TSC                   : Ok
  55: DWARF unwind                               : Ok
  56: x86 instruction decoder - new instructions : Ok
  57: Intel cqm nmi context read                 : Skip
  # 
  # dm
   1 alpine:3.4: Ok
   2 android-ndk:r12b-arm: Ok
   3 archlinux:latest: Ok
   4 centos:5: Ok
   5 centos:6: Ok
   6 centos:7: Ok
   7 debian:7: Ok
   8 debian:8: Ok
   9 debian:experimental: Ok
  10 debian:experimental-x-mips64: Ok
  11 fedora:20: Ok
  12 fedora:21: Ok
  13 fedora:22: Ok
  14 fedora:23: Ok
  15 fedora:24: Ok
  16 fedora:24-x-ARC-uClibc: Ok
  17 fedora:25: Ok
  18 fedora:rawhide: Ok
  19 mageia:5: Ok
  20 opensuse:13.2: Ok
  21 opensuse:42.1: Ok
  22 opensuse:tumbleweed: Ok
  23 ubuntu:12.04.5: Ok
  24 ubuntu:14.04.4-x-linaro-arm64: Ok
  25 ubuntu:15.10: Ok
  26 ubuntu:16.04: Ok
  27 ubuntu:16.04-x-arm: Ok
  28 ubuntu:16.04-x-arm64: Ok
  29 ubuntu:16.04-x-powerpc: Ok
  30 ubuntu:16.04-x-powerpc64: Ok
  31 ubuntu:16.04-x-powerpc64el: Ok
  32 ubuntu:16.04-x-s390: Ok
  33 ubuntu:16.10: Ok
  #
  $ make -C tools/perf build-test
  make: Entering directory '/home/acme/git/linux/tools/perf'
  - tarpkg: ./tests/perf-targz-src-pkg .
                 make_perf_o_O: make perf.o
           make_no_libbionic_O: make NO_LIBBIONIC=1
              make_no_libelf_O: make NO_LIBELF=1
            make_install_bin_O: make install-bin
              make_clean_all_O: make clean all
                   make_pure_O: make
             make_no_libnuma_O: make NO_LIBNUMA=1
           make_no_libunwind_O: make NO_LIBUNWIND=1
         make_install_prefix_O: make install prefix=/tmp/krava
                   make_help_O: make help
        make_with_babeltrace_O: make LIBBABELTRACE=1
                 make_static_O: make LDFLAGS=-static
                  make_debug_O: make DEBUG=1
                   make_tags_O: make tags
                make_minimal_O: make NO_LIBPERL=1 NO_LIBPYTHON=1 NO_NEWT=1 NO_GTK2=1 NO_DEMANGLE=1 NO_LIBELF=1 NO_LIBUNWIND=1 NO_BACKTRACE=1 NO_LIBNUMA=1 NO_LIBAUDIT=1 NO_LIBBIONIC=1 NO_LIBDW_DWARF_UNWIND=1 NO_AUXTRACE=1 NO_LIBBPF=1 NO_LIBCRYPTO=1 NO_SDT=1 NO_JVMTI=1
           make_no_backtrace_O: make NO_BACKTRACE=1
                    make_doc_O: make doc
            make_no_libaudit_O: make NO_LIBAUDIT=1
       make_util_pmu_bison_o_O: make util/pmu-bison.o
             make_no_libperl_O: make NO_LIBPERL=1
             make_no_scripts_O: make NO_LIBPYTHON=1 NO_LIBPERL=1
  make_no_libdw_dwarf_unwind_O: make NO_LIBDW_DWARF_UNWIND=1
             make_util_map_o_O: make util/map.o
               make_no_slang_O: make NO_SLANG=1
              make_no_libbpf_O: make NO_LIBBPF=1
                make_no_newt_O: make NO_NEWT=1
            make_no_demangle_O: make NO_DEMANGLE=1
           make_no_libpython_O: make NO_LIBPYTHON=1
   make_install_prefix_slash_O: make install prefix=/tmp/krava/
                make_install_O: make install
            make_no_auxtrace_O: make NO_AUXTRACE=1
                  make_no_ui_O: make NO_NEWT=1 NO_SLANG=1 NO_GTK2=1
                make_no_gtk2_O: make NO_GTK2=1
         make_with_clangllvm_O: make LIBCLANGLLVM=1
  OK
  make: Leaving directory '/home/acme/git/linux/tools/perf'
  $

From: Namhyung Kim <[email protected]>

Current default value is 20, but that may change in the future, so make places where we have 20 hardcoded use 'comm_width'.

---
 tools/perf/builtin-sched.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

index c1c07bfe132c..020f9c9cef7b 100644
@@ -1817,7 +1817,7 @@ static void timehist_header(struct perf_sched *sched)
 		printf(" ");
 	}
 
-	printf(" %-20s  %9s  %9s  %9s",
+	printf(" %-*s  %9s  %9s  %9s", comm_width,
 		"task name", "wait time", "sch delay", "run time");
 
 	printf("\n");

@@ -1830,7 +1830,8 @@ static void timehist_header(struct perf_sched *sched)
 	if (sched->show_cpu_visual)
 		printf(" %*s ", ncpus, "");
 
-	printf(" %-20s  %9s  %9s  %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
+	printf(" %-*s  %9s  %9s  %9s\n", comm_width,
+	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
 
 	/*
 	 * separator

@@ -1840,7 +1841,7 @@ static void timehist_header(struct perf_sched *sched)
 	if (sched->show_cpu_visual)
 		printf(" %.*s ", ncpus, graph_dotted_line);
 
-	printf(" %.20s  %.9s  %.9s  %.9s",
+	printf(" %.*s  %.9s  %.9s  %.9s", comm_width,
 		graph_dotted_line, graph_dotted_line, graph_dotted_line,
 		graph_dotted_line);
 

2.9.3

From: Namhyung Kim <[email protected]>

Current default value is 20 but it's easily changed to a bigger value as task has a long name and different tid and pid. And it makes the output not aligned. So change it to have a large value as summary shows.

Committer notes:

Before:

  # perf sched record
  ^C
  # perf sched timehist
  <SNIP>
    40602.770537 [0001]  rcuos/2[29]               7.970      0.002      0.020
    40602.771512 [0003]  <idle>                    0.003      0.000      0.986
    40602.771586 [0001]  <idle>                    0.020      0.000      1.049
    40602.771606 [0001]  qemu-system-x86[3593/3510]      0.000      0.002      0.020
    40602.771629 [0003]  qemu-system-x86[3510]           0.000      0.003      0.116
    40602.771776 [0000]  <idle>                          0.001      0.000      1.892
  <SNIP>

After:

  # perf sched timehist
  <SNIP>
   40602.770537 [0001]  rcuos/2[29]                         7.970      0.002      0.020
   40602.771512 [0003]  <idle>                              0.003      0.000      0.986
   40602.771586 [0001]  <idle>                              0.020      0.000      1.049
   40602.771606 [0001]  qemu-system-x86[3593/3510]          0.000      0.002      0.020
   40602.771629 [0003]  qemu-system-x86[3510]               0.000      0.003      0.116
  <SNIP>

---
 tools/perf/builtin-sched.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 020f9c9cef7b..c65f16cbae62 100644
@@ -1775,7 +1775,7 @@ static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)
 	return r->last_time[cpu];
 }
 
-static int comm_width = 20;
+static int comm_width = 30;
 
 static char *timehist_get_commstr(struct thread *thread)
 {

2.9.3

From: Namhyung Kim <[email protected]>

Now that the default 'comm_width' value is 30, no need to check that at print_summary,

---
 tools/perf/builtin-sched.c | 3 ---
 1 file changed, 3 deletions(-)

index c65f16cbae62..5052caa91caa 100644
@@ -2627,9 +2627,6 @@ static void timehist_print_summary(struct perf_sched *sched,
 
 	memset(&totals, 0, sizeof(totals));
 
-	if (comm_width < 30)
-		comm_width = 30;
-
 	if (sched->idle_hist) {
 		printf("\nIdle-time summary\n");
 		printf("%*s  parent  sched-out  ", comm_width, "comm");

2.9.3

From: Namhyung Kim <[email protected]>

When --time option is given with a value outside recorded time, the last sample time (tprev) was set to that value and run time calculation might be incorrect. This is a problem of the first samples for each cpus since it would skip the runtime update when tprev is 0. But with --time option it had non-zero (which is invalid) value so the calculation is also incorrect.

For example, let's see the followging:

  $ perf sched timehist
             time    cpu  task name                       wait time  sch delay   run time
                          [tid/pid]                          (msec)     (msec)     (msec)
  --------------- ------  ------------------------------  ---------  ---------  ---------
      3195.968367 [0003]  <idle>                              0.000      0.000      0.000
      3195.968386 [0002]  Timer[4306/4277]                    0.000      0.000      0.018
      3195.968397 [0002]  Web Content[4277]                   0.000      0.000      0.000
      3195.968595 [0001]  JS Helper[4302/4277]                0.000      0.000      0.000
      3195.969217 [0000]  <idle>                              0.000      0.000      0.621
      3195.969251 [0001]  kworker/1:1H[291]                   0.000      0.000      0.033

The sample starts at 3195.968367 but when I gave a time interval from 3194 to 3196 (in sec) it will calculate the whole 2 second as runtime. In below, 2 cpus accounted it as runtime, other 2 cpus accounted it as idle time.

Before:

  $ perf sched timehist --time 3194,3196 -s | tail
  Idle stats:
      CPU  0 idle for   1995.991  msec
      CPU  1 idle for     20.793  msec
      CPU  2 idle for     30.191  msec
      CPU  3 idle for   1999.852  msec

Total number of unique tasks: 23
Total number of context switches: 128

             Total run time (msec): 3724.940

After:

  $ perf sched timehist --time 3194,3196 -s | tail
  Idle stats:
      CPU  0 idle for     10.811  msec
      CPU  1 idle for     20.793  msec
      CPU  2 idle for     30.191  msec
      CPU  3 idle for     18.337  msec

Total number of unique tasks: 23
Total number of context switches: 128

             Total run time (msec): 18.139

Committer notes:

Further testing:

Before:

Idle stats:

      CPU  0 idle for    229.785  msec
      CPU  1 idle for    937.944  msec
      CPU  2 idle for    188.931  msec
      CPU  3 idle for    986.185  msec

After:

  # perf sched timehist --time 40602,40603 -s | tail

Idle stats:

      CPU  0 idle for    229.785  msec
      CPU  1 idle for    175.407  msec
      CPU  2 idle for    188.931  msec
      CPU  3 idle for    223.657  msec

Total number of unique tasks: 68
Total number of context switches: 814

             Total run time (msec): 97.688

  # for cpu in `seq 0 3` ; do echo -n "CPU $cpu idle for " ; perf sched timehist --time 40602,40603 | grep "\[000${cpu}\].*\<idle\>" | tr -s ' ' | cut -d' ' -f7 | awk '{entries++ ; s+=$1} END {print s " msec (entries: " entries ")"}' ; done
  CPU 0 idle for 229.721 msec (entries: 123)
  CPU 1 idle for 175.381 msec (entries: 65)
  CPU 2 idle for 188.903 msec (entries: 56)
  CPU 3 idle for 223.61 msec (entries: 102)

Difference due to the idle stats being accounted at nanoseconds precision while the <idle> entries in 'perf sched timehist' are trucated at msec.usec.

---
 tools/perf/builtin-sched.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 5052caa91caa..d53e706a6f17 100644
@@ -2405,7 +2405,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	if (ptime->start && ptime->start > t)
 		goto out;
 
-	if (ptime->start > tprev)
+	if (tprev && ptime->start > tprev)
 		tprev = ptime->start;
 
 	/*

2.9.3

Hi Arnaldo,

Thanks for taking care of the patches!
Namhyung

Thanks,
Namhyung

Pulled, thanks a lot Arnaldo!

Ingo