Adding more people to the CC, hope they can stick some Acked-by on the final version of this patch.
Em Mon, Nov 29, 2010 at 04:07:09PM -0700, David Ahern escreveu: > Add a timehist option to perf record to save cpu and kernel timestamp > with each sample. Add timehist option to perf report to display the > cpu and timestamps for each event sample rather than generating a > histogram. The timehist option leverages the reference timestamp > from the perf header to create time-of-day stamps. > > This option has been extremely in analyzing context switches. The > time history output can be mined for data such as how long a process > runs when scheduled in, where it is when scheduled out (ie., backtrace) > and how long between schedule in events. Suggestion: Please put some example output on the commit log message, that way reviewers can have a glimpse of how it looks like. More comments below. > Signed-off-by: David Ahern <[email protected]> > --- > tools/perf/builtin-record.c | 8 +++ > tools/perf/builtin-report.c | 120 > ++++++++++++++++++++++++++++++++++++++++++- > 2 files changed, 126 insertions(+), 2 deletions(-) > > diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c > index 024e144..2496b04 100644 > --- a/tools/perf/builtin-record.c > +++ b/tools/perf/builtin-record.c > @@ -49,6 +49,7 @@ static int group > = 0; > static int realtime_prio = 0; > static bool raw_samples = false; > static bool system_wide = false; > +static bool time_history = false; > static pid_t target_pid = -1; > static pid_t target_tid = -1; > static pid_t *all_tids = NULL; > @@ -281,6 +282,11 @@ static void create_counter(int counter, int cpu) > if (system_wide) > attr->sample_type |= PERF_SAMPLE_CPU; > > + if (time_history) { > + attr->sample_type |= PERF_SAMPLE_TIME; > + attr->sample_type |= PERF_SAMPLE_CPU; > + } > + > if (raw_samples) { > attr->sample_type |= PERF_SAMPLE_TIME; > attr->sample_type |= PERF_SAMPLE_RAW; > @@ -840,6 +846,8 @@ const struct option record_options[] = { > "do not update the buildid cache"), > OPT_BOOLEAN('B', "no-buildid", &no_buildid, > "do not collect buildids in perf.data"), > + OPT_BOOLEAN(0, "timehist", &time_history, > + "collect data for time history report"), > OPT_END() > }; > > diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c > index 5de405d..042dc7c 100644 > --- a/tools/perf/builtin-report.c > +++ b/tools/perf/builtin-report.c > @@ -35,6 +35,7 @@ static char const *input_name = "perf.data"; > static bool force, use_tui, use_stdio; > static bool hide_unresolved; > static bool dont_use_callchains; > +static bool time_history; > > static bool show_threads; > static struct perf_read_values show_threads_values; > @@ -124,6 +125,106 @@ out_free_syms: > return err; > } > > +static const char *timestr(u64 timestamp, struct perf_session *session) > +{ > + struct tm ltime; > + u64 dt; > + struct timeval tv_dt, tv_res; > + static char tstr[64]; > + > + dt = timestamp - session->header.nsec_ref; > + tv_dt.tv_sec = (time_t) (dt / NSEC_PER_SEC); > + tv_dt.tv_usec = (suseconds_t) ((dt - tv_dt.tv_sec * NSEC_PER_SEC) / > 1000); > + > + timeradd(&session->header.tv_ref, &tv_dt, &tv_res); > + > + if ((session->header.nsec_ref == 0) || > + (localtime_r(&tv_res.tv_sec, <ime) == NULL)) { > + snprintf(tstr, sizeof(tstr), "00:00:00.000000 %16Ld", > timestamp); > + } else { > + char date[64]; > + strftime(date, sizeof(date), "%H:%M:%S", <ime); > + snprintf(tstr, sizeof(tstr), "%s.%06ld %16Ld", > + date, tv_res.tv_usec, timestamp); > + } > + > + return tstr; > +} > + > +#define TIMEHIST_FMT "%33s %3d %-16s %5d %16Lx %s (%s)\n" > + > +static void timehist_header(void) > +{ > + printf("%33s %3s %-16s %5s %16s %s (%s)\n", > + " Time-of-Day Kernel Timestamp", > + "cpu", "Command Name", "PID", > + " IP ", "Symbol Name", "DSO Name"); > +} > + > +static int perf_session__print_sample(struct perf_session *self, Please replace self with 'session', Thomas suggested that and I agreed that its better. We'll slowly rename all those self variables. > + struct addr_location *al, > + struct sample_data *data) > +{ > + static int show_timehist_error = 1; > + u64 timestamp = 0; > + struct map_symbol *syms = NULL; > + struct symbol *parent = NULL; > + const char *tstr; > + > + if (show_timehist_error && > + ((data->cpu == (u32) -1) || !(self->sample_type & > PERF_SAMPLE_TIME))) { > + pr_err("Data for time history missing in perf event samples.\n" > + "Did you record with -T option?\n"); --timehist As you used: + OPT_BOOLEAN(0, "timehist", &time_history, + "Dump time history of event samples"), In a branch I'm working on I'm using 'T' to mean "--sample_time", i.e. to ask for just PERF_SAMPLE_TIME > + show_timehist_error = 0; > + } > + > + if (self->sample_type & PERF_SAMPLE_TIME) > + timestamp = data->time; > + > + tstr = timestr(timestamp, self); > + > + > + if ((symbol_conf.use_callchain) && data->callchain) { > + u64 i; > + > + syms = perf_session__resolve_callchain(self, al->thread, > + data->callchain, > &parent); > + if (syms == NULL) > + return -ENOMEM; > + > + for (i = 0; i < data->callchain->nr; ++i) { > + const char *symname = "", *dsoname = ""; > + > + if (syms[i].sym && syms[i].sym->name) > + symname = syms[i].sym->name; > + else if (hide_unresolved) > + continue; > + > + if (syms[i].map && syms[i].map->dso && > + syms[i].map->dso->name) > + dsoname = syms[i].map->dso->name; > + else if (hide_unresolved) > + continue; > + > + printf(TIMEHIST_FMT, > + tstr, data->cpu, > + al->thread->comm, al->thread->pid, > + data->callchain->ips[i], symname, dsoname); > + } > + > + free(syms); > + > + } else { > + printf(TIMEHIST_FMT, > + tstr, data->cpu, > + al->thread->comm, al->thread->pid, al->addr, > + al->sym->name, al->map->dso->name); > + } > + printf("\n"); > + > + return 0; > +} > + > static int add_event_total(struct perf_session *session, > struct sample_data *data, > struct perf_event_attr *attr) > @@ -165,7 +266,9 @@ static int process_sample_event(event_t *event, struct > perf_session *session) > if (al.filtered || (hide_unresolved && al.sym == NULL)) > return 0; > > - if (perf_session__add_hist_entry(session, &al, &data)) { > + if (time_history) { > + perf_session__print_sample(session, &al, &data); > + } else if (perf_session__add_hist_entry(session, &al, &data)) { > pr_debug("problem incrementing symbol period, skipping > event\n"); > return -1; > } > @@ -318,6 +421,14 @@ static int __cmd_report(void) > if (ret) > goto out_delete; > > + if (time_history) { > + if (!session->header.nsec_ref) { > + pr_err("Reference timestamp missing in perf.data > file.\n" > + "Cannot convert kernel timestamps to > time-of-day.\n"); > + } > + timehist_header(); > + } > + > ret = perf_session__process_events(session, &event_ops); > if (ret) > goto out_delete; > @@ -333,6 +444,9 @@ static int __cmd_report(void) > if (verbose > 2) > perf_session__fprintf_dsos(session, stdout); > > + if (time_history) > + goto out_delete; > + > next = rb_first(&session->hists_tree); > while (next) { > struct hists *hists; > @@ -478,6 +592,8 @@ static const struct option options[] = { > "columns '.' is reserved."), > OPT_BOOLEAN('U', "hide-unresolved", &hide_unresolved, > "Only display entries resolved to a symbol"), > + OPT_BOOLEAN(0, "timehist", &time_history, > + "Dump time history of event samples"), > OPT_END() > }; > > @@ -485,7 +601,7 @@ int cmd_report(int argc, const char **argv, const char > *prefix __used) > { > argc = parse_options(argc, argv, options, report_usage, 0); > > - if (use_stdio) > + if (use_stdio || time_history) > use_browser = 0; > else if (use_tui) > use_browser = 1; > -- > 1.7.2.3 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in > the body of a message to [email protected] > More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
