[PATCH 3/3] perf events: add timehist option to record and report

From: David Ahern
Date: Fri Feb 18 2011 - 00:54:11 EST

The intent of the timehist option is to 'pretty-print' the samples
recorded rather than generating a histogram. This is done by
sampling the realtime clock event and correlating perf_clock time
stamps to wall-clock.

If the realtime-clock event is not available (e.g, older kernels)
fallback to a synthesized event. (I realize there is resistance
to new synthesized events, but it is a simple way to gain this
feature on older kernels without the new to modify the kernel
code).

NOTE: Commit ba3dd36 needs to be reverted else this causes the
system to spin. Ironically, ba3dd36 was created to resolve a
lockup.

Signed-off-by: David Ahern <daahern@xxxxxxxxx>
---
tools/perf/Documentation/perf-record.txt | 4 +
tools/perf/Documentation/perf-report.txt | 6 +
tools/perf/builtin-record.c | 78 +++++++++++-
tools/perf/builtin-report.c | 208 +++++++++++++++++++++++++++++-
tools/perf/util/event.c | 1 +
tools/perf/util/event.h | 8 +
tools/perf/util/parse-events.c | 2 +
tools/perf/util/session.c | 4 +
tools/perf/util/session.h | 3 +-
9 files changed, 310 insertions(+), 4 deletions(-)

diff --git a/tools/perf/Documentation/perf-record.txt b/tools/perf/Documentation/perf-record.txt
index 5a520f8..8ae106b 100644
--- a/tools/perf/Documentation/perf-record.txt
+++ b/tools/perf/Documentation/perf-record.txt
@@ -148,6 +148,10 @@ an empty cgroup (monitor all the time) using, e.g., -G foo,,bar. Cgroups must ha
corresponding events, i.e., they always refer to events defined earlier on the command
line.

+--timehist::
+Collect data for time history report. This generates reference time samples
+which are used to convert perf timestamps to time-of-day.
+
SEE ALSO
--------
linkperf:perf-stat[1], linkperf:perf-list[1]
diff --git a/tools/perf/Documentation/perf-report.txt b/tools/perf/Documentation/perf-report.txt
index 8ba03d6..aaaf035 100644
--- a/tools/perf/Documentation/perf-report.txt
+++ b/tools/perf/Documentation/perf-report.txt
@@ -119,6 +119,12 @@ OPTIONS
--symfs=<directory>::
Look for files with symbols relative to this directory.

+--timehist::
+ Generate time history output. This shows each sample with a wall-clock
+ timestamp and address to symbol conversions. The samples are output in
+ the same order they exist in the perf.data file. The --timehist option
+ must be used with the record to get wall-clock timestamps.
+
SEE ALSO
--------
linkperf:perf-stat[1]
diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index a4aaadc..91d49a3 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -55,6 +55,8 @@ static bool nodelay = false;
static bool raw_samples = false;
static bool sample_id_all_avail = true;
static bool system_wide = false;
+static bool time_history = false;
+static struct perf_evsel *th_evsel = NULL;
static pid_t target_pid = -1;
static pid_t target_tid = -1;
static pid_t child_pid = -1;
@@ -276,6 +278,11 @@ static void config_attr(struct perf_evsel *evsel, struct perf_evlist *evlist)
attr->sample_type |= PERF_SAMPLE_CPU;
}

+ if (time_history) {
+ attr->sample_type |= PERF_SAMPLE_TIME;
+ attr->sample_type |= PERF_SAMPLE_CPU;
+ }
+
if (nodelay) {
attr->watermark = 0;
attr->wakeup_events = 1;
@@ -290,6 +297,56 @@ static void config_attr(struct perf_evsel *evsel, struct perf_evlist *evlist)
}
}

