[PATCH] perf timehist: Handle cpu migration events

[PATCH] perf timehist: Handle cpu migration events

[David Ahern]

From: David Ahern <dsahern@gmail.com>

Add handlers for sched:sched_migrate_task event. Total number of migrations
is added to summary display and -M/--migrations can be used to show
migration events.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/Documentation/perf-sched.txt |  4 ++
 tools/perf/builtin-sched.c              | 97 ++++++++++++++++++++++++++++++++-
 2 files changed, 99 insertions(+), 2 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index fb9e52d65fca..121c60da03e5 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -128,6 +128,10 @@ OPTIONS for 'perf sched timehist'
 --wakeups::
 	Show wakeup events.
 
+-M::
+--migrations::
+	Show migration events.
+
 SEE ALSO
 --------
 linkperf:perf-record[1]
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 829468defa07..2706809bc3e4 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -203,6 +203,7 @@ struct perf_sched {
 	unsigned int	max_stack;
 	bool		show_cpu_visual;
 	bool		show_wakeups;
+	bool		show_migrations;
 	u64		skipped_samples;
 };
 
@@ -216,6 +217,8 @@ struct thread_runtime {
 
 	struct stats run_stats;
 	u64 total_run_time;
+
+	u64 migrations;
 };
 
 /* per event run time data */
@@ -2175,6 +2178,87 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
 	return 0;
 }
 
