lkml.org 
[lkml]   [2010]   [Dec]   [8]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: [PATCH 2/2] perf tools: Add option to show time history of event samples
    Em Tue, Dec 07, 2010 at 06:54:45PM -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 a pretty-print format
    > of the timestamp, cpu, and event data each event rather than
    > generating a histogram. The timehist option leverages the reference
    > timestamp from the perf header to correlate kernel timestamps to
    > time-of-day which allows correlating with external (non-perf)
    > log files.
    >
    > As an example, consider recording context switches:
    > perf record -e cs -c 1 -ga --timehist
    >
    > Today the 'perf report -D' option gives output in the form
    > 0 182392227877 0x17d8f8 [0xd8]: PERF_RECORD_SAMPLE(IP, 1): \
    > 1861/1861: 0xffffffff810348d2 period: 2057672
    > ... chain: nr:21
    > ..... 0: ffffffffffffff80
    > ..... 1: ffffffff810348d2
    > ..... 2: ffffffff8139c02b
    > ..... 3: ffffffffa004b4a3
    > ..... 4: ffffffff8139c79c
    > ..... 5: ffffffff8139c83d
    > ..... 6: ffffffffa004b43f
    > ..... 7: ffffffffa00ec135
    > ..... 8: ffffffffa00ec214
    > ..... 9: ffffffffa00f01ec
    > ..... 10: ffffffffa00f0439
    > ..... 11: ffffffffa00d6e8b
    > ..... 12: ffffffff8110b763
    > ..... 13: ffffffff8110b883
    > ..... 14: ffffffff8110ddcd
    > ..... 15: ffffffff8110e45d
    > ..... 16: ffffffff81101f36
    > ..... 17: ffffffff81101ff3
    > ..... 18: ffffffff81002c82
    > ..... 19: fffffffffffffe00
    > ..... 20: 00002acfd31ce050
    > ... thread: cc1:1861
    > ...... dso: /lib/modules/2.6.37-rc5/build/vmlinux
    >
    > With the timehist option 'perf report --timehist' displays the same sample as
    > (lines wrapped to < 80 and truncated here):

    You can instead compress the same info as:

    -------------------------------

    With the timehist option 'perf report --timehist' displays the same
    sample as (some fields removed/compressed to make it fit under 80 columns)

    17:11:10.1 cc1 61 ff810348d2 perf_event_task_sched_out ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff8139c02b schedule ([kernel.kallsyms])
    17:11:10.1 cc1 61 ffa004b4a3 rpc_wait_bit_killable (/lib/modules/2.6.37-rc5/...
    17:11:10.1 cc1 61 ff8139c79c __wait_on_bit ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff8139c83d out_of_line_wait_on_bit ([kernel.kallsyms])
    17:11:10.1 cc1 61 ffa004b43f __rpc_wait_for_completion_task (/lib/modules/...
    17:11:10.1 cc1 61 ffa00ec135 nfs4_wait_for_completion_rpc_task (/lib/modules/...
    17:11:10.1 cc1 61 ffa00ec214 nfs4_run_open_task (/lib/modules/2.6.37-rc5/...
    17:11:10.1 cc1 61 ffa00f01ec nfs4_do_open.clone.21 (/lib/modules/2.6.37-rc5/...
    17:11:10.1 cc1 61 ffa00f0439 nfs4_atomic_open (/lib/modules/2.6.37-rc5/...
    17:11:10.1 cc1 61 ffa00d6e8b nfs_open_revalidate (/lib/modules/2.6.37-rc5/...
    17:11:10.1 cc1 61 ff8110b763 do_revalidate ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff8110b883 do_lookup ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff8110ddcd do_last ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff8110e45d do_filp_open ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff81101f36 do_sys_open ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff81101ff3 sys_open ([kernel.kallsyms])
    17:11:10.1 cc1 61 ff81002c82 system_call ([kernel.kallsyms])
    17:11:10.1 cc1 61 1ce050 __GI___libc_open (/lib64/libc-2.12.90.so)

    It allows you to see each schedule out point, where the process is when
    it gets scheduled out and, with additional processing on the timehist
    output, time between schedule-in events and time on the processor.

    -----------------------------

    changing the PID and addresses on the 'perf record -D' output to match the
    shorter PID, etc, helps too.

    will continue reviewing later, thanks

    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff810348d2 perf_event_task_sched_out ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8139c02b schedule ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa004b4a3 rpc_wait_bit_killable (/lib/modules/2.6.37-rc5/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8139c79c __wait_on_bit ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8139c83d out_of_line_wait_on_bit ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa004b43f __rpc_wait_for_completion_task (/lib/modules/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa00ec135 nfs4_wait_for_completion_rpc_task (/lib/modules/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa00ec214 nfs4_run_open_task (/lib/modules/2.6.37-rc5/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa00f01ec nfs4_do_open.clone.21 (/lib/modules/2.6.37-rc5/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa00f0439 nfs4_atomic_open (/lib/modules/2.6.37-rc5/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffffa00d6e8b nfs_open_revalidate (/lib/modules/2.6.37-rc5/...
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8110b763 do_revalidate ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8110b883 do_lookup ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8110ddcd do_last ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff8110e45d do_filp_open ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff81101f36 do_sys_open ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff81101ff3 sys_open ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > ffffffff81002c82 system_call ([kernel.kallsyms])
    > 17:11:10.174502 182392227877 0 cc1 1861 \
    > 2acfd31ce050 __GI___libc_open (/lib64/libc-2.12.90.so)
    >
    > While the line lengths are horrible for a git commit message and email,
    > the data is indispensable. It allows you to see each schedule out point,
    > where the process is when it gets scheduled out and, with additional
    > processing on the timehist output, time between schedule-in events and
    > time on the processor.
    >
    > Signed-off-by: David Ahern <daahern@cisco.com>
    > ---
    > tools/perf/builtin-record.c | 8 +++
    > tools/perf/builtin-report.c | 131 ++++++++++++++++++++++++++++++++++++++++++-
    > 2 files changed, 137 insertions(+), 2 deletions(-)
    >
    > diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
    > index 699dd21..cf30c98 100644
    > --- a/tools/perf/builtin-record.c
    > +++ b/tools/perf/builtin-record.c
    > @@ -51,6 +51,7 @@ static int realtime_prio = 0;
    > static bool raw_samples = false;
    > static bool sample_id_all_avail = true;
    > 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;
    > @@ -288,6 +289,11 @@ static void create_counter(int counter, int cpu)
    > if (sample_time)
    > attr->sample_type |= PERF_SAMPLE_TIME;
    >
    > + 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;
    > @@ -863,6 +869,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 904519f..bcde3c2 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,117 @@ 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, &ltime) == NULL)) {
    > + snprintf(tstr, sizeof(tstr), "00:00:00.000000 %16Ld", timestamp);
    > + } else {
    > + char date[64];
    > + strftime(date, sizeof(date), "%H:%M:%S", &ltime);
    > + snprintf(tstr, sizeof(tstr), "%s.%06ld %16Ld",
    > + date, tv_res.tv_usec, timestamp);
    > + }
    > +
    > + return tstr;
    > +}
    > +
    > +#define TIMEHIST_FMT "%32s %3d %-16s %5d %16Lx %s (%s)\n"
    > +
    > +static void timehist_header(void)
    > +{
    > + printf("%32s %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 *session,
    > + 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;
    > + bool need_spacer = false;
    > +
    > + if (show_timehist_error && ((data->cpu == (u32) -1) ||
    > + !(session->sample_type & PERF_SAMPLE_TIME))) {
    > + pr_err("Data for time history missing in perf event samples.\n"
    > + "Did you record with --timehist option?\n");
    > + show_timehist_error = 0;
    > + }
    > +
    > + if (session->sample_type & PERF_SAMPLE_TIME)
    > + timestamp = data->time;
    > +
    > + tstr = timestr(timestamp, session);
    > +
    > +
    > + if ((symbol_conf.use_callchain) && data->callchain) {
    > + u64 i;
    > +
    > + syms = perf_session__resolve_callchain(session, al->thread,
    > + data->callchain, &parent);
    > + if (syms == NULL)
    > + return -ENOMEM;
    > +
    > + for (i = 0; i < data->callchain->nr; ++i) {
    > + const char *symname = "", *dsoname = "";
    > +
    > + if (data->callchain->ips[i] >= PERF_CONTEXT_MAX)
    > + continue;
    > +
    > + 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);
    > +
    > + need_spacer = true;
    > + }
    > +
    > + free(syms);
    > +
    > + } else {
    > + printf(TIMEHIST_FMT,
    > + tstr, data->cpu,
    > + al->thread->comm, al->thread->pid, al->addr,
    > + al->sym->name, al->map->dso->name);
    > +
    > + need_spacer = true;
    > + }
    > +
    > + /* put a gap between records */
    > + if (need_spacer)
    > + printf("\n");
    > +
    > + return 0;
    > +}
    > +
    > static int add_event_total(struct perf_session *session,
    > struct sample_data *data,
    > struct perf_event_attr *attr)
    > @@ -165,7 +277,9 @@ static int process_sample_event(event_t *event, struct sample_data *sample,
    > if (al.filtered || (hide_unresolved && al.sym == NULL))
    > return 0;
    >
    > - if (perf_session__add_hist_entry(session, &al, sample)) {
    > + if (time_history) {
    > + perf_session__print_sample(session, &al, sample);
    > + } else if (perf_session__add_hist_entry(session, &al, sample)) {
    > pr_debug("problem incrementing symbol period, skipping event\n");
    > return -1;
    > }
    > @@ -319,6 +433,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;
    > @@ -334,6 +456,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;
    > @@ -479,6 +604,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()
    > };
    >
    > @@ -486,7 +613,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@vger.kernel.org
    > More majordomo info at http://vger.kernel.org/majordomo-info.html


    \
     
     \ /
      Last update: 2010-12-08 22:09    [W:0.091 / U:0.164 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site