[PATCH 12/14] perf tools: record elapsed time

From: kan . liang
Date: Wed Nov 23 2016 - 12:45:45 EST


From: Kan Liang <kan.liang@xxxxxxxxx>

Record the elapsed time of perf record, and display it in perf report

Signed-off-by: Kan Liang <kan.liang@xxxxxxxxx>
---
tools/perf/builtin-record.c | 10 ++++++++++
tools/perf/builtin-report.c | 1 +
tools/perf/util/event.h | 3 +++
tools/perf/util/machine.c | 3 +++
tools/perf/util/session.c | 3 +++
5 files changed, 20 insertions(+)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 492058e..ea94e10 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -69,6 +69,7 @@ struct record {
bool switch_output;
unsigned long long samples;
struct write_overhead overhead[MAX_NR_CPUS];
+ u64 elapsed_time;
};

static u64 get_vnsecs(void)
@@ -866,6 +867,12 @@ static void perf_event__synth_overhead(struct record *rec, perf_event__handler_t

(void)process(&rec->tool, &event, NULL, NULL);
}
+
+ event.overhead.type = PERF_USER_ELAPSED_TIME;
+ event.overhead.entry.cpu = -1;
+ event.overhead.entry.nr = 1;
+ event.overhead.entry.time = rec->elapsed_time;
+ (void)process(&rec->tool, &event, NULL, NULL);
}

static int __cmd_record(struct record *rec, int argc, const char **argv)
@@ -1129,6 +1136,7 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
goto out_child;
}

+ rec->elapsed_time = get_nsecs() - rec->elapsed_time;
perf_event__synth_overhead(rec, process_synthesized_event);

if (!quiet)
@@ -1601,6 +1609,8 @@ int cmd_record(int argc, const char **argv, const char *prefix __maybe_unused)
# undef REASON
#endif

+ rec->elapsed_time = get_nsecs();
+
rec->evlist = perf_evlist__new();
if (rec->evlist == NULL)
return -ENOMEM;
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 9c0a424..de2a9b6 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -371,6 +371,7 @@ static int perf_evlist__tty_browse_hists(struct perf_evlist *evlist,

fprintf(stdout, "#\n# Total Lost Samples: %" PRIu64 "\n#\n", evlist->stats.total_lost_samples);
if (symbol_conf.show_overhead) {
+ fprintf(stdout, "# Elapsed time: %" PRIu64 " ns\n", evlist->stats.elapsed_time);
fprintf(stdout, "# Overhead:\n");
for (cpu = 0; cpu < session->header.env.nr_cpus_online; cpu++) {
if (!evlist->stats.total_nmi_overhead[cpu][0])
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 9927cf9..ceb0968 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -275,6 +275,7 @@ enum auxtrace_error_type {
* The total_user_write_overhead tells exactly the overhead to write data in
* perf record.
* The total write# is stored in [0], while the accumulated time is in [1].
+ * The elapsed_time tells the elapsed time of perf record
*/
struct events_stats {
u64 total_period;
@@ -287,6 +288,7 @@ struct events_stats {
u64 total_mux_overhead[MAX_NR_CPUS][2];
u64 total_sb_overhead[MAX_NR_CPUS][2];
u64 total_user_write_overhead[MAX_NR_CPUS][2];
+ u64 elapsed_time;
u32 nr_events[PERF_RECORD_HEADER_MAX];
u32 nr_non_filtered_samples;
u32 nr_lost_warned;
@@ -497,6 +499,7 @@ struct time_conv_event {
u64 time_zero;
};

+#define PERF_USER_ELAPSED_TIME 200 /* above any possible overhead type */
enum perf_user_overhead_event_type { /* above any possible kernel type */
PERF_USER_OVERHEAD_TYPE_START = 100,
PERF_USER_WRITE_OVERHEAD = 100,
diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index ce7a0ea..150071f 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -578,6 +578,9 @@ int machine__process_overhead_event(struct machine *machine __maybe_unused,
event->overhead.entry.nr,
event->overhead.entry.time,
event->overhead.entry.cpu);
+ } else if (event->overhead.type == PERF_USER_ELAPSED_TIME) {
+ dump_printf(" Elapsed time: %llu\n",
+ event->overhead.entry.time);
} else {
dump_printf("\tUNSUPPORT OVERHEAD TYPE 0x%x!\n", event->overhead.type);
}
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a72992b..e84808f 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -1231,6 +1231,9 @@ overhead_stats_update(struct perf_tool *tool,
evlist->stats.total_user_write_overhead[event->overhead.entry.cpu][0] += event->overhead.entry.nr;
evlist->stats.total_user_write_overhead[event->overhead.entry.cpu][1] += event->overhead.entry.time;
break;
+ case PERF_USER_ELAPSED_TIME:
+ evlist->stats.elapsed_time = event->overhead.entry.time;
+ break;
default:
break;
}
--
2.5.5