Skip to contentSkip to conversation

perf trace: Add duration filter

tip:perf/core tip-bot for Arnaldo Carvalho de Melo 1 participant 1 message Oct 25, 2012 perf events

lore
Share & tools
lore

tip-bot for Arnaldo Carvalho de Melo

author
#0 lore raw
Commit-ID:  ae9ed03579c9745e85a88e80522770df7ae5c9b7
Gitweb:     http://git.kernel.org/tip/ae9ed03579c9745e85a88e80522770df7ae5c9b7
Author:     Arnaldo Carvalho de Melo <[email protected]>
AuthorDate: Mon, 8 Oct 2012 09:56:00 -0300
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Wed, 24 Oct 2012 18:41:04 -0200

perf trace: Add duration filter

Example:

[acme@sandy linux]$ perf trace --duration 0.025 usleep 1

     2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
     3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
     3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1                        ) = 3
     4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0                     ) = 3
     4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0                              ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
     1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0

[acme@sandy linux]$

Cherry picked from tmp.perf/trace2 branch.

Cc David Ahern <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Mike Galbraith <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Paul Mackerras <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Stephane Eranian <[email protected]>
Cc Thomas Gleixner <[email protected]>
Link http://lkml.kernel.org/n/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/Documentation/perf-trace.txt |    3 ++
 tools/perf/builtin-trace.c              |   32 +++++++++++++++++++++++++++---
 2 files changed, 31 insertions(+), 4 deletions(-)
tools/perf/Documentation/perf-trace.txt +3 -0
index 3a2ae37..38d4b68 100644
@@ -48,6 +48,9 @@ comma-separated list with no space: 0,1. Ranges of CPUs are specified with -: 0-
 In per-thread mode with inheritance mode on (default), Events are captured only when
 the thread executes on the designated CPUs. Default is to monitor all CPUs.
 
+--duration:
+	Show only events that had a duration greater than N.M ms.
+
 SEE ALSO
 --------
 linkperf:perf-record[1], linkperf:perf-script[1]
tools/perf/builtin-trace.c +28 -4
index ddb6e37..82ffa6c 100644
@@ -100,8 +100,14 @@ struct trace {
 	struct machine		host;
 	u64			base_time;
 	bool			multiple_threads;
+	double			duration_filter;
 };
 
+static bool trace__filter_duration(struct trace *trace, double t)
+{
+	return t < (trace->duration_filter * NSEC_PER_MSEC);
+}
+
 static size_t trace__fprintf_tstamp(struct trace *trace, u64 tstamp, FILE *fp)
 {
 	double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;

@@ -307,8 +313,10 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 	printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed,  args);
 
 	if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
-		trace__fprintf_entry_head(trace, thread, 1, sample->time, stdout);
-		printf("%-70s\n", ttrace->entry_str);
+		if (!trace->duration_filter) {
+			trace__fprintf_entry_head(trace, thread, 1, sample->time, stdout);
+			printf("%-70s\n", ttrace->entry_str);
+		}
 	} else
 		ttrace->entry_pending = true;
 

@@ -333,8 +341,12 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 
 	ttrace->exit_time = sample->time;
 
-	if (ttrace->entry_time)
+	if (ttrace->entry_time) {
 		duration = sample->time - ttrace->entry_time;
+		if (trace__filter_duration(trace, duration))
+			goto out;
+	} else if (trace->duration_filter)
+		goto out;
 
 	trace__fprintf_entry_head(trace, thread, duration, sample->time, stdout);
 

@@ -358,7 +370,7 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 		printf(") = %d", ret);
 
 	putchar('\n');
-
+out:
 	ttrace->entry_pending = false;
 
 	return 0;

@@ -495,6 +507,15 @@ out:
 	return err;
 }
 
+static int trace__set_duration(const struct option *opt, const char *str,
+			       int unset __maybe_unused)
+{
+	struct trace *trace = opt->value;
+
+	trace->duration_filter = atof(str);
+	return 0;
+}
+
 int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
 {
 	const char * const trace_usage[] = {

@@ -533,6 +554,9 @@ int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
 		     "number of mmap data pages"),
 	OPT_STRING(0, "uid", &trace.opts.target.uid_str, "user",
 		   "user to profile"),
+	OPT_CALLBACK(0, "duration", &trace, "float",
+		     "show only events with duration > N.M ms",
+		     trace__set_duration),
 	OPT_END()
 	};
 	int err;