Skip to content

Commit

Permalink
perf sched timehist: Add option to specify time window of interest
Browse files Browse the repository at this point in the history
Add option to allow user to control analysis window. e.g., collect data
for time window and analyze a segment of interest within that window.

Committer notes:

Testing it:

  # perf sched record -a usleep 1
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 1.593 MB perf.data (25 samples) ]
  #
  # perf sched timehist | head -18
  Samples do not have callchains.
          time    cpu   task name       wait time  sch delay  run time
                        [tid/pid]          (msec)     (msec)    (msec)
  ------------- ------  --------------- ---------  ---------  --------
   19818.635579 [0002]  <idle>              0.000      0.000     0.000
   19818.635613 [0000]  perf[9116]          0.000      0.000     0.000
   19818.635676 [0000]  <idle>              0.000      0.000     0.063
   19818.635678 [0000]  rcuos/2[29]         0.000      0.002     0.001
   19818.635696 [0002]  perf[9117]          0.000      0.004     0.116
   19818.635702 [0000]  <idle>              0.001      0.000     0.024
   19818.635709 [0002]  migration/2[25]     0.000      0.003     0.012
   19818.636263 [0000]  usleep[9117]        0.005      0.000     0.560
   19818.636316 [0000]  <idle>              0.560      0.000     0.053
   19818.636358 [0002]  <idle>              0.129      0.000     0.649
   19818.636358 [0000]  usleep[9117]        0.053      0.002     0.042
  #

  # perf sched timehist --time 19818.635696,
  Samples do not have callchains.
           time    cpu  task name       wait time  sch delay  run time
                        [tid/pid]          (msec)     (msec)    (msec)
  ------------- ------  ---------------  --------  --------- ---------
   19818.635696 [0002]  perf[9117]          0.000      0.120     0.000
   19818.635702 [0000]  <idle>              0.019      0.000     0.006
   19818.635709 [0002]  migration/2[25]     0.000      0.003     0.012
   19818.636263 [0000]  usleep[9117]        0.005      0.000     0.560
   19818.636316 [0000]  <idle>              0.560      0.000     0.053
   19818.636358 [0002]  <idle>              0.129      0.000     0.649
   19818.636358 [0000]  usleep[9117]        0.053      0.002     0.042
  #
  # perf sched timehist --time 19818.635696,19818.635709
  Samples do not have callchains.
           time    cpu  task name       wait time  sch delay  run time
                        [tid/pid]          (msec)     (msec)    (msec)
  ------------- ------  --------------- ---------  --------- ---------
   19818.635696 [0002]  perf[9117]          0.000      0.120     0.000
   19818.635702 [0000]  <idle>              0.019      0.000     0.006
   19818.635709 [0002]  migration/2[25]     0.000      0.003     0.012
   19818.635709 [0000]  usleep[9117]        0.005      0.000     0.006
  #

Signed-off-by: David Ahern <dsahern@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1480439746-42695-5-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
  • Loading branch information
David Ahern authored and Arnaldo Carvalho de Melo committed Dec 1, 2016
1 parent a91f4c4 commit 853b740
Show file tree
Hide file tree
Showing 2 changed files with 53 additions and 6 deletions.
8 changes: 8 additions & 0 deletions tools/perf/Documentation/perf-sched.txt
Original file line number Diff line number Diff line change
Expand Up @@ -132,6 +132,14 @@ OPTIONS for 'perf sched timehist'
--migrations::
Show migration events.

--time::
Only analyze samples within given time window: <start>,<stop>. Times
have the format seconds.microseconds. If start is not given (i.e., time
string is ',x.y') then analysis starts at the beginning of the file. If
stop time is not given (i.e, time string is 'x.y,') then analysis goes
to end of file.


SEE ALSO
--------
linkperf:perf-record[1]
51 changes: 45 additions & 6 deletions tools/perf/builtin-sched.c
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
#include "util/color.h"
#include "util/stat.h"
#include "util/callchain.h"
#include "util/time-utils.h"

#include <subcmd/parse-options.h>
#include "util/trace-event.h"
Expand Down Expand Up @@ -205,6 +206,8 @@ struct perf_sched {
bool show_wakeups;
bool show_migrations;
u64 skipped_samples;
const char *time_str;
struct perf_time_interval ptime;
};

/* per thread run time data */
Expand Down Expand Up @@ -1837,13 +1840,14 @@ static void timehist_header(struct perf_sched *sched)
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
struct addr_location *al,
struct thread *thread)
struct thread *thread,
u64 t)
{
struct thread_runtime *tr = thread__priv(thread);
u32 max_cpus = sched->max_cpu + 1;
char tstr[64];

timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);

if (sched->show_cpu_visual) {
Expand Down Expand Up @@ -2194,7 +2198,8 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
tr->ready_to_run = sample->time;

/* show wakeups if requested */
if (sched->show_wakeups)
if (sched->show_wakeups &&
!perf_time__skip_sample(&sched->ptime, sample->time))
timehist_print_wakeup_event(sched, sample, machine, thread);

return 0;
Expand Down Expand Up @@ -2288,10 +2293,11 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct machine *machine)
{
struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct perf_time_interval *ptime = &sched->ptime;
struct addr_location al;
struct thread *thread;
struct thread_runtime *tr = NULL;
u64 tprev;
u64 tprev, t = sample->time;
int rc = 0;

if (machine__resolve(machine, &al, sample) < 0) {
Expand All @@ -2318,9 +2324,35 @@ static int timehist_sched_change_event(struct perf_tool *tool,

tprev = perf_evsel__get_time(evsel, sample->cpu);

timehist_update_runtime_stats(tr, sample->time, tprev);
/*
* If start time given:
* - sample time is under window user cares about - skip sample
* - tprev is under window user cares about - reset to start of window
*/
if (ptime->start && ptime->start > t)
goto out;

if (ptime->start > tprev)
tprev = ptime->start;

/*
* If end time given:
* - previous sched event is out of window - we are done
* - sample time is beyond window user cares about - reset it
* to close out stats for time window interest
*/
if (ptime->end) {
if (tprev > ptime->end)
goto out;

if (t > ptime->end)
t = ptime->end;
}

timehist_update_runtime_stats(tr, t, tprev);

if (!sched->summary_only)
timehist_print_sample(sched, sample, &al, thread);
timehist_print_sample(sched, sample, &al, thread, t);

out:
if (tr) {
Expand Down Expand Up @@ -2583,6 +2615,11 @@ static int perf_sched__timehist(struct perf_sched *sched)

symbol__init(&session->header.env);

if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
pr_err("Invalid time string\n");
return -EINVAL;
}

if (timehist_check_attr(sched, evlist) != 0)
goto out;

Expand Down Expand Up @@ -2997,6 +3034,8 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
OPT_STRING(0, "time", &sched.time_str, "str",
"Time span for analysis (start,stop)"),
OPT_PARENT(sched_options)
};

Expand Down

0 comments on commit 853b740

Please sign in to comment.