| 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: <1291773285-16254-3-git-send-email-daahern@cisco.com>
Date: Tue, 7 Dec 2010 18:54:45 -0700
From: David Ahern <daahern@...co.com>
To: linux-perf-users@...r.kernel.org, linux-kernel@...r.kernel.org
Cc: David Ahern <daahern@...co.com>
Subject: [PATCH 2/2] perf tools: Add option to show time history of event samples
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):
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@...co.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, <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 "%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-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