| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20101130191905.GB9706@ghostprotocols.net>
Date: Tue, 30 Nov 2010 17:19:05 -0200
From: Arnaldo Carvalho de Melo <acme@...stprotocols.net>
To: David Ahern <daahern@...co.com>
Cc: linux-perf-users@...r.kernel.org, linux-kernel@...r.kernel.org,
Frédéric Weisbecker <fweisbec@...il.com>,
Ingo Molnar <mingo@...e.hu>,
Peter Zijlstra <peterz@...radead.org>,
Stephane Eranian <eranian@...gle.com>,
Thomas Gleixner <tglx@...utronix.de>
Subject: Re: [PATCH 2/2] perf tools: Add option to show time history of event
samples
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 <daahern@...co.com>
> ---
> 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 majordomo@...r.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists