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

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
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <1479894292-16277-13-git-send-email-kan.liang@intel.com>
Date:   Wed, 23 Nov 2016 04:44:50 -0500
From:   kan.liang@...el.com
To:     peterz@...radead.org, mingo@...hat.com, acme@...nel.org,
        linux-kernel@...r.kernel.org
Cc:     alexander.shishkin@...ux.intel.com, tglx@...utronix.de,
        namhyung@...nel.org, jolsa@...nel.org, adrian.hunter@...el.com,
        wangnan0@...wei.com, mark.rutland@....com, andi@...stfloor.org,
        Kan Liang <kan.liang@...el.com>
Subject: [PATCH 12/14] perf tools: record elapsed time

From: Kan Liang <kan.liang@...el.com>

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

Signed-off-by: Kan Liang <kan.liang@...el.com>
---
 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