[RFC PATCH v1 37/37] perf test/evlist-open-close: add detailed output mode
From: Riccardo Mancini
Date: Sat Aug 21 2021 - 05:22:50 EST
This patch adds a detailed output mode in the perf-test
evlist-open-close. In this output mode, the time taken by each single
evlist function is computed.
Normal mode:
$ sudo ./perf bench internals evlist-open-close
Number of workers: 1
Number of cpus: 4
Number of threads: 1
Number of events: 1 (4 fds)
Number of iterations: 100
Average open-close took: 1199.300 usec (+- 289.699 usec)
Detailed mode:
$ sudo ./perf bench internals evlist-open-close -d
Number of workers: 1
Number of cpus: 4
Number of threads: 1
Number of events: 1 (4 fds)
Number of iterations: 100
Average open-close took: 1199.300 usec (+- 289.699 usec)
init took: 0.000 usec (+- 0.000 usec)
open took: 25.600 usec (+- 1.778 usec)
mmap took: 532.000 usec (+- 58.133 usec)
enable took: 337.300 usec (+- 194.160 usec)
disable took: 181.700 usec (+- 85.307 usec)
munmap took: 22.100 usec (+- 4.045 usec)
close took: 100.300 usec (+- 21.329 usec)
fini took: 0.200 usec (+- 0.133 usec)
* init and fini represent the time taken before and after the evlist
operations (in this case the workqueue setup and teardown operations)
Signed-off-by: Riccardo Mancini <rickyman7@xxxxxxxxx>
---
tools/perf/bench/evlist-open-close.c | 63 ++++++++++++++++++++++++++--
1 file changed, 60 insertions(+), 3 deletions(-)
diff --git a/tools/perf/bench/evlist-open-close.c b/tools/perf/bench/evlist-open-close.c
index 00d0aef564f80d44..8ba2799c66cafb3e 100644
--- a/tools/perf/bench/evlist-open-close.c
+++ b/tools/perf/bench/evlist-open-close.c
@@ -25,12 +25,18 @@
static int iterations = 100;
static int nr_events = 1;
static const char *event_string = "dummy";
+static bool detail;
static inline u64 timeval2usec(struct timeval *tv)
{
return tv->tv_sec * USEC_PER_SEC + tv->tv_usec;
}
+struct timers {
+ struct timeval start, end, diff;
+ struct stats init, open, mmap, enable, disable, munmap, close, fini;
+};
+
static struct record_opts opts = {
.sample_time = true,
.mmap_pages = UINT_MAX,
@@ -60,6 +66,7 @@ static const struct option options[] = {
OPT_STRING('u', "uid", &opts.target.uid_str, "user", "user to profile"),
OPT_BOOLEAN(0, "per-thread", &opts.target.per_thread, "use per-thread mmaps"),
OPT_UINTEGER_OPTARG('j', "threads", &opts.nr_threads, UINT_MAX, "Number of threads to use"),
+ OPT_BOOLEAN('d', "detail", &detail, "compute time taken by single functions"),
OPT_END()
};
@@ -113,11 +120,28 @@ static struct evlist *bench__create_evlist(char *evstr)
return NULL;
}
-static int bench__do_evlist_open_close(struct evlist *evlist)
+#define START_TIMER(timers) do { \
+ if (detail) { \
+ gettimeofday(&(timers)->start, NULL); \
+ } \
+} while (0)
+
+#define RECORD_TIMER(timers, field) do { \
+ if (detail) { \
+ gettimeofday(&(timers)->end, NULL); \
+ timersub(&(timers)->end, &(timers)->start, &(timers)->diff); \
+ update_stats(&(timers)->field, timeval2usec(&(timers)->diff)); \
+ (timers)->start = (timers)->end; \
+ } \
+} while (0)
+
+static int bench__do_evlist_open_close(struct evlist *evlist, struct timers *timers)
{
char sbuf[WORKQUEUE_STRERR_BUFSIZE];
int err = -1, ret;
+ START_TIMER(timers);
+
if (opts.nr_threads > 1) {
err = setup_global_workqueue(opts.nr_threads);
if (err) {
@@ -130,23 +154,30 @@ static int bench__do_evlist_open_close(struct evlist *evlist)
perf_set_multithreaded();
}
+ RECORD_TIMER(timers, init);
err = evlist__open(evlist);
if (err < 0) {
pr_err("evlist__open: %s\n", str_error_r(errno, sbuf, sizeof(sbuf)));
goto out;
}
+ RECORD_TIMER(timers, open);
err = evlist__mmap(evlist, opts.mmap_pages);
if (err < 0) {
pr_err("evlist__mmap: %s\n", str_error_r(errno, sbuf, sizeof(sbuf)));
goto out;
}
+ RECORD_TIMER(timers, mmap);
evlist__enable(evlist);
+ RECORD_TIMER(timers, enable);
evlist__disable(evlist);
+ RECORD_TIMER(timers, disable);
evlist__munmap(evlist);
+ RECORD_TIMER(timers, munmap);
evlist__close(evlist);
+ RECORD_TIMER(timers, close);
out:
if (opts.nr_threads > 1) {
@@ -159,10 +190,15 @@ static int bench__do_evlist_open_close(struct evlist *evlist)
perf_set_singlethreaded();
}
+ RECORD_TIMER(timers, fini);
return err;
}
+#define PRINT_TIMER(timers, field) \
+ printf("%20s took: %12.3f usec (+- %12.3f usec)\n", #field, \
+ avg_stats(&(timers)->field), stddev_stats(&(timers)->field))
+
static int bench_evlist_open_close__run(char *evstr)
{
// used to print statistics only
@@ -172,10 +208,21 @@ static int bench_evlist_open_close__run(char *evstr)
struct stats time_stats;
u64 runtime_us;
int i, err;
+ struct timers timers;
if (!evlist)
return -ENOMEM;
+ init_stats(&time_stats);
+ init_stats(&timers.init);
+ init_stats(&timers.open);
+ init_stats(&timers.mmap);
+ init_stats(&timers.enable);
+ init_stats(&timers.disable);
+ init_stats(&timers.munmap);
+ init_stats(&timers.close);
+ init_stats(&timers.fini);
+
init_stats(&time_stats);
printf(" Number of workers:\t%u\n", opts.nr_threads);
@@ -194,7 +241,7 @@ static int bench_evlist_open_close__run(char *evstr)
return -ENOMEM;
gettimeofday(&start, NULL);
- err = bench__do_evlist_open_close(evlist);
+ err = bench__do_evlist_open_close(evlist, &timers);
if (err) {
evlist__delete(evlist);
return err;
@@ -211,7 +258,17 @@ static int bench_evlist_open_close__run(char *evstr)
time_average = avg_stats(&time_stats);
time_stddev = stddev_stats(&time_stats);
- printf(" Average open-close took: %.3f usec (+- %.3f usec)\n", time_average, time_stddev);
+ printf(" Average open-close took: %12.3f usec (+- %12.3f usec)\n", time_average, time_stddev);
+ if (detail) {
+ PRINT_TIMER(&timers, init);
+ PRINT_TIMER(&timers, open);
+ PRINT_TIMER(&timers, mmap);
+ PRINT_TIMER(&timers, enable);
+ PRINT_TIMER(&timers, disable);
+ PRINT_TIMER(&timers, munmap);
+ PRINT_TIMER(&timers, close);
+ PRINT_TIMER(&timers, fini);
+ }
return 0;
}
--
2.31.1