+static void timehist_print_migration_event(struct perf_sched *sched,
+					struct perf_evsel *evsel,
+					struct perf_sample *sample,
+					struct machine *machine,
+					struct thread *migrated)
+{
+	struct thread *thread;
+	char tstr[64];
+	u32 max_cpus = sched->max_cpu + 1;
+	u32 ocpu, dcpu;
+
+	if (sched->summary_only)
+		return;
+
+	max_cpus = sched->max_cpu + 1;
+	ocpu = perf_evsel__intval(evsel, sample, "orig_cpu");
+	dcpu = perf_evsel__intval(evsel, sample, "dest_cpu");
+
+	thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+	if (thread == NULL)
+		return;
+
+	if (timehist_skip_sample(sched, thread) &&
+	    timehist_skip_sample(sched, migrated)) {
+		return;
+	}
+
+	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+	printf("%15s [%04d] ", tstr, sample->cpu);
+
+	if (sched->show_cpu_visual) {
+		u32 i;
+		char c;
+
+		printf("  ");
+		for (i = 0; i < max_cpus; ++i) {
+			c = (i == sample->cpu) ? 'm' : ' ';
+			printf("%c", c);
+		}
+		printf("  ");
+	}
+
+	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+	/* dt spacer */
+	printf("  %9s  %9s  %9s ", "", "", "");
+
+	printf("migrated: %s", timehist_get_commstr(migrated));
+	printf(" cpu %d => %d", ocpu, dcpu);
+
+	printf("\n");
+}
+
+static int timehist_migrate_task_event(struct perf_tool *tool,
+				       union perf_event *event __maybe_unused,
+				       struct perf_evsel *evsel,
+				       struct perf_sample *sample,
+				       struct machine *machine)
+{
+	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
+	struct thread *thread;
+	struct thread_runtime *tr = NULL;
+	/* want pid of migrated task not pid in sample */
+	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
+
+	thread = machine__findnew_thread(machine, 0, pid);
+	if (thread == NULL)
+		return -1;
+
+	tr = thread__get_runtime(thread);
+	if (tr == NULL)
+		return -1;
+
+	tr->migrations++;
+
+	/* show migrations if requested */
+	timehist_print_migration_event(sched, evsel, sample, machine, thread);
+
+	return 0;
+}
+
 static int timehist_sched_change_event(struct perf_tool *tool,
 				       union perf_event *event,
 				       struct perf_evsel *evsel,
@@ -2273,6 +2357,7 @@ static void print_thread_runtime(struct thread *t,
 	print_sched_time(r->run_stats.max, 6);
 	printf("  ");
 	printf("%5.2f", stddev);
+	printf("   %5" PRIu64, r->migrations);
 	printf("\n");
 }
 
@@ -2334,10 +2419,10 @@ static void timehist_print_summary(struct perf_sched *sched,
 
 	printf("\nRuntime summary\n");
 	printf("%*s  parent   sched-in  ", comm_width, "comm");
-	printf("   run-time    min-run     avg-run     max-run  stddev\n");
+	printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
 	printf("%*s            (count)  ", comm_width, "");
 	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
-	printf("%.105s\n", graph_dotted_line);
+	printf("%.117s\n", graph_dotted_line);
 
 	machine__for_each_thread(m, show_thread_runtime, &totals);
 	task_count = totals.task_count;
@@ -2438,6 +2523,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
 		{ "sched:sched_wakeup",	      timehist_sched_wakeup_event, },
 		{ "sched:sched_wakeup_new",   timehist_sched_wakeup_event, },
 	};
+	const struct perf_evsel_str_handler migrate_handlers[] = {
+		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
+	};
 	struct perf_data_file file = {
 		.path = input_name,
 		.mode = PERF_DATA_MODE_READ,
@@ -2485,6 +2573,10 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (!perf_session__has_traces(session, "record -R"))
 		goto out;
 
+	if (sched->show_migrations &&
+	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
+		goto out;
+
 	/* pre-allocate struct for per-CPU idle stats */
 	sched->max_cpu = session->header.env.nr_cpus_online;
 	if (sched->max_cpu == 0)
@@ -2881,6 +2973,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('S', "with-summary", &sched.summary,
 		    "Show all syscalls and summary with statistics"),
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
 	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
 	OPT_PARENT(sched_options)
 	};
-- 
2.7.4 (Apple Git-66)

Re: [PATCH] perf timehist: Handle cpu migration events

[Arnaldo Carvalho de Melo]

Em Fri, Nov 25, 2016 at 09:28:41AM -0700, David Ahern escreveu:
> From: David Ahern <dsahern@gmail.com>
> 
> Add handlers for sched:sched_migrate_task event. Total number of migrations
> is added to summary display and -M/--migrations can be used to show
> migration events.

Thanks, applied.
 
> Signed-off-by: David Ahern <dsahern@gmail.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/Documentation/perf-sched.txt |  4 ++
>  tools/perf/builtin-sched.c              | 97 ++++++++++++++++++++++++++++++++-
>  2 files changed, 99 insertions(+), 2 deletions(-)
> 
> diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
> index fb9e52d65fca..121c60da03e5 100644
> --- a/tools/perf/Documentation/perf-sched.txt
> +++ b/tools/perf/Documentation/perf-sched.txt
> @@ -128,6 +128,10 @@ OPTIONS for 'perf sched timehist'
>  --wakeups::
>  	Show wakeup events.
>  
> +-M::
> +--migrations::
> +	Show migration events.
> +
>  SEE ALSO
>  --------
>  linkperf:perf-record[1]
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 829468defa07..2706809bc3e4 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -203,6 +203,7 @@ struct perf_sched {
>  	unsigned int	max_stack;
>  	bool		show_cpu_visual;
>  	bool		show_wakeups;
> +	bool		show_migrations;
>  	u64		skipped_samples;
>  };
>  
> @@ -216,6 +217,8 @@ struct thread_runtime {
>  
>  	struct stats run_stats;
>  	u64 total_run_time;
> +
> +	u64 migrations;
>  };
>  
>  /* per event run time data */
> @@ -2175,6 +2178,87 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
>  	return 0;
>  }
>  
> +static void timehist_print_migration_event(struct perf_sched *sched,
> +					struct perf_evsel *evsel,
> +					struct perf_sample *sample,
> +					struct machine *machine,
> +					struct thread *migrated)
> +{
> +	struct thread *thread;
> +	char tstr[64];
> +	u32 max_cpus = sched->max_cpu + 1;
> +	u32 ocpu, dcpu;
> +
> +	if (sched->summary_only)
> +		return;
> +
> +	max_cpus = sched->max_cpu + 1;
> +	ocpu = perf_evsel__intval(evsel, sample, "orig_cpu");
> +	dcpu = perf_evsel__intval(evsel, sample, "dest_cpu");
> +
> +	thread = machine__findnew_thread(machine, sample->pid, sample->tid);
> +	if (thread == NULL)
> +		return;
> +
> +	if (timehist_skip_sample(sched, thread) &&
> +	    timehist_skip_sample(sched, migrated)) {
> +		return;
> +	}
> +
> +	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
> +	printf("%15s [%04d] ", tstr, sample->cpu);
> +
> +	if (sched->show_cpu_visual) {
> +		u32 i;
> +		char c;
> +
> +		printf("  ");
> +		for (i = 0; i < max_cpus; ++i) {
> +			c = (i == sample->cpu) ? 'm' : ' ';
> +			printf("%c", c);
> +		}
> +		printf("  ");
> +	}
> +
> +	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
> +
> +	/* dt spacer */
> +	printf("  %9s  %9s  %9s ", "", "", "");
> +
> +	printf("migrated: %s", timehist_get_commstr(migrated));
> +	printf(" cpu %d => %d", ocpu, dcpu);
> +
> +	printf("\n");
> +}
> +
> +static int timehist_migrate_task_event(struct perf_tool *tool,
> +				       union perf_event *event __maybe_unused,
> +				       struct perf_evsel *evsel,
> +				       struct perf_sample *sample,
> +				       struct machine *machine)
> +{
> +	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
> +	struct thread *thread;
> +	struct thread_runtime *tr = NULL;
> +	/* want pid of migrated task not pid in sample */
> +	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
> +
> +	thread = machine__findnew_thread(machine, 0, pid);
> +	if (thread == NULL)
> +		return -1;
> +
> +	tr = thread__get_runtime(thread);
> +	if (tr == NULL)
> +		return -1;
> +
> +	tr->migrations++;
> +
> +	/* show migrations if requested */
> +	timehist_print_migration_event(sched, evsel, sample, machine, thread);
> +
> +	return 0;
> +}
> +
>  static int timehist_sched_change_event(struct perf_tool *tool,
>  				       union perf_event *event,
>  				       struct perf_evsel *evsel,
> @@ -2273,6 +2357,7 @@ static void print_thread_runtime(struct thread *t,
>  	print_sched_time(r->run_stats.max, 6);
>  	printf("  ");
>  	printf("%5.2f", stddev);
> +	printf("   %5" PRIu64, r->migrations);
>  	printf("\n");
>  }
>  
> @@ -2334,10 +2419,10 @@ static void timehist_print_summary(struct perf_sched *sched,
>  
>  	printf("\nRuntime summary\n");
>  	printf("%*s  parent   sched-in  ", comm_width, "comm");
> -	printf("   run-time    min-run     avg-run     max-run  stddev\n");
> +	printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
>  	printf("%*s            (count)  ", comm_width, "");
>  	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
> -	printf("%.105s\n", graph_dotted_line);
> +	printf("%.117s\n", graph_dotted_line);
>  
>  	machine__for_each_thread(m, show_thread_runtime, &totals);
>  	task_count = totals.task_count;
> @@ -2438,6 +2523,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
>  		{ "sched:sched_wakeup",	      timehist_sched_wakeup_event, },
>  		{ "sched:sched_wakeup_new",   timehist_sched_wakeup_event, },
>  	};
> +	const struct perf_evsel_str_handler migrate_handlers[] = {
> +		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
> +	};
>  	struct perf_data_file file = {
>  		.path = input_name,
>  		.mode = PERF_DATA_MODE_READ,
> @@ -2485,6 +2573,10 @@ static int perf_sched__timehist(struct perf_sched *sched)
>  	if (!perf_session__has_traces(session, "record -R"))
>  		goto out;
>  
> +	if (sched->show_migrations &&
> +	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
> +		goto out;
> +
>  	/* pre-allocate struct for per-CPU idle stats */
>  	sched->max_cpu = session->header.env.nr_cpus_online;
>  	if (sched->max_cpu == 0)
> @@ -2881,6 +2973,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
>  	OPT_BOOLEAN('S', "with-summary", &sched.summary,
>  		    "Show all syscalls and summary with statistics"),
>  	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
> +	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
>  	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
>  	OPT_PARENT(sched_options)
>  	};
> -- 
> 2.7.4 (Apple Git-66)

[tip:perf/core] perf sched timehist: Handle cpu migration events

[tip-bot for David Ahern]

Commit-ID:  350f54fab2afd7f819e64fbeecdf980086fa59f2
Gitweb:     http://git.kernel.org/tip/350f54fab2afd7f819e64fbeecdf980086fa59f2
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Fri, 25 Nov 2016 09:28:41 -0700
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 25 Nov 2016 16:00:22 -0300

perf sched timehist: Handle cpu migration events

Add handlers for sched:sched_migrate_task event. Total number of
migrations is added to summary display and -M/--migrations can be used
to show migration events.

Signed-off-by: David Ahern <dsahern@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/1480091321-35591-1-git-send-email-dsa@cumulusnetworks.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/Documentation/perf-sched.txt |  4 ++
 tools/perf/builtin-sched.c              | 97 ++++++++++++++++++++++++++++++++-
 2 files changed, 99 insertions(+), 2 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index fb9e52d..121c60d 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -128,6 +128,10 @@ OPTIONS for 'perf sched timehist'
 --wakeups::
 	Show wakeup events.
 
+-M::
+--migrations::
+	Show migration events.
+
 SEE ALSO
 --------
 linkperf:perf-record[1]
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index a49a032..4f9e7cb 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -203,6 +203,7 @@ struct perf_sched {
 	unsigned int	max_stack;
 	bool		show_cpu_visual;
 	bool		show_wakeups;
+	bool		show_migrations;
 	u64		skipped_samples;
 };
 
@@ -216,6 +217,8 @@ struct thread_runtime {
 
 	struct stats run_stats;
 	u64 total_run_time;
+
+	u64 migrations;
 };
 
 /* per event run time data */
@@ -2197,6 +2200,87 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
 	return 0;
 }
 
+static void timehist_print_migration_event(struct perf_sched *sched,
+					struct perf_evsel *evsel,
+					struct perf_sample *sample,
+					struct machine *machine,
+					struct thread *migrated)
+{
+	struct thread *thread;
+	char tstr[64];
+	u32 max_cpus = sched->max_cpu + 1;
+	u32 ocpu, dcpu;
+
+	if (sched->summary_only)
+		return;
+
+	max_cpus = sched->max_cpu + 1;
+	ocpu = perf_evsel__intval(evsel, sample, "orig_cpu");
+	dcpu = perf_evsel__intval(evsel, sample, "dest_cpu");
+
+	thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+	if (thread == NULL)
+		return;
+
+	if (timehist_skip_sample(sched, thread) &&
+	    timehist_skip_sample(sched, migrated)) {
+		return;
+	}
+
+	timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+	printf("%15s [%04d] ", tstr, sample->cpu);
+
+	if (sched->show_cpu_visual) {
+		u32 i;
+		char c;
+
+		printf("  ");
+		for (i = 0; i < max_cpus; ++i) {
+			c = (i == sample->cpu) ? 'm' : ' ';
+			printf("%c", c);
+		}
+		printf("  ");
+	}
+
+	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+	/* dt spacer */
+	printf("  %9s  %9s  %9s ", "", "", "");
+
+	printf("migrated: %s", timehist_get_commstr(migrated));
+	printf(" cpu %d => %d", ocpu, dcpu);
+
+	printf("\n");
+}
+
+static int timehist_migrate_task_event(struct perf_tool *tool,
+				       union perf_event *event __maybe_unused,
+				       struct perf_evsel *evsel,
+				       struct perf_sample *sample,
+				       struct machine *machine)
+{
+	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
+	struct thread *thread;
+	struct thread_runtime *tr = NULL;
+	/* want pid of migrated task not pid in sample */
+	const u32 pid = perf_evsel__intval(evsel, sample, "pid");
+
+	thread = machine__findnew_thread(machine, 0, pid);
+	if (thread == NULL)
+		return -1;
+
+	tr = thread__get_runtime(thread);
+	if (tr == NULL)
+		return -1;
+
+	tr->migrations++;
+
+	/* show migrations if requested */
+	timehist_print_migration_event(sched, evsel, sample, machine, thread);
+
+	return 0;
+}
+
 static int timehist_sched_change_event(struct perf_tool *tool,
 				       union perf_event *event,
 				       struct perf_evsel *evsel,
@@ -2295,6 +2379,7 @@ static void print_thread_runtime(struct thread *t,
 	print_sched_time(r->run_stats.max, 6);
 	printf("  ");
 	printf("%5.2f", stddev);
+	printf("   %5" PRIu64, r->migrations);
 	printf("\n");
 }
 
@@ -2356,10 +2441,10 @@ static void timehist_print_summary(struct perf_sched *sched,
 
 	printf("\nRuntime summary\n");
 	printf("%*s  parent   sched-in  ", comm_width, "comm");
-	printf("   run-time    min-run     avg-run     max-run  stddev\n");
+	printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
 	printf("%*s            (count)  ", comm_width, "");
 	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
-	printf("%.105s\n", graph_dotted_line);
+	printf("%.117s\n", graph_dotted_line);
 
 	machine__for_each_thread(m, show_thread_runtime, &totals);
 	task_count = totals.task_count;
@@ -2460,6 +2545,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
 		{ "sched:sched_wakeup",	      timehist_sched_wakeup_event, },
 		{ "sched:sched_wakeup_new",   timehist_sched_wakeup_event, },
 	};
+	const struct perf_evsel_str_handler migrate_handlers[] = {
+		{ "sched:sched_migrate_task", timehist_migrate_task_event, },
+	};
 	struct perf_data_file file = {
 		.path = input_name,
 		.mode = PERF_DATA_MODE_READ,
@@ -2507,6 +2595,10 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (!perf_session__has_traces(session, "record -R"))
 		goto out;
 
+	if (sched->show_migrations &&
+	    perf_session__set_tracepoints_handlers(session, migrate_handlers))
+		goto out;
+
 	/* pre-allocate struct for per-CPU idle stats */
 	sched->max_cpu = session->header.env.nr_cpus_online;
 	if (sched->max_cpu == 0)
@@ -2903,6 +2995,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('S', "with-summary", &sched.summary,
 		    "Show all syscalls and summary with statistics"),
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
 	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
 	OPT_PARENT(sched_options)
 	};