+static int perf_event__synthesize_reftime(perf_event__handler_t process,
+ struct perf_session *psession)
+{
+ union perf_event ev;
+ struct timespec tp;
+
+ memset(&ev, 0, sizeof(ev));
+
+ /* race here between successive calls, but should be close enough */
+ if (gettimeofday(&ev.reftime.tv, NULL) != 0) {
+ error("gettimeofday failed. Cannot generate reference time.\n");
+ return -1;
+ }
+ if (clock_gettime(CLOCK_MONOTONIC, &tp) != 0) {
+ error("clock_gettime failed. Cannot generate reference time.\n");
+ return -1;
+ }
+ ev.reftime.nsec = (u64) tp.tv_sec * NSEC_PER_SEC + (u64) tp.tv_nsec;
+
+ ev.header.type = PERF_RECORD_REFTIME;
+ ev.header.size = sizeof(ev.reftime);
+
+ return process(&ev, NULL, psession);
+}
+
+static struct perf_evsel *create_timehist_counter(void)
+{
+ struct perf_event_attr attr;
+ struct perf_evsel *evsel;
+
+ memset(&attr, 0, sizeof(attr));
+ attr.type = PERF_TYPE_SOFTWARE;
+ attr.config = PERF_COUNT_SW_REALTIME_CLOCK;
+
+ /* need raw to get realtime clock samples and want sample
+ * time for correlating the two
+ */
+ attr.sample_type = PERF_SAMPLE_RAW | PERF_SAMPLE_ID | PERF_SAMPLE_TIME;
+ attr.read_format = PERF_FORMAT_ID;
+
+ /* TO-DO: make this time configurable */
+ attr.sample_period = 1 * NSEC_PER_SEC;
+
+ evsel = perf_evsel__new(&attr, evsel_list->nr_entries);
+ if (!evsel)
+ die("Error: Failed to allocate memory for time counter\n");
+
+ return evsel;
+}
+
static void open_counters(struct perf_evlist *evlist)
{
struct perf_evsel *pos;
@@ -331,7 +388,8 @@ try_again:
* Old kernel, no attr->sample_id_type_all field
*/
sample_id_all_avail = false;
- if (!sample_time && !raw_samples && !time_needed)
+ if (!sample_time && !raw_samples
+ && !time_needed && !time_history)
attr->sample_type &= ~PERF_SAMPLE_TIME;

goto retry_sample_id;
@@ -612,6 +670,16 @@ static int __cmd_record(int argc, const char **argv)
return err;
}

+ if (time_history && !th_evsel) {
+ if (verbose)
+ warning ("REALTIME_CLOCK event failed. "
+ "falling back to synthesized clock events\n");
+
+ if (perf_event__synthesize_reftime(process_synthesized_event,
+ session) != 0)
+ error("Failed to synthesize reftime event. SOL.\n");
+ }
+
post_processing_offset = lseek(output, 0, SEEK_CUR);

perf_session__set_sample_id_all(session, sample_id_all_avail);
@@ -810,6 +878,8 @@ const struct option record_options[] = {
OPT_CALLBACK('G', "cgroup", &evsel_list, "name",
"monitor event in cgroup name only",
parse_cgroups),
+ OPT_BOOLEAN(0, "timehist", &time_history,
+ "collect data for time history report"),
OPT_END()
};

@@ -855,6 +925,12 @@ int cmd_record(int argc, const char **argv, const char *prefix __used)
goto out_symbol_exit;
}

+ if (time_history) {
+ th_evsel = create_timehist_counter();
+ if (th_evsel)
+ perf_evlist__add(evsel_list, th_evsel);
+ }
+
if (target_pid != -1)
target_tid = target_pid;

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index f9a99a1..59002d6 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -36,6 +36,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;
@@ -46,6 +47,189 @@ static const char *pretty_printing_style = default_pretty_printing_style;
static char callchain_default_opt[] = "fractal,0.5";
static symbol_filter_t annotate_init;

