linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: Ingo Molnar <mingo@kernel.org>
Cc: "Clark Williams" <williams@redhat.com>,
	linux-kernel@vger.kernel.org, linux-perf-users@vger.kernel.org,
	"Arnaldo Carvalho de Melo" <acme@redhat.com>,
	"Adrian Hunter" <adrian.hunter@intel.com>,
	"David Ahern" <dsahern@gmail.com>, "Jiri Olsa" <jolsa@kernel.org>,
	"Milian Wolff" <milian.wolff@kdab.com>,
	"Namhyung Kim" <namhyung@kernel.org>,
	"Rudá Moura" <ruda.moura@gmail.com>,
	"Wang Nan" <wangnan0@huawei.com>
Subject: [PATCH 07/37] perf trace: Introduce --max-events
Date: Thu, 25 Oct 2018 08:10:01 -0300	[thread overview]
Message-ID: <20181025111031.3440-8-acme@kernel.org> (raw)
In-Reply-To: <20181025111031.3440-1-acme@kernel.org>

From: Arnaldo Carvalho de Melo <acme@redhat.com>

Allow stopping tracing after a number of events take place, considering
strace-like syscalls formatting as one event per enter/exit pair or when
in a multi-process tracing session a syscall is interrupted and printed
ending with '...'.

Examples included in the documentation:

