perf sched timehist: Mark schedule function in callchains

Commit-ID:  2d9bbf6eb3825739efa9e91c256ce7ead60d8367
Gitweb:     http://git.kernel.org/tip/2d9bbf6eb3825739efa9e91c256ce7ead60d8367
Author:     Namhyung Kim <[email protected]>
AuthorDate: Thu, 24 Nov 2016 10:11:13 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Fri, 25 Nov 2016 10:49:38 -0300

perf callchain: Add option to skip ignore symbol when printing callchains

For tracepoint events, callchains always contain certain functions. Sometimes it'd be better to skip those functions as they have no value.

---
 tools/perf/builtin-sched.c      | 3 ++-
 tools/perf/util/evsel.h         | 1 +
 tools/perf/util/evsel_fprintf.c | 7 ++++++-
 3 files changed, 9 insertions(+), 2 deletions(-)

index 829468d..43fcc13 100644
@@ -1876,7 +1876,8 @@ static void timehist_print_sample(struct perf_sched *sched,
 
 	sample__fprintf_sym(sample, al, 0,
 			    EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
-			    EVSEL__PRINT_CALLCHAIN_ARROW,
+			    EVSEL__PRINT_CALLCHAIN_ARROW |
+			    EVSEL__PRINT_SKIP_IGNORED,
 			    &callchain_cursor, stdout);
 
 out:

index 27fa3a3..6abb89c 100644
@@ -392,6 +392,7 @@ int perf_evsel__fprintf(struct perf_evsel *evsel,
 #define EVSEL__PRINT_SRCLINE		(1<<5)
 #define EVSEL__PRINT_UNKNOWN_AS_ADDR	(1<<6)
 #define EVSEL__PRINT_CALLCHAIN_ARROW	(1<<7)
+#define EVSEL__PRINT_SKIP_IGNORED	(1<<8)
 
 struct callchain_cursor;
 

index 53bb614..5a6f522 100644
@@ -109,6 +109,7 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
 	int print_srcline = print_opts & EVSEL__PRINT_SRCLINE;
 	int print_unknown_as_addr = print_opts & EVSEL__PRINT_UNKNOWN_AS_ADDR;
 	int print_arrow = print_opts & EVSEL__PRINT_CALLCHAIN_ARROW;
+	int print_skip_ignored = print_opts & EVSEL__PRINT_SKIP_IGNORED;
 	char s = print_oneline ? ' ' : '\t';
 	bool first = true;
 

@@ -124,6 +125,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
 			if (!node)
 				break;
 
+			if (node->sym && node->sym->ignore && print_skip_ignored)
+				goto next;
+
 			printed += fprintf(fp, "%-*.*s", left_alignment, left_alignment, " ");
 
 			if (print_arrow && !first)

@@ -162,8 +166,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
 			if (!print_oneline)
 				printed += fprintf(fp, "\n");
 
-			callchain_cursor_advance(cursor);
 			first = false;
+next:
+			callchain_cursor_advance(cursor);
 		}
 	}
 

Commit-ID:  8388deb3ba4d36ffcae91a2a01cb2ea6f27553e6
Gitweb:     http://git.kernel.org/tip/8388deb3ba4d36ffcae91a2a01cb2ea6f27553e6
Author:     Namhyung Kim <[email protected]>
AuthorDate: Thu, 24 Nov 2016 10:11:14 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Fri, 25 Nov 2016 10:50:57 -0300

perf sched timehist: Enlarge max stack depth by 2

When it records callchains, they will always have 2 scheduler functions (__schedule + schedule or __schedule + preempt_schedule) and get ignored. So it should collect 2 more functions to show the expected number of callchains to user.

Committer Notes:

Example of final result, using the same perf.data file as in the previous cset comment, but this time redirecting the output of 'perf sched timehist' to a file instead of copy'n'pasting from xterm:

[root@jouet experimental]# perf sched timehist > /tmp/bla [root@jouet experimental]# cat /tmp/bla
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
-------- ---- -------------------- ------ ------ -----

  6.494998 [01] <idle>                0.000  0.000  0.000
  6.495027 [02] perf[519]             0.000  0.000  0.000 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
  6.495096 [03] <idle>                0.000  0.000  0.000
  6.495100 [03] rcuos/0[9]            0.000  0.005  0.003 rcu_nocb_kthread <- kthread <- ret_from_fork
  6.495113 [01] perf[520]             0.000  0.008  0.114 preempt_schedule_common <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec <- do_execveat_common.isra.35
  6.495121 [00] <idle>                0.000  0.000  0.000
  6.495129 [01] migration/1[17]       0.000  0.003  0.016 smpboot_thread_fn <- kthread <- ret_from_fork
  6.496085 [02] <idle>                0.000  0.000  1.057
  6.496096 [02] kworker/u16:1[31169]  0.000  0.004  0.011 worker_thread <- kthread <- ret_from_fork
  6.496096 [03] <idle>                0.003  0.000  0.996
  6.496169 [02] <idle>                0.011  0.000  0.072
  6.496171 [00] ls[520]               0.008  0.000  1.049 do_exit <- do_group_exit <- [unknown] <- entry_SYSCALL_64_fastpath
  6.496172 [03] gnome-terminal-[4391] 0.000  0.003  0.076 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll

---
 tools/perf/builtin-sched.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 06be809..a49a032 100644