+
+struct timeval tv_ref;
+u64 timestamp_ref;
+
+static const char *timestr(u64 timestamp)
+{
+ struct tm ltime;
+ u64 dt;
+ struct timeval tv_dt, tv_res;
+ static char tstr[64];
+
+ if (timestamp_ref == 0) {
+ static bool show_msg = true;
+ if (show_msg) {
+ fprintf(stderr, "Reference clock event not found in file; "
+ "Cannot generate wall-clock time strings\n");
+ show_msg = false;
+ }
+ snprintf(tstr, sizeof(tstr), "%16" PRId64, timestamp);
+ return tstr;
+ } else if (timestamp == 0) {
+ snprintf(tstr, sizeof(tstr), "%16" PRId64, timestamp);
+ return tstr;
+ }
+ if (timestamp > timestamp_ref) {
+ dt = timestamp - timestamp_ref;
+ tv_dt.tv_sec = (time_t) (dt / NSEC_PER_SEC);
+ tv_dt.tv_usec = (dt - tv_dt.tv_sec * NSEC_PER_SEC) / 1000;
+ timeradd(&tv_ref, &tv_dt, &tv_res);
+ } else {
+ dt = timestamp_ref - timestamp;
+ tv_dt.tv_sec = (time_t) (dt / NSEC_PER_SEC);
+ tv_dt.tv_usec = (dt - tv_dt.tv_sec * NSEC_PER_SEC) / 1000;
+ timersub(&tv_ref, &tv_dt, &tv_res);
+ }
+
+ if (localtime_r(&tv_res.tv_sec, &ltime) == NULL) {
+ snprintf(tstr, sizeof(tstr), "00:00:00.000000 %16" PRId64, timestamp);
+ } else {
+ char date[64];
+ strftime(date, sizeof(date), "%H:%M:%S", &ltime);
+ snprintf(tstr, sizeof(tstr), "%s.%06ld %16" PRId64,
+ date, tv_res.tv_usec, timestamp);
+ }
+
+ return tstr;
+}
+
+#define TIMEHIST_FMT "%32s %2d %s %s %d %16" PRIx64 " %s (%s)\n"
+
+static void timehist_header(void)
+{
+ printf("%32s %s %7s %3s %5s %16s %s (%s)\n\n",
+ " Time-of-Day Kernel Timestamp",
+ "cpu", "Event", "Command", "PID",
+ " IP ", "Symbol Name", "DSO Name");
+}
+
+static int perf_event__process_reftime(union perf_event *event,
+ struct perf_session *session __used)
+{
+ tv_ref = event->reftime.tv;
+ timestamp_ref = event->reftime.nsec;
+
+ return 0;
+}
+
+static void perf_event__process_rclk(struct perf_sample *sample,
+ struct perf_session *session)
+{
+ u64 s;
+
+ if (!sample->raw_size) {
+ printf("rclk sample does not have raw data.\n");
+ return;
+ }
+
+ if (sample->raw_size != sizeof(u64)) {
+ printf("rclk sample has raw size %d; expected %ld.\n",
+ sample->raw_size, sizeof(u64));
+ return;
+ }
+ if (!(session->sample_type & PERF_SAMPLE_TIME)) {
+ printf("rclk sample does not have kernel sample time\n");
+ return;
+ }
+
+ /* convert raw sample to wall-clock reference time */
+ s = *(u64*)sample->raw_data;
+ tv_ref.tv_sec = s / NSEC_PER_SEC;
+ tv_ref.tv_usec = (s - tv_ref.tv_sec * NSEC_PER_SEC) / 1000;
+
+ /* match raw sample with kernel timestamp */
+ timestamp_ref = sample->time;
+}
+
+static void perf_session__print_sample(struct perf_session *session,
+ struct addr_location *al,
+ struct perf_sample *sample)
+{
+ static int show_timehist_error = 1;
+ struct callchain_cursor_node *node, *prev;
+ u64 timestamp = 0;
+ const char *tstr;
+ bool need_spacer = false;
+ struct perf_event_attr *attr;
+ const char *evname = NULL;
+ const char *symname = "", *dsoname = "";
+
+ if (show_timehist_error && ((sample->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;
+ }
+
+ attr = perf_header__find_attr(sample->id, &session->header);
+ if (attr)
+ evname = __event_name(attr->type, attr->config);
+
+ if (session->sample_type & PERF_SAMPLE_TIME)
+ timestamp = sample->time;
+
+ tstr = timestr(timestamp);
+
+ if ((symbol_conf.use_callchain) && sample->callchain) {
+
+ if (perf_session__resolve_callchain(session, al->thread,
+ sample->callchain, NULL) != 0) {
+ fprintf(stderr, "failed to resolve callchain. skipping\n");
+ return;
+ }
+
+ node = session->callchain_cursor.first;
+ while (node) {
+
+ if (node->sym && node->sym->name)
+ symname = node->sym->name;
+ else if (hide_unresolved)
+ continue;
+
+ if (node->map && node->map->dso && node->map->dso->name)
+ dsoname = node->map->dso->name;
+ else if (hide_unresolved)
+ continue;
+
+ printf(TIMEHIST_FMT,
+ tstr, sample->cpu, evname ? evname : "-",
+ al->thread->comm_set ? al->thread->comm : "-",
+ al->thread->pid,
+ node->ip,
+ symname, dsoname);
+
+ need_spacer = true;
+
+ prev = node;
+ node = node->next;
+ }
+
+ } else {
+ if (al->sym && al->sym->name)
+ symname = al->sym->name;
+
+ if (al->map && al->map->dso && al->map->dso->name)
+ dsoname = al->map->dso->name;
+
+ printf(TIMEHIST_FMT,
+ tstr, sample->cpu, evname ? evname : "-",
+ al->thread->comm_set ? al->thread->comm : "-",
+ al->thread->pid, al->addr,
+ symname, dsoname);
+
+ need_spacer = true;
+ }
+
+ /* put a gap between records */
+ if (need_spacer)
+ printf("\n");
+
+ return;
+}
+
+
static struct hists *perf_session__hists_findnew(struct perf_session *self,
u64 event_stream, u32 type,
u64 config)
@@ -167,6 +351,15 @@ static int process_sample_event(union perf_event *event,
struct addr_location al;
struct perf_event_attr *attr;

+ attr = perf_header__find_attr(sample->id, &session->header);
+ if (attr &&
+ (attr->type == PERF_TYPE_SOFTWARE) &&
+ (attr->config == PERF_COUNT_SW_REALTIME_CLOCK)) {
+ perf_event__process_rclk(sample, session);
+ if (time_history)
+ return 0;
+ }
+
if (perf_event__preprocess_sample(event, session, &al, sample,
annotate_init) < 0) {
fprintf(stderr, "problem processing %d event, skipping it.\n",
@@ -177,7 +370,9 @@ static int process_sample_event(union perf_event *event,
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;
}
@@ -257,6 +452,7 @@ static struct perf_event_ops event_ops = {
.event_type = perf_event__process_event_type,
.tracing_data = perf_event__process_tracing_data,
.build_id = perf_event__process_build_id,
+ .reftime = perf_event__process_reftime,
.ordered_samples = true,
.ordering_requires_timestamps = true,
};
@@ -334,6 +530,9 @@ static int __cmd_report(void)
if (ret)
goto out_delete;

+ if (time_history)
+ timehist_header();
+
ret = perf_session__process_events(session, &event_ops);
if (ret)
goto out_delete;
@@ -349,6 +548,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;
@@ -498,6 +700,8 @@ static const struct option options[] = {
"Only display entries resolved to a symbol"),
OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
"Look for files with symbols relative to this directory"),
+ OPT_BOOLEAN(0, "timehist", &time_history,
+ "Dump time history of event samples"),
OPT_END()
};

@@ -505,7 +709,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;
diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index fbf5754..6bbd551 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -24,6 +24,7 @@ static const char *perf_event__names[] = {
[PERF_RECORD_HEADER_TRACING_DATA] = "TRACING_DATA",
[PERF_RECORD_HEADER_BUILD_ID] = "BUILD_ID",
[PERF_RECORD_FINISHED_ROUND] = "FINISHED_ROUND",
+ [PERF_RECORD_REFTIME] = "REF_TIME",
};

const char *perf_event__name(unsigned int id)
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 9c35170..4ba112d 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -91,6 +91,7 @@ enum perf_user_event_type { /* above any possible kernel type */
PERF_RECORD_HEADER_TRACING_DATA = 66,
PERF_RECORD_HEADER_BUILD_ID = 67,
PERF_RECORD_FINISHED_ROUND = 68,
+ PERF_RECORD_REFTIME = 69,
PERF_RECORD_HEADER_MAX
};

@@ -117,6 +118,12 @@ struct tracing_data_event {
u32 size;
};

+struct reftime_event {
+ struct perf_event_header header;
+ struct timeval tv;
+ u64 nsec;
+};
+
union perf_event {
struct perf_event_header header;
struct ip_event ip;
@@ -130,6 +137,7 @@ union perf_event {
struct event_type_event event_type;
struct tracing_data_event tracing_data;
struct build_id_event build_id;
+ struct reftime_event reftime;
};

void perf_event__print_totals(void);
diff --git a/tools/perf/util/parse-events.c b/tools/perf/util/parse-events.c
index cf082da..eb143a1 100644
--- a/tools/perf/util/parse-events.c
+++ b/tools/perf/util/parse-events.c
@@ -40,6 +40,7 @@ static struct event_symbol event_symbols[] = {
{ CHW(BUS_CYCLES), "bus-cycles", "" },

{ CSW(CPU_CLOCK), "cpu-clock", "" },
+ { CSW(REALTIME_CLOCK), "realtime-clock", "rclk" },
{ CSW(TASK_CLOCK), "task-clock", "" },
{ CSW(PAGE_FAULTS), "page-faults", "faults" },
{ CSW(PAGE_FAULTS_MIN), "minor-faults", "" },
@@ -78,6 +79,7 @@ static const char *sw_event_names[] = {
"major-faults",
"alignment-faults",
"emulation-faults",
+ "realtime-clock-msecs",
};

#define MAX_ALIASES 8
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a3a871f..a07d96f 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -779,6 +779,10 @@ static int perf_session__process_user_event(struct perf_session *session, union
return ops->build_id(event, session);
case PERF_RECORD_FINISHED_ROUND:
return ops->finished_round(event, session, ops);
+ case PERF_RECORD_REFTIME:
+ if (ops->reftime)
+ return ops->reftime(event, session);
+ return -EINVAL;
default:
return -EINVAL;
}
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 977b3a1..687d2b7 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -77,7 +77,8 @@ struct perf_event_ops {
event_synth_op attr,
event_type,
tracing_data,
- build_id;
+ build_id,
+ reftime;
event_op2 finished_round;
bool ordered_samples;
bool ordering_requires_timestamps;
--
1.7.3.4

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/