Trace the first 4 open, openat or open_by_handle_at syscalls (in the future more syscalls may match here):

  $ perf trace -e open* --max-events 4
  [root@jouet perf]# trace -e open* --max-events 4
  2272.992 ( 0.037 ms): gnome-shell/1370 openat(dfd: CWD, filename: /proc/self/stat) = 31
  2277.481 ( 0.139 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
  3026.398 ( 0.076 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
  4294.665 ( 0.015 ms): sed/15879 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
  $

Trace the first minor page fault when running a workload:

  # perf trace -F min --max-stack=7 --max-events 1 sleep 1
     0.000 ( 0.000 ms): sleep/18006 minfault [__clear_user+0x1a] => 0x5626efa56080 (?k)
                                       __clear_user ([kernel.kallsyms])
                                       load_elf_binary ([kernel.kallsyms])
                                       search_binary_handler ([kernel.kallsyms])
                                       __do_execve_file.isra.33 ([kernel.kallsyms])
                                       __x64_sys_execve ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
  #

Trace the next min page page fault to take place on the first CPU:

  # perf trace -F min --call-graph=dwarf --max-events 1 --cpu 0
     0.000 ( 0.000 ms): Web Content/17136 minfault [js::gc::Chunk::fetchNextDecommittedArena+0x4b] => 0x7fbe6181b000 (?.)
                                       js::gc::FreeSpan::initAsEmpty (inlined)
                                       js::gc::Arena::setAsNotAllocated (inlined)
                                       js::gc::Chunk::fetchNextDecommittedArena (/usr/lib64/firefox/libxul.so)
                                       js::gc::Chunk::allocateArena (/usr/lib64/firefox/libxul.so)
                                       js::gc::GCRuntime::allocateArena (/usr/lib64/firefox/libxul.so)
                                       js::gc::ArenaLists::allocateFromArena (/usr/lib64/firefox/libxul.so)
                                       js::gc::GCRuntime::tryNewTenuredThing<JSString, (js::AllowGC)1> (inlined)
                                       js::AllocateString<JSString, (js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                       js::Allocate<JSThinInlineString, (js::AllowGC)1> (inlined)
                                       JSThinInlineString::new_<(js::AllowGC)1> (inlined)
                                       AllocateInlineString<(js::AllowGC)1, unsigned char> (inlined)
                                       js::ConcatStrings<(js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                       [0x18b26e6bc2bd] (/tmp/perf-17136.map)

Tracing the next four ext4 operations on a specific CPU:

  # perf trace -e ext4:*/call-graph=fp/ --max-events 4 --cpu 3
     0.000 mutt/3849 ext4:ext4_es_lookup_extent_enter:dev 253,2 ino 57277 lblk 0
                                       ext4_es_lookup_extent ([kernel.kallsyms])
                                       read (/usr/lib64/libc-2.26.so)
     0.097 mutt/3849 ext4:ext4_es_lookup_extent_exit:dev 253,2 ino 57277 found 0 [0/0) 0
                                       ext4_es_lookup_extent ([kernel.kallsyms])
                                       read (/usr/lib64/libc-2.26.so)
     0.141 mutt/3849 ext4:ext4_ext_map_blocks_enter:dev 253,2 ino 57277 lblk 0 len 1 flags
                                       ext4_ext_map_blocks ([kernel.kallsyms])
                                       read (/usr/lib64/libc-2.26.so)
     0.184 mutt/3849 ext4:ext4_ext_load_extent:dev 253,2 ino 57277 lblk 1516511 pblk 18446744071750013657
                                       __read_extent_tree_block ([kernel.kallsyms])
                                       __read_extent_tree_block ([kernel.kallsyms])
                                       ext4_find_extent ([kernel.kallsyms])
                                       ext4_ext_map_blocks ([kernel.kallsyms])
                                       ext4_map_blocks ([kernel.kallsyms])
                                       ext4_mpage_readpages ([kernel.kallsyms])
                                       read_pages ([kernel.kallsyms])
                                       __do_page_cache_readahead ([kernel.kallsyms])
                                       ondemand_readahead ([kernel.kallsyms])
                                       generic_file_read_iter ([kernel.kallsyms])
                                       __vfs_read ([kernel.kallsyms])
                                       vfs_read ([kernel.kallsyms])
                                       ksys_read ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64 ([kernel.kallsyms])
                                       read (/usr/lib64/libc-2.26.so)
  #

Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Milian Wolff <milian.wolff@kdab.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Rudá Moura <ruda.moura@gmail.com>
Cc: Wang Nan <wangnan0@huawei.com>
Link: https://lkml.kernel.org/n/tip-sweh107bs7ol5bzls0m4tqdz@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/Documentation/perf-trace.txt | 47 +++++++++++++++++++++++++++++++++
 tools/perf/builtin-trace.c              | 21 +++++++++++++++
 2 files changed, 68 insertions(+)

diff --git a/tools/perf/Documentation/perf-trace.txt b/tools/perf/Documentation/perf-trace.txt
index 115db9e06ecd..0d1a1cd4d328 100644
--- a/tools/perf/Documentation/perf-trace.txt
+++ b/tools/perf/Documentation/perf-trace.txt
@@ -171,6 +171,11 @@ the thread executes on the designated CPUs. Default is to monitor all CPUs.
 --kernel-syscall-graph::
 	 Show the kernel callchains on the syscall exit path.
 
+--max-events=N::
+	Stop after processing N events. Note that strace-like events are considered
+	only at exit time or when a syscall is interrupted, i.e. in those cases this
+	option is equivalent to the number of lines printed.
+
 --max-stack::
         Set the stack depth limit when parsing the callchain, anything
         beyond the specified depth will be ignored. Note that at this point
@@ -238,6 +243,48 @@ Trace syscalls, major and minor pagefaults:
   As you can see, there was major pagefault in python process, from
   CRYPTO_push_info_ routine which faulted somewhere in libcrypto.so.
 
+Trace the first 4 open, openat or open_by_handle_at syscalls (in the future more syscalls may match here):
+
+  $ perf trace -e open* --max-events 4
+  [root@jouet perf]# trace -e open* --max-events 4
+  2272.992 ( 0.037 ms): gnome-shell/1370 openat(dfd: CWD, filename: /proc/self/stat) = 31
+  2277.481 ( 0.139 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
+  3026.398 ( 0.076 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
+  4294.665 ( 0.015 ms): sed/15879 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
+  $
+
+Trace the first minor page fault when running a workload:
+
+  # perf trace -F min --max-stack=7 --max-events 1 sleep 1
+     0.000 ( 0.000 ms): sleep/18006 minfault [__clear_user+0x1a] => 0x5626efa56080 (?k)
+                                       __clear_user ([kernel.kallsyms])
+                                       load_elf_binary ([kernel.kallsyms])
+                                       search_binary_handler ([kernel.kallsyms])
+                                       __do_execve_file.isra.33 ([kernel.kallsyms])
+                                       __x64_sys_execve ([kernel.kallsyms])
+                                       do_syscall_64 ([kernel.kallsyms])
+                                       entry_SYSCALL_64 ([kernel.kallsyms])
+  #
+
+Trace the next min page page fault to take place on the first CPU:
+
+  # perf trace -F min --call-graph=dwarf --max-events 1 --cpu 0
+     0.000 ( 0.000 ms): Web Content/17136 minfault [js::gc::Chunk::fetchNextDecommittedArena+0x4b] => 0x7fbe6181b000 (?.)
+                                       js::gc::FreeSpan::initAsEmpty (inlined)
+                                       js::gc::Arena::setAsNotAllocated (inlined)
+                                       js::gc::Chunk::fetchNextDecommittedArena (/usr/lib64/firefox/libxul.so)
+                                       js::gc::Chunk::allocateArena (/usr/lib64/firefox/libxul.so)
+                                       js::gc::GCRuntime::allocateArena (/usr/lib64/firefox/libxul.so)
+                                       js::gc::ArenaLists::allocateFromArena (/usr/lib64/firefox/libxul.so)
+                                       js::gc::GCRuntime::tryNewTenuredThing<JSString, (js::AllowGC)1> (inlined)
+                                       js::AllocateString<JSString, (js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
+                                       js::Allocate<JSThinInlineString, (js::AllowGC)1> (inlined)
+                                       JSThinInlineString::new_<(js::AllowGC)1> (inlined)
+                                       AllocateInlineString<(js::AllowGC)1, unsigned char> (inlined)
+                                       js::ConcatStrings<(js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
+                                       [0x18b26e6bc2bd] (/tmp/perf-17136.map)
+  #
+
 SEE ALSO
 --------
 linkperf:perf-record[1], linkperf:perf-script[1]
diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 90289f31dd87..74638034861c 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -89,6 +89,8 @@ struct trace {
 	u64			base_time;
 	FILE			*output;
 	unsigned long		nr_events;
+	unsigned long		nr_events_printed;
+	unsigned long		max_events;
 	struct strlist		*ev_qualifier;
 	struct {
 		size_t		nr;
@@ -1664,6 +1666,8 @@ static int trace__printf_interrupted_entry(struct trace *trace)
 	printed += fprintf(trace->output, "%-70s) ...\n", ttrace->entry_str);
 	ttrace->entry_pending = false;
 
+	++trace->nr_events_printed;
+
 	return printed;
 }
 
@@ -1940,6 +1944,13 @@ errno_print: {
 
 	fputc('\n', trace->output);
 
+	/*
+	 * We only consider an 'event' for the sake of --max-events a non-filtered
+	 * sys_enter + sys_exit and other tracepoint events.
+	 */
+	if (++trace->nr_events_printed == trace->max_events && trace->max_events != ULONG_MAX)
+		interrupted = true;
+
 	if (callchain_ret > 0)
 		trace__fprintf_callchain(trace, sample);
 	else if (callchain_ret < 0)
@@ -2072,6 +2083,7 @@ static void bpf_output__fprintf(struct trace *trace,
 {
 	binary__fprintf(sample->raw_data, sample->raw_size, 8,
 			bpf_output__printer, NULL, trace->output);
+	++trace->nr_events_printed;
 }
 
 static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
@@ -2127,6 +2139,7 @@ static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
 			event_format__fprintf(evsel->tp_format, sample->cpu,
 					      sample->raw_data, sample->raw_size,
 					      trace->output);
+			++trace->nr_events_printed;
 		}
 	}
 
@@ -2225,6 +2238,8 @@ static int trace__pgfault(struct trace *trace,
 		trace__fprintf_callchain(trace, sample);
 	else if (callchain_ret < 0)
 		pr_err("Problem processing %s callchain, skipping...\n", perf_evsel__name(evsel));
+
+	++trace->nr_events_printed;
 out:
 	err = 0;
 out_put:
@@ -2402,6 +2417,9 @@ static void trace__handle_event(struct trace *trace, union perf_event *event, st
 		tracepoint_handler handler = evsel->handler;
 		handler(trace, evsel, event, sample);
 	}
+
+	if (trace->nr_events_printed >= trace->max_events && trace->max_events != ULONG_MAX)
+		interrupted = true;
 }
 
 static int trace__add_syscall_newtp(struct trace *trace)
@@ -3249,6 +3267,7 @@ int cmd_trace(int argc, const char **argv)
 		.trace_syscalls = false,
 		.kernel_syscallchains = false,
 		.max_stack = UINT_MAX,
+		.max_events = ULONG_MAX,
 	};
 	const char *output_name = NULL;
 	const struct option trace_options[] = {
@@ -3301,6 +3320,8 @@ int cmd_trace(int argc, const char **argv)
 		     &record_parse_callchain_opt),
 	OPT_BOOLEAN(0, "kernel-syscall-graph", &trace.kernel_syscallchains,
 		    "Show the kernel callchains on the syscall exit path"),
+	OPT_ULONG(0, "max-events", &trace.max_events,
+		"Set the maximum number of events to print, exit after that is reached. "),
 	OPT_UINTEGER(0, "min-stack", &trace.min_stack,
 		     "Set the minimum stack depth when parsing the callchain, "
 		     "anything below the specified depth will be ignored."),
-- 
2.14.4


  parent reply	other threads:[~2018-10-25 11:11 UTC|newest]

Thread overview: 39+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-10-25 11:09 [PATCH 00/37] perf/core improvements and fixes Arnaldo Carvalho de Melo
2018-10-25 11:09 ` [PATCH 01/37] perf record: Encode -k clockid frequency into Perf trace Arnaldo Carvalho de Melo
2018-10-25 11:09 ` [PATCH 02/37] perf annotate: Add Sparc support Arnaldo Carvalho de Melo
2018-10-25 11:09 ` [PATCH 03/37] perf jitdump: " Arnaldo Carvalho de Melo
2018-10-25 11:09 ` [PATCH 04/37] perf symbols: Set PLT entry/header sizes properly on Sparc Arnaldo Carvalho de Melo
2018-10-25 11:09 ` [PATCH 05/37] perf arm64: Fix generate system call table failed with /tmp mounted with noexec Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 06/37] tools lib subcmd: Introduce OPTION_ULONG Arnaldo Carvalho de Melo
2018-10-25 11:10 ` Arnaldo Carvalho de Melo [this message]
2018-10-25 11:10 ` [PATCH 08/37] perf evsel: Introduce per event max_events property Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 09/37] perf evsel: Mark a evsel as disabled when asking the kernel do disable it Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 10/37] perf trace: Drop addr_location refcounts Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 11/37] perf trace: Drop thread refcount in trace__event_handler() Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 12/37] perf stat: Poll for monitored tasks being alive Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 13/37] perf script: Allow extended console debug output Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 14/37] perf script: Flush output stream after events in verbose mode Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 15/37] perf trace: Introduce per-event maximum number of events property Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 16/37] perf scripts python: call-graph-from-sql.py: Use SPDX license identifier Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 17/37] perf scripts python: call-graph-from-sql.py: Provide better default column sizes Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 18/37] perf scripts python: call-graph-from-sql.py: Set a minimum window size Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 19/37] perf scripts python: call-graph-from-sql.py: Change icon Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 20/37] perf scripts python: call-graph-from-sql.py: Make a "Main" function Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 21/37] perf scripts python: call-graph-from-sql.py: Separate the database details into a class Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 22/37] perf scripts python: call-graph-from-sql.py: Add a class for global data Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 23/37] perf scripts python: call-graph-from-sql.py: Remove use of setObjectName() Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 24/37] perf scripts python: call-graph-from-sql.py: Factor out CallGraphModel from TreeModel Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 25/37] perf scripts python: call-graph-from-sql.py: Add data helper functions Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 26/37] perf scripts python: call-graph-from-sql.py: Refactor TreeItem class Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 27/37] perf scripts python: call-graph-from-sql.py: Rename to exported-sql-viewer.py Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 28/37] perf scripts python: exported-sql-viewer.py: Add support for multiple sub-windows Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 29/37] perf scripts python: exported-sql-viewer.py: Add ability to find symbols in the call-graph Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 30/37] perf scripts python: exported-sql-viewer.py: Add ability to shrink / enlarge font Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 31/37] perf scripts python: exported-sql-viewer.py: Add ability to display all the database tables Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 32/37] perf scripts python: exported-sql-viewer.py: Add All branches report Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 33/37] perf script: Add --insn-trace for instruction decoding Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 34/37] perf script: Make itrace script default to all calls Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 35/37] tools script: Add --call-trace and --call-ret-trace Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 36/37] perf script: Implement --graph-function Arnaldo Carvalho de Melo
2018-10-25 11:10 ` [PATCH 37/37] perf script: Support total cycles count Arnaldo Carvalho de Melo
2018-10-26  7:25 ` [PATCH 00/37] perf/core improvements and fixes Ingo Molnar

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20181025111031.3440-8-acme@kernel.org \
    --to=acme@kernel.org \
    --cc=acme@redhat.com \
    --cc=adrian.hunter@intel.com \
    --cc=dsahern@gmail.com \
    --cc=jolsa@kernel.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-perf-users@vger.kernel.org \
    --cc=milian.wolff@kdab.com \
    --cc=mingo@kernel.org \
    --cc=namhyung@kernel.org \
    --cc=ruda.moura@gmail.com \
    --cc=wangnan0@huawei.com \
    --cc=williams@redhat.com \
    --subject='Re: [PATCH 07/37] perf trace: Introduce --max-events' \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).