perf sched timehist: Add -w/--wakeups option

The -w option is to show wakeup events with timehist.

  $ perf sched timehist -w
             time    cpu  task name              b/n time  sch delay   run time
                          [tid/pid]                (msec)     (msec)     (msec)
  --------------- ------  --------------------  ---------  ---------  ---------
   2412598.429689 [0002]  perf[7219]                                             awakened: perf[7220]
   2412598.429696 [0009]  <idle>                    0.000      0.000      0.000
   2412598.429767 [0002]  perf[7219]                0.000      0.000      0.000
   2412598.429780 [0009]  perf[7220]                                             awakened: migration/9[53]
  ...

Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-6-namhyung@kernel.org
[ Add documentation based on above commit message ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 72730da307b9a8c23ea8864dbbcd4a8836d96dda..9a77bc73e8a3450ec26661b3db4f2faa388ea890 100644 (file)
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -112,6 +112,10 @@ OPTIONS for 'perf sched timehist'
 --symfs=<directory>::
     Look for files with symbols relative to this directory.
 
+-w::
+--wakeups::
+       Show wakeup events.
+
 SEE ALSO
 --------
 linkperf:perf-record[1]

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1e7d81ad5ec650c350982b0b7b2714d9ca4b5a1e..8fb7bcc2cb76b990be1dc2715e6cb9d573fa536b 100644 (file)
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -198,6 +198,7 @@ struct perf_sched {
        /* options for timehist command */
        bool            summary;
        bool            summary_only;
+       bool            show_wakeups;
        u64             skipped_samples;
 };
 
@@ -1807,7 +1808,8 @@ static void timehist_header(void)
        printf("\n");
 }
 
-static void timehist_print_sample(struct perf_sample *sample,
+static void timehist_print_sample(struct perf_sched *sched,
+                                 struct perf_sample *sample,
                                  struct thread *thread)
 {
        struct thread_runtime *tr = thread__priv(thread);
@@ -1821,6 +1823,10 @@ static void timehist_print_sample(struct perf_sample *sample,
        print_sched_time(tr->dt_wait, 6);
        print_sched_time(tr->dt_delay, 6);
        print_sched_time(tr->dt_run, 6);
+
+       if (sched->show_wakeups)
+               printf("  %-*s", comm_width, "");
+
        printf("\n");
 }
 
@@ -2028,12 +2034,44 @@ static bool timehist_skip_sample(struct perf_sched *sched,
        return rc;
 }
 
-static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+static void timehist_print_wakeup_event(struct perf_sched *sched,
+                                       struct perf_sample *sample,
+                                       struct machine *machine,
+                                       struct thread *awakened)
+{
+       struct thread *thread;
+       char tstr[64];
+
+       thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+       if (thread == NULL)
+               return;
+
+       /* show wakeup unless both awakee and awaker are filtered */
+       if (timehist_skip_sample(sched, thread) &&
+           timehist_skip_sample(sched, awakened)) {
+               return;
+       }
+
+       timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+       printf("%15s [%04d] ", tstr, sample->cpu);
+
+       printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+       /* dt spacer */
+       printf("  %9s  %9s  %9s ", "", "", "");
+
+       printf("awakened: %s", timehist_get_commstr(awakened));
+
+       printf("\n");
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool,
                                       union perf_event *event __maybe_unused,
                                       struct perf_evsel *evsel,
                                       struct perf_sample *sample,
                                       struct machine *machine)
 {
+       struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
        struct thread *thread;
        struct thread_runtime *tr = NULL;
        /* want pid of awakened task not pid in sample */
@@ -2050,6 +2088,10 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
        if (tr->ready_to_run == 0)
                tr->ready_to_run = sample->time;
 
+       /* show wakeups if requested */
+       if (sched->show_wakeups)
+               timehist_print_wakeup_event(sched, sample, machine, thread);
+
        return 0;
 }
 
@@ -2059,12 +2101,12 @@ static int timehist_sched_change_event(struct perf_tool *tool,
                                       struct perf_sample *sample,
                                       struct machine *machine)
 {
+       struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
        struct addr_location al;
        struct thread *thread;
        struct thread_runtime *tr = NULL;
        u64 tprev;
        int rc = 0;
-       struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
 
        if (machine__resolve(machine, &al, sample) < 0) {
                pr_err("problem processing %d event. skipping it\n",
@@ -2092,7 +2134,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 
        timehist_update_runtime_stats(tr, sample->time, tprev);
        if (!sched->summary_only)
-               timehist_print_sample(sample, thread);
+               timehist_print_sample(sched, sample, thread);
 
 out:
        if (tr) {
@@ -2723,6 +2765,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
                    "Show only syscall summary with statistics"),
        OPT_BOOLEAN('S', "with-summary", &sched.summary,
                    "Show all syscalls and summary with statistics"),
+       OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
        OPT_PARENT(sched_options)
        };
 
@@ -2814,6 +2857,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
                        if (argc)
                                usage_with_options(timehist_usage, timehist_options);
                }
+               if (sched.show_wakeups && sched.summary_only) {
+                       pr_err(" Error: -s and -w are mutually exclusive.\n");
+                       parse_options_usage(timehist_usage, timehist_options, "s", true);
+                       parse_options_usage(NULL, timehist_options, "w", true);
+                       return -EINVAL;
+               }
+
                return perf_sched__timehist(&sched);
        } else {
                usage_with_options(sched_usage, sched_options);