Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1508717 > unrolled thread

[PATCH 0/2] perf: measure page fault duration in perf trace

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/2] perf: measure page fault duration in perf trace Alexis Berlemont <alexis.berlemont@gmail.com> - 2016-10-26 02:00 +0200
    [PATCH 2/2] perf: add page fault duration measures in perf trace Alexis Berlemont <alexis.berlemont@gmail.com> - 2016-10-26 02:00 +0200
    Re: [PATCH 0/2] perf: measure page fault duration in perf trace Peter Zijlstra <peterz@infradead.org> - 2016-10-26 10:50 +0200
      Re: [PATCH 0/2] perf: measure page fault duration in perf trace Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-10-26 20:50 +0200

#1508717 — [PATCH 0/2] perf: measure page fault duration in perf trace

Hi,

Here are 2 small patches which try to fulfill a point in the perf todo
list:

* Forward port the page fault tracepoints and use it in 'trace'.
http://git.kernel.org/?p=linux/kernel/git/acme/linux.git;a=commitdiff;h=d53b11976093b6d8afeb8181db53aaffc754920d;hp=32ba4abf60ae1b710d22a75725491815de649bc5

There are some questionable points:

* With luck I think I found the patch related with the todo item (the
  link in the todo wiki page is broken); I hope I am not wrong...
* In the patch mentioned above, I found only changes related with
  tracepoints creations and calls; the tracepoints were declared
  generic (in include/trace/events/kmem.h) but were only called in x86
  (arch/x86/mm/fault.c); as in x86, the tracepoint
  "mm_pagefault_start" looks fairly like "page_fault_user" and
  "page_fault_kernel", I decided to only create one x86-specific
  tracepoint: "page_fault_exit"; maybe, you would prefer declaring
  generic tracepoints;
* No option has been added for activating page-fault duration
  calculation: if the needed tracepoints are available, durations will
  be printed; maybe, that was not what you were looking for.

The patches were generated against tip/perf/core.

Alexis.

Alexis Berlemont (2):
  perf, x86-mm: Add exit-fault tracing
  perf: add page fault duration measures in perf trace

 arch/x86/include/asm/trace/exceptions.h |  21 +++
 arch/x86/mm/fault.c                     |   1 +
 tools/perf/builtin-trace.c              | 225 ++++++++++++++++++++++++++++----
 3 files changed, 221 insertions(+), 26 deletions(-)

-- 
2.10.1

[toc] | [next] | [standalone]

#1508720 — [PATCH 2/2] perf: add page fault duration measures in perf trace

Signed-off-by: Alexis Berlemont <alexis.berlemont@gmail.com>
---
 tools/perf/Documentation/perf-trace.txt |   4 +-
 tools/perf/builtin-trace.c              | 225 ++++++++++++++++++++++++++++----
 2 files changed, 202 insertions(+), 27 deletions(-)

diff --git a/tools/perf/Documentation/perf-trace.txt b/tools/perf/Documentation/perf-trace.txt
index 781b019..53c103c 100644
--- a/tools/perf/Documentation/perf-trace.txt
+++ b/tools/perf/Documentation/perf-trace.txt
@@ -117,7 +117,9 @@ the thread executes on the designated CPUs. Default is to monitor all CPUs.
 -F=[all|min|maj]::
 --pf=[all|min|maj]::
 	Trace pagefaults. Optionally, you can specify whether you want minor,
-	major or all pagefaults. Default value is maj.
+	major or all pagefaults. Default value is maj. Durations of
+	page-fault handling will be printed if possible (need for some
+	architecture-dependent tracepoints).
 
 --syscalls::
 	Trace system calls. This options is enabled by default.
diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 5f45166..100c28a 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -861,6 +861,8 @@ struct thread_trace {
 	} paths;
 
 	struct intlist *syscall_stats;
+	u64	       pgfault_entry_time;
+	char           *pgfault_entry_str;
 };
 
 static struct thread_trace *thread_trace__new(void)
@@ -1797,21 +1799,56 @@ static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
 	return 0;
 }
 