@@ -1960,7 +1960,7 @@ static bool is_idle_sample(struct perf_sched *sched,
 		return false;
 
 	if (thread__resolve_callchain(thread, cursor, evsel, sample,
-				      NULL, NULL, sched->max_stack) != 0) {
+				      NULL, NULL, sched->max_stack + 2) != 0) {
 		if (verbose)
 			error("Failed to resolve callchain. Skipping\n");
 

Commit-ID:  cdeb01bf7863718bbbbdac2a2c3a12b62366757a
Gitweb:     http://git.kernel.org/tip/cdeb01bf7863718bbbbdac2a2c3a12b62366757a
Author:     Namhyung Kim <[email protected]>
AuthorDate: Thu, 24 Nov 2016 10:11:12 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Fri, 25 Nov 2016 10:49:43 -0300

perf sched timehist: Mark schedule function in callchains

The sched_switch event always captured from the scheduler function. So it'd be great omit them from the callchain. This patch marks the functions to be omitted by later patch.

Committer notes:

Testing it:

Before:

[root@jouet experimental]# perf sched record -g ls Dockerfile perf.data x-mips64
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.355 MB perf.data (29 samples) ] [root@jouet experimental]# perf sched timehist
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
----------- ----- ----------------- ------ ------ ------

  6.494998 [001] <idle>                0.000  0.000  0.000
  6.495027 [002] perf[519]             0.000  0.000  0.000 __schedule <- schedule <- schedule_hrtimeout_range_clock <- schedule_hrtimeou
  6.495096 [003] <idle>                0.000  0.000  0.000
  6.495100 [003] rcuos/0[9]            0.000  0.005  0.003 __schedule <- schedule <- rcu_nocb_kthread <- kthread <- ret_from_fork
  6.495113 [001] perf[520]             0.000  0.008  0.114 __schedule <- preempt_schedule_common <- _cond_resched <- wait_for_completion
  6.495121 [000] <idle>                0.000  0.000  0.000
  6.495129 [001] migration/1[17]       0.000  0.003  0.016 __schedule <- schedule <- smpboot_thread_fn <- kthread <- ret_from_fork
  6.496085 [002] <idle>                0.000  0.000  1.057
  6.496096 [002] kworker/u16:1[31169]  0.000  0.004  0.011 __schedule <- schedule <- worker_thread <- kthread <- ret_from_fork
  6.496096 [003] <idle>                0.003  0.000  0.996
  6.496169 [002] <idle>                0.011  0.000  0.072
  6.496171 [000] ls[520]               0.008  0.000  1.049 __schedule <- schedule <- do_exit <- do_group_exit <- [unknown]
  6.496172 [003] gnome-terminal-[4391] 0.000  0.003  0.076 __schedule <- schedule <- schedule_hrtimeout_range_clock <- schedule_hrtimeo

After:

[root@jouet experimental]# perf sched timehist
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)

  ----------- -----  ----------------- -----  -----  ------
  6.494998 [001] <idle>                0.000  0.000  0.000
  6.495027 [002] perf[519]             0.000  0.000  0.000 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_t
  6.495096 [003] <idle>                0.000  0.000  0.000
  6.495100 [003] rcuos/0[9]            0.000  0.005  0.003 rcu_nocb_kthread <- kthread <- ret_from_fork
  6.495113 [001] perf[520]             0.000  0.008  0.114 preempt_schedule_common <- _cond_resched <- wait_for_completion <- stop_one_c
  6.495121 [000] <idle>                0.000  0.000  0.000
  6.495129 [001] migration/1[17]       0.000  0.003  0.016 smpboot_thread_fn <- kthread <- ret_from_fork
  6.496085 [002] <idle>                0.000  0.000  1.057
  6.496096 [002] kworker/u16:1[31169]  0.000  0.004  0.011 worker_thread <- kthread <- ret_from_fork
  6.496096 [003] <idle>                0.003  0.000  0.996
  6.496169 [002] <idle>                0.011  0.000  0.072
  6.496171 [000] ls[520]               0.008  0.000  1.049 do_exit <- do_group_exit <- [unknown]
  6.496172 [003] gnome-terminal-[4391] 0.000  0.003  0.076 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_

[root@jouet experimental]#

---
 tools/perf/builtin-sched.c | 21 +++++++++++++++++++++
 tools/perf/util/symbol.h   |  1 +
 2 files changed, 22 insertions(+)

index 43fcc13..06be809 100644
@@ -1966,7 +1966,28 @@ static bool is_idle_sample(struct perf_sched *sched,
 
 		return false;
 	}
+
 	callchain_cursor_commit(cursor);
+
+	while (true) {
+		struct callchain_cursor_node *node;
+		struct symbol *sym;
+
+		node = callchain_cursor_current(cursor);
+		if (node == NULL)
+			break;
+
+		sym = node->sym;
+		if (sym && sym->name) {
+			if (!strcmp(sym->name, "schedule") ||
+			    !strcmp(sym->name, "__schedule") ||
+			    !strcmp(sym->name, "preempt_schedule"))
+				sym->ignore = 1;
+		}
+
+		callchain_cursor_advance(cursor);
+	}
+
 	return false;
 }
 

index dec7e2d4..1bcbefc 100644
@@ -58,6 +58,7 @@ struct symbol {
 	u16		namelen;
 	u8		binding;
 	u8		idle:1;
+	u8		ignore:1;
 	u8		arch_sym;
 	char		name[0];
 };