-static void print_location(FILE *f, struct perf_sample *sample,
-			   struct addr_location *al,
-			   bool print_dso, bool print_sym)
+static int trace__pgfault_enter(struct trace *trace,
+				struct perf_evsel *evsel __maybe_unused,
+				union perf_event *event __maybe_unused,
+				struct perf_sample *sample)
 {
+	struct thread *thread;
+	struct thread_trace *ttrace;
+	int err = -1;
+
+	thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
+	if (!thread)
+		goto out;
+
+	ttrace = thread__trace(thread, trace->output);
+	if (ttrace == NULL)
+		goto out_put;
+
+	ttrace->pgfault_entry_time = sample->time;
+
+out:
+	err = 0;
+out_put:
+	thread__put(thread);
+	return err;
+}
+
+static size_t scnprintf_location(char *bf, size_t size,
+				struct perf_sample *sample,
+				struct addr_location *al,
+				bool print_dso, bool print_sym)
+{
+	size_t printed = 0;
 
 	if ((verbose || print_dso) && al->map)
-		fprintf(f, "%s@", al->map->dso->long_name);
+		printed += scnprintf(bf + printed,
+				size - printed, "%s@", al->map->dso->long_name);
 
 	if ((verbose || print_sym) && al->sym)
-		fprintf(f, "%s+0x%" PRIx64, al->sym->name,
-			al->addr - al->sym->start);
+		printed += scnprintf(bf + printed,
+				size - printed,
+				"%s+0x%" PRIx64, al->sym->name,
+				al->addr - al->sym->start);
 	else if (al->map)
-		fprintf(f, "0x%" PRIx64, al->addr);
+		printed += scnprintf(bf + printed,
+				size - printed, "0x%" PRIx64, al->addr);
 	else
-		fprintf(f, "0x%" PRIx64, sample->addr);
+		printed += scnprintf(bf + printed,
+				size - printed, "0x%" PRIx64, sample->addr);
+
+	return printed;
 }
 
 static int trace__pgfault(struct trace *trace,
@@ -1823,13 +1860,22 @@ static int trace__pgfault(struct trace *trace,
 	struct addr_location al;
 	char map_type = 'd';
 	struct thread_trace *ttrace;
+	size_t printed = 0;
 	int err = -1;
 	int callchain_ret = 0;
 
 	thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
+	if (!thread)
+		goto out;
 
-	if (sample->callchain) {
-		callchain_ret = trace__resolve_callchain(trace, evsel, sample, &callchain_cursor);
+	ttrace = thread__trace(thread, trace->output);
+	if (ttrace == NULL)
+		goto out_put;
+
+	if (!ttrace->pgfault_entry_time && sample->callchain) {
+		callchain_ret =
+			trace__resolve_callchain(trace, evsel,
+						sample, &callchain_cursor);
 		if (callchain_ret == 0) {
 			if (callchain_cursor.nr < trace->min_stack)
 				goto out_put;
@@ -1837,10 +1883,6 @@ static int trace__pgfault(struct trace *trace,
 		}
 	}
 
-	ttrace = thread__trace(thread, trace->output);
-	if (ttrace == NULL)
-		goto out_put;
-
 	if (evsel->attr.config == PERF_COUNT_SW_PAGE_FAULTS_MAJ)
 		ttrace->pfmaj++;
 	else
@@ -1849,18 +1891,27 @@ static int trace__pgfault(struct trace *trace,
 	if (trace->summary_only)
 		goto out;
 
+	if (ttrace->pgfault_entry_str == NULL) {
+		ttrace->pgfault_entry_str = malloc(trace__entry_str_size);
+		if (!ttrace->pgfault_entry_str)
+			goto out_put;
+		ttrace->pgfault_entry_str[0] = '\0';
+	}
+
 	thread__find_addr_location(thread, sample->cpumode, MAP__FUNCTION,
 			      sample->ip, &al);
 
-	trace__fprintf_entry_head(trace, thread, 0, sample->time, trace->output);
-
-	fprintf(trace->output, "%sfault [",
-		evsel->attr.config == PERF_COUNT_SW_PAGE_FAULTS_MAJ ?
-		"maj" : "min");
+	printed += scnprintf(ttrace->pgfault_entry_str + printed,
+			trace__entry_str_size - printed, "%sfault [",
+			evsel->attr.config == PERF_COUNT_SW_PAGE_FAULTS_MAJ ?
+			"maj" : "min");
 
-	print_location(trace->output, sample, &al, false, true);
+	printed += scnprintf_location(ttrace->pgfault_entry_str + printed,
+				trace__entry_str_size - printed,
+				sample, &al, false, true);
 
-	fprintf(trace->output, "] => ");
+	printed += scnprintf(ttrace->pgfault_entry_str + printed,
+			trace__entry_str_size - printed, "] => ");
 
 	thread__find_addr_location(thread, sample->cpumode, MAP__VARIABLE,
 				   sample->addr, &al);
@@ -1875,14 +1926,97 @@ static int trace__pgfault(struct trace *trace,
 			map_type = '?';
 	}
 
-	print_location(trace->output, sample, &al, true, false);
+	printed += scnprintf_location(ttrace->pgfault_entry_str + printed,
+				trace__entry_str_size - printed,
+				sample, &al, true, false);
 
-	fprintf(trace->output, " (%c%c)\n", map_type, al.level);
+	printed += scnprintf(ttrace->pgfault_entry_str + printed,
+			trace__entry_str_size - printed,
+			" (%c%c)", map_type, al.level);
+
+	if (!ttrace->pgfault_entry_time) {
+		trace__fprintf_entry_head(trace, thread,
+					0, sample->time, trace->output);
+		fprintf(trace->output, "%-70s\n", ttrace->pgfault_entry_str);
+
+		if (callchain_ret > 0)
+			trace__fprintf_callchain(trace, sample);
+		else if (callchain_ret < 0)
+			pr_err("Problem processing %s callchain, skipping...\n",
+				perf_evsel__name(evsel));
+	}
+
+out:
+	err = 0;
+out_put:
+	thread__put(thread);
+	return err;
+}
+
+static int trace__pgfault_exit(struct trace *trace, struct perf_evsel *evsel,
+			      union perf_event *event __maybe_unused,
+			      struct perf_sample *sample)
+{
+	struct thread *thread;
+	struct thread_trace *ttrace;
+	u64 duration = 0;
+	int err = -1, callchain_ret = 0;
+
+	thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
+
+	ttrace = thread__priv(thread);
+	if (!ttrace)
+		goto out_put;
+
+	if (!ttrace->pgfault_entry_time)
+		goto out;
+
+	/*
+	 * The check below is necessary for a specific case: it is
+	 * possible to enable only major (or minor) page faults
+	 * software events but it is impossible to filter page-fault
+	 * related tracepoints according to the major / minor
+	 * characteristic.
+	 */
+
+	if (!ttrace->pgfault_entry_str ||
+		strlen(ttrace->pgfault_entry_str) == 0)
+		goto out;
+
+	if (sample->callchain) {
+		callchain_ret =
+			trace__resolve_callchain(trace, evsel,
+						sample, &callchain_cursor);
+		if (callchain_ret == 0) {
+			if (callchain_cursor.nr < trace->min_stack)
+				goto out;
+			callchain_ret = 1;
+		}
+	}
+
+	if (ttrace->pgfault_entry_time) {
+		duration = sample->time - ttrace->pgfault_entry_time;
+		if (trace__filter_duration(trace, duration))
+			goto out;
+	}
+
+	trace__fprintf_entry_head(trace, thread,
+				duration, sample->time, trace->output);
+
+	fprintf(trace->output, "%-70s\n", ttrace->pgfault_entry_str);
+
+	/*
+	 * Once the string is printed; clear it just in case the next
+	 * software events is filtered (because of major / minor.
+	 */
+	ttrace->pgfault_entry_str[0] = '\0';
 
 	if (callchain_ret > 0)
 		trace__fprintf_callchain(trace, sample);
 	else if (callchain_ret < 0)
-		pr_err("Problem processing %s callchain, skipping...\n", perf_evsel__name(evsel));
+		pr_err("Problem processing %s callchain, skipping...\n",
+			perf_evsel__name(evsel));
+
 out:
 	err = 0;
 out_put:
@@ -2062,6 +2196,37 @@ static struct perf_evsel *perf_evsel__new_pgfault(u64 config)
 	return evsel;
 }
 
+static int trace__add_pgfault_newtp(struct trace *trace)
+{
+	int err = -1;
+	struct perf_evlist *evlist = trace->evlist;
+
+	/*
+	 * The tracepoints exceptions::page_fault_* are not available
+	 * on all architecture.; so, we consider it is not an error if
+	 * the 1st one's initialization is KO...
+	 */
+	err = perf_evlist__add_newtp(evlist, "exceptions",
+				"page_fault_exit", trace__pgfault_exit);
+	if (err < 0)
+		return 0;
+
+	/*
+	 * ...however, if the 2nd or the 3rd init is KO; there is
+	 * definitely something wrong not related with the absence of
+	 * tracepoints
+	 */
+	err = perf_evlist__add_newtp(evlist, "exceptions",
+				"page_fault_kernel", trace__pgfault_enter);
+	if (err < 0)
+		return -1;
+
+	err = perf_evlist__add_newtp(evlist, "exceptions",
+				"page_fault_user", trace__pgfault_enter);
+
+	return err;
+}
+
 static void trace__handle_event(struct trace *trace, union perf_event *event, struct perf_sample *sample)
 {
 	const u32 type = event->header.type;
@@ -2193,9 +2358,12 @@ static int trace__run(struct trace *trace, int argc, const char **argv)
 		perf_evlist__add(evlist, pgfault_min);
 	}
 
+	if (trace->trace_pgfaults && trace__add_pgfault_newtp(trace))
+		goto out_error_pgfault_tp;
+
 	if (trace->sched &&
-	    perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
-				   trace__sched_stat_runtime))
+		perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
+				trace__sched_stat_runtime))
 		goto out_error_sched_stat_runtime;
 
 	err = perf_evlist__create_maps(evlist, &trace->opts.target);
@@ -2399,6 +2567,11 @@ static int trace__run(struct trace *trace, int argc, const char **argv)
 	tracing_path__strerror_open_tp(errno, errbuf, sizeof(errbuf), "raw_syscalls", "sys_(enter|exit)");
 	goto out_error;
 
+out_error_pgfault_tp:
+	tracing_path__strerror_open_tp(errno, errbuf, sizeof(errbuf),
+				"exceptions", "page_fault_(kernel|user)");
+	goto out_error;
+
 out_error_mmap:
 	perf_evlist__strerror_mmap(evlist, errno, errbuf, sizeof(errbuf));
 	goto out_error;
-- 
2.10.1

[toc] | [prev] | [next] | [standalone]

#1508939

On Wed, Oct 26, 2016 at 01:51:58AM +0200, Alexis Berlemont wrote:
> Hi,
> 
> Here are 2 small patches which try to fulfill a point in the perf todo
> list:

There's a todo list?

> * Forward port the page fault tracepoints and use it in 'trace'.
> http://git.kernel.org/?p=linux/kernel/git/acme/linux.git;a=commitdiff;h=d53b11976093b6d8afeb8181db53aaffc754920d;hp=32ba4abf60ae1b710d22a75725491815de649bc5

dead link

[toc] | [prev] | [next] | [standalone]

#1509698

Em Wed, Oct 26, 2016 at 10:46:18AM +0200, Peter Zijlstra escreveu:
> On Wed, Oct 26, 2016 at 01:51:58AM +0200, Alexis Berlemont wrote:
> > Hi,
> > 
> > Here are 2 small patches which try to fulfill a point in the perf todo
> > list:
> 
> There's a todo list?

https://perf.wiki.kernel.org/index.php/Todo
 
> > * Forward port the page fault tracepoints and use it in 'trace'.
> > http://git.kernel.org/?p=linux/kernel/git/acme/linux.git;a=commitdiff;h=d53b11976093b6d8afeb8181db53aaffc754920d;hp=32ba4abf60ae1b710d22a75725491815de649bc5
> 
> dead link

I guess this is the one:

http://git.kernel.org/cgit/linux/kernel/git/acme/linux.git/commit/?id=eea86c6e06c241667c96c8e87e43c0870e1d6285

author	Frederic Weisbecker <fweisbec@gmail.com>	2010-11-12 04:35:06 (GMT)
committer	Ingo Molnar <mingo@elte.hu>	2011-05-07 16:10:43 (GMT)
commit	eea86c6e06c241667c96c8e87e43c0870e1d6285 (patch)
tree	b00ce7ef9a6219f4df6b0e1ffe453d2d5baf3593
parent	57d524154ffe99d27fb55e0e30ddbad9f4c35806 (diff)
perf, mm: Add fault tracing
Part of that are two modified patches from Jiri Olsa who added the fault
tracepoints. I had to split them in two tracepoints so that we get the
faults
handling duration.

Originally-from: Frederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

--------------------

After that entry was added to the todo we got --pf, but no duration:

[root@jouet ~]# perf trace --pf maj --no-syscalls
     0.000 ( 0.000 ms): perf/20412 majfault [__memcmp_sse4_1+0xbc6] => 0x7f1e0010c000 (?.)
     1.156 ( 0.000 ms): perf/20412 majfault [__memcmp_sse4_1+0xbc6] => /usr/bin/mv@0x0 (d.)
    56.907 ( 0.000 ms): perf/20412 majfault [__memcpy_avx_unaligned+0x1e7] => /usr/bin/mv@0x207a0 (d.)
    57.683 ( 0.000 ms): perf/20412 majfault [__memcmp_sse4_1+0xbc6] => /usr/lib/debug/usr/bin/mv.debug@0x0 (d.)
    60.916 ( 0.000 ms): perf/20412 majfault [__memcpy_avx_unaligned+0x2b6] => /usr/lib/debug/usr/bin/mv.debug@0x6ace0 (d.)
18446744073708.766 ( 0.000 ms): systemd-journa/578 majfault [0x14972] => 0x7f25bdd9ebd0 (?.)
    70.193 ( 0.000 ms): perf/20412 majfault [__memcmp_sse4_1+0xbc6] => /usr/lib/debug/usr/lib/systemd/systemd-journald.debug@0x0 (d.)
    71.176 ( 0.000 ms): perf/20412 majfault [__memcpy_avx_unaligned+0x2b6] => /usr/lib/debug/usr/lib/systemd/systemd-journald.debug@0x1221e0 (d.)
^C[root@jouet ~]# trace -h --pf

 Usage: perf trace [<options>] [<command>]
    or: perf trace [<options>] -- <command> [<options>]
    or: perf trace record [<options>] [<command>]
    or: perf trace record [<options>] -- <command> [<options>]

    -F, --pf <all|maj|min>
                          Trace pagefaults

[root@jouet ~]#

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web