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


Groups > linux.kernel > #1523247 > unrolled thread

[PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)

Started byNamhyung Kim <namhyung@kernel.org>
First post2016-11-16 07:10 +0100
Last post2016-11-22 08:10 +0100
Articles 9 — 5 participants

Back to article view | Back to linux.kernel


Contents

  [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim <namhyung@kernel.org> - 2016-11-16 07:10 +0100
    [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally Namhyung Kim <namhyung@kernel.org> - 2016-11-16 07:10 +0100
      [tip:perf/core] perf symbols: Print symbol offsets conditionally tip-bot for Namhyung Kim <tipbot@zytor.com> - 2016-11-24 05:20 +0100
    [PATCH v2 4/8] perf sched timehist: Add summary options Namhyung Kim <namhyung@kernel.org> - 2016-11-16 07:10 +0100
      [tip:perf/core] perf sched timehist: Add summary options tip-bot for David Ahern <tipbot@zytor.com> - 2016-11-24 05:30 +0100
    Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Ingo Molnar <mingo@kernel.org> - 2016-11-16 09:00 +0100
    Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Jiri Olsa <jolsa@redhat.com> - 2016-11-16 16:40 +0100
      Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim <namhyung@kernel.org> - 2016-11-22 08:10 +0100
    Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim <namhyung@kernel.org> - 2016-11-22 08:10 +0100

#1523247 — [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)

FromNamhyung Kim <namhyung@kernel.org>
Date2016-11-16 07:10 +0100
Subject[PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)
Message-ID<sE1zX-7AZ-9@gated-at.bofh.it>
Hello,

This patchset is a rebased version of David's sched timehist work [1].
I plan to improve perf sched command more and think that having
timehist command before the work looks good.  It seems David is busy
these days, so I'm retrying it by myself.

 * changes in v2)
  - change name 'b/n time' to 'wait time'  (Ingo)
  - show arrow between functions in the callchain  (Ingo)
  - fix a bug in calculating initial run time
  
This implements only basic feature and a few options.  I just split
the patch to make it easier to review and did some cosmetic changes.
More patches will come later.

The below is from the David's original description (w/ slight change):

------------------------8<-------------------------
'perf sched timehist' provides an analysis of scheduling events.

Example usage:
    perf sched record -- sleep 1
    perf sched timehist

By default it shows the individual schedule events, including the time between
sched-in events for the task, the task scheduling delay (time between wakeup
and actually running) and run time for the task:

           time cpu  task name[tid/pid]   wait time sch delay  run time
  ------------- ---- -------------------- --------- --------- ---------
   79371.874569 [11] gcc[31949]               0.014     0.000     1.148
   79371.874591 [10] gcc[31951]               0.000     0.000     0.024
   79371.874603 [10] migration/10[59]         3.350     0.004     0.011
   79371.874604 [11] <idle>                   1.148     0.000     0.035
   79371.874723 [05] <idle>                   0.016     0.000     1.383
   79371.874746 [05] gcc[31949]               0.153     0.078     0.022
...

Times are in msec.usec.

If callchains were recorded they are appended to the line with a default stack depth of 5:

   79371.874569 [11] gcc[31949]               0.014     0.000     1.148  wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
   79371.874591 [10] gcc[31951]               0.000     0.000     0.024  __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
   79371.874603 [10] migration/10[59]         3.350     0.004     0.011  smpboot_thread_fn <- kthread <- ret_from_fork
   79371.874604 [11] <idle>                   1.148     0.000     0.035  cpu_startup_entry <- start_secondary
   79371.874723 [05] <idle>                   0.016     0.000     1.383  cpu_startup_entry <- start_secondary
   79371.874746 [05] gcc[31949]               0.153     0.078     0.022  do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid

--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.

Similar to perf-trace -s and -S can be used to dump a statistical summary
without or with events (respectively). Statistics include min run time,
average run time and max run time. Stats are also shown for run time by
cpu.

The cpu-visual option provides a visual aid for sched switches by cpu:
...
   79371.874569 [11]            s      gcc[31949]                  0.014     0.000     1.148
   79371.874591 [10]           s       gcc[31951]                  0.000     0.000     0.024
   79371.874603 [10]           s       migration/10[59]            3.350     0.004     0.011
   79371.874604 [11]            i      <idle>                      1.148     0.000     0.035
   79371.874723 [05]      i            <idle>                      0.016     0.000     1.383
   79371.874746 [05]      s            gcc[31949]                  0.153     0.078     0.022
...

------------------------8<-------------------------

This code is available at 'perf/timehist-v2' branch in my tree

  git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git

Any feedback is welcomed.

Thanks,
Namhyung


[1] https://lkml.org/lkml/2013/12/1/129

David Ahern (6):
  perf sched timehist: Introduce timehist command
  perf sched timehist: Add summary options
  perf sched timehist: Add -w/--wakeups option
  perf sched timehist: Add call graph options
  perf sched timehist: Add -V/--cpu-visual option
  perf sched: Add documentation for timehist options

Namhyung Kim (2):
  perf symbol: Print symbol offsets conditionally
  perf tools: Support printing callchains with arrows

 tools/perf/Documentation/perf-sched.txt |  46 +-
 tools/perf/builtin-sched.c              | 914 +++++++++++++++++++++++++++++++-
 tools/perf/util/evsel.h                 |   1 +
 tools/perf/util/evsel_fprintf.c         |  12 +-
 tools/perf/util/symbol.h                |   3 +-
 tools/perf/util/symbol_fprintf.c        |  11 +-
 6 files changed, 972 insertions(+), 15 deletions(-)

-- 
2.10.1

[toc] | [next] | [standalone]


#1523248 — [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally

FromNamhyung Kim <namhyung@kernel.org>
Date2016-11-16 07:10 +0100
Subject[PATCH v2 1/8] perf symbol: Print symbol offsets conditionally
Message-ID<sE1zY-7AZ-25@gated-at.bofh.it>
In reply to#1523247
The __symbol__fprintf_symname_offs() always shows symbol offsets.  So
there's no difference between 'perf script -F ip,sym' and 'perf script
-F ip,sym,symoff'.  I don't think it's a desired behavior..

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/evsel_fprintf.c  |  6 ++++--
 tools/perf/util/symbol.h         |  3 ++-
 tools/perf/util/symbol_fprintf.c | 11 ++++++-----
 3 files changed, 12 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index 662a0a6182e7..ccb602397b60 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -137,7 +137,8 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
 
 				if (print_symoffset) {
 					printed += __symbol__fprintf_symname_offs(node->sym, &node_al,
-										  print_unknown_as_addr, fp);
+										  print_unknown_as_addr,
+										  true, fp);
 				} else {
 					printed += __symbol__fprintf_symname(node->sym, &node_al,
 									     print_unknown_as_addr, fp);
@@ -188,7 +189,8 @@ int sample__fprintf_sym(struct perf_sample *sample, struct addr_location *al,
 			printed += fprintf(fp, " ");
 			if (print_symoffset) {
 				printed += __symbol__fprintf_symname_offs(al->sym, al,
-									  print_unknown_as_addr, fp);
+									  print_unknown_as_addr,
+									  true, fp);
 			} else {
 				printed += __symbol__fprintf_symname(al->sym, al,
 								     print_unknown_as_addr, fp);
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index 2d0a905c879a..dec7e2d44885 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -282,7 +282,8 @@ int symbol__annotation_init(void);
 struct symbol *symbol__new(u64 start, u64 len, u8 binding, const char *name);
 size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
 				      const struct addr_location *al,
-				      bool unknown_as_addr, FILE *fp);
+				      bool unknown_as_addr,
+				      bool print_offsets, FILE *fp);
 size_t symbol__fprintf_symname_offs(const struct symbol *sym,
 				    const struct addr_location *al, FILE *fp);
 size_t __symbol__fprintf_symname(const struct symbol *sym,
diff --git a/tools/perf/util/symbol_fprintf.c b/tools/perf/util/symbol_fprintf.c
index a680bdaa65dc..7c6b33e8e2d2 100644
--- a/tools/perf/util/symbol_fprintf.c
+++ b/tools/perf/util/symbol_fprintf.c
@@ -15,14 +15,15 @@ size_t symbol__fprintf(struct symbol *sym, FILE *fp)
 
 size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
 				      const struct addr_location *al,
-				      bool unknown_as_addr, FILE *fp)
+				      bool unknown_as_addr,
+				      bool print_offsets, FILE *fp)
 {
 	unsigned long offset;
 	size_t length;
 
 	if (sym && sym->name) {
 		length = fprintf(fp, "%s", sym->name);
-		if (al) {
+		if (al && print_offsets) {
 			if (al->addr < sym->end)
 				offset = al->addr - sym->start;
 			else
@@ -40,19 +41,19 @@ size_t symbol__fprintf_symname_offs(const struct symbol *sym,
 				    const struct addr_location *al,
 				    FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, al, false, fp);
+	return __symbol__fprintf_symname_offs(sym, al, false, true, fp);
 }
 
 size_t __symbol__fprintf_symname(const struct symbol *sym,
 				 const struct addr_location *al,
 				 bool unknown_as_addr, FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, fp);
+	return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, false, fp);
 }
 
 size_t symbol__fprintf_symname(const struct symbol *sym, FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, NULL, false, fp);
+	return __symbol__fprintf_symname_offs(sym, NULL, false, false, fp);
 }
 
 size_t dso__fprintf_symbols_by_name(struct dso *dso,
-- 
2.10.1

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


#1528950 — [tip:perf/core] perf symbols: Print symbol offsets conditionally

Fromtip-bot for Namhyung Kim <tipbot@zytor.com>
Date2016-11-24 05:20 +0100
Subject[tip:perf/core] perf symbols: Print symbol offsets conditionally
Message-ID<sGTFT-5T2-1@gated-at.bofh.it>
In reply to#1523248
Commit-ID:  a8763445f6c78628bd96d51649745065c0bb2c92
Gitweb:     http://git.kernel.org/tip/a8763445f6c78628bd96d51649745065c0bb2c92
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Wed, 16 Nov 2016 15:06:27 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:06 -0300

perf symbols: Print symbol offsets conditionally

The __symbol__fprintf_symname_offs() always shows symbol offsets.  So
there's no difference between 'perf script -F ip,sym' and 'perf script
-F ip,sym,symoff'.  I don't think it's a desired behavior..

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-2-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/evsel_fprintf.c  |  6 ++++--
 tools/perf/util/symbol.h         |  3 ++-
 tools/perf/util/symbol_fprintf.c | 11 ++++++-----
 3 files changed, 12 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index 662a0a6..ccb6023 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -137,7 +137,8 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
 
 				if (print_symoffset) {
 					printed += __symbol__fprintf_symname_offs(node->sym, &node_al,
-										  print_unknown_as_addr, fp);
+										  print_unknown_as_addr,
+										  true, fp);
 				} else {
 					printed += __symbol__fprintf_symname(node->sym, &node_al,
 									     print_unknown_as_addr, fp);
@@ -188,7 +189,8 @@ int sample__fprintf_sym(struct perf_sample *sample, struct addr_location *al,
 			printed += fprintf(fp, " ");
 			if (print_symoffset) {
 				printed += __symbol__fprintf_symname_offs(al->sym, al,
-									  print_unknown_as_addr, fp);
+									  print_unknown_as_addr,
+									  true, fp);
 			} else {
 				printed += __symbol__fprintf_symname(al->sym, al,
 								     print_unknown_as_addr, fp);
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index 2d0a905..dec7e2d4 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -282,7 +282,8 @@ int symbol__annotation_init(void);
 struct symbol *symbol__new(u64 start, u64 len, u8 binding, const char *name);
 size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
 				      const struct addr_location *al,
-				      bool unknown_as_addr, FILE *fp);
+				      bool unknown_as_addr,
+				      bool print_offsets, FILE *fp);
 size_t symbol__fprintf_symname_offs(const struct symbol *sym,
 				    const struct addr_location *al, FILE *fp);
 size_t __symbol__fprintf_symname(const struct symbol *sym,
diff --git a/tools/perf/util/symbol_fprintf.c b/tools/perf/util/symbol_fprintf.c
index a680bda..7c6b33e 100644
--- a/tools/perf/util/symbol_fprintf.c
+++ b/tools/perf/util/symbol_fprintf.c
@@ -15,14 +15,15 @@ size_t symbol__fprintf(struct symbol *sym, FILE *fp)
 
 size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
 				      const struct addr_location *al,
-				      bool unknown_as_addr, FILE *fp)
+				      bool unknown_as_addr,
+				      bool print_offsets, FILE *fp)
 {
 	unsigned long offset;
 	size_t length;
 
 	if (sym && sym->name) {
 		length = fprintf(fp, "%s", sym->name);
-		if (al) {
+		if (al && print_offsets) {
 			if (al->addr < sym->end)
 				offset = al->addr - sym->start;
 			else
@@ -40,19 +41,19 @@ size_t symbol__fprintf_symname_offs(const struct symbol *sym,
 				    const struct addr_location *al,
 				    FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, al, false, fp);
+	return __symbol__fprintf_symname_offs(sym, al, false, true, fp);
 }
 
 size_t __symbol__fprintf_symname(const struct symbol *sym,
 				 const struct addr_location *al,
 				 bool unknown_as_addr, FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, fp);
+	return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, false, fp);
 }
 
 size_t symbol__fprintf_symname(const struct symbol *sym, FILE *fp)
 {
-	return __symbol__fprintf_symname_offs(sym, NULL, false, fp);
+	return __symbol__fprintf_symname_offs(sym, NULL, false, false, fp);
 }
 
 size_t dso__fprintf_symbols_by_name(struct dso *dso,

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


#1523249 — [PATCH v2 4/8] perf sched timehist: Add summary options

FromNamhyung Kim <namhyung@kernel.org>
Date2016-11-16 07:10 +0100
Subject[PATCH v2 4/8] perf sched timehist: Add summary options
Message-ID<sE1zY-7AZ-23@gated-at.bofh.it>
In reply to#1523247
From: David Ahern <dsahern@gmail.com>

The -s/--summary option is to show process runtime statistics.  And the
 -S/--with-summary option is to show the stats with the normal output.

  $ perf sched timehist -s

  Runtime summary
                            comm  parent   sched-in     run-time    min-run     avg-run     max-run  stddev
                                            (count)       (msec)     (msec)      (msec)      (msec)       %
  ---------------------------------------------------------------------------------------------------------
                  ksoftirqd/0[3]       2          2        0.011      0.004       0.005       0.006   14.87
                  rcu_preempt[7]       2         11        0.071      0.002       0.006       0.017   20.23
                  watchdog/0[11]       2          1        0.002      0.002       0.002       0.002    0.00
                  watchdog/1[12]       2          1        0.004      0.004       0.004       0.004    0.00
  ...

  Terminated tasks:
                     sleep[7220]    7219          3        0.770      0.087       0.256       0.576   62.28

  Idle stats:
      CPU  0 idle for   2352.006  msec
      CPU  1 idle for   2764.497  msec
      CPU  2 idle for   2998.229  msec
      CPU  3 idle for   2967.800  msec

      Total number of unique tasks: 52
  Total number of context switches: 2532
             Total run time (msec): 218.036

Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 160 insertions(+), 6 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index c0ac0c9557e8..1e7d81ad5ec6 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -194,6 +194,11 @@ struct perf_sched {
 	bool force;
 	bool skip_merge;
 	struct perf_sched_map map;
+
+	/* options for timehist command */
+	bool		summary;
+	bool		summary_only;
+	u64		skipped_samples;
 };
 
 /* per thread run time data */
@@ -2010,12 +2015,15 @@ static struct thread *timehist_get_thread(struct perf_sample *sample,
 	return thread;
 }
 
-static bool timehist_skip_sample(struct thread *thread)
+static bool timehist_skip_sample(struct perf_sched *sched,
+				 struct thread *thread)
 {
 	bool rc = false;
 
-	if (thread__is_filtered(thread))
+	if (thread__is_filtered(thread)) {
 		rc = true;
+		sched->skipped_samples++;
+	}
 
 	return rc;
 }
@@ -2045,7 +2053,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
 	return 0;
 }
 
-static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
+static int timehist_sched_change_event(struct perf_tool *tool,
 				       union perf_event *event,
 				       struct perf_evsel *evsel,
 				       struct perf_sample *sample,
@@ -2056,6 +2064,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 	struct thread_runtime *tr = NULL;
 	u64 tprev;
 	int rc = 0;
+	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
 
 	if (machine__resolve(machine, &al, sample) < 0) {
 		pr_err("problem processing %d event. skipping it\n",
@@ -2070,7 +2079,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 		goto out;
 	}
 
-	if (timehist_skip_sample(thread))
+	if (timehist_skip_sample(sched, thread))
 		goto out;
 
 	tr = thread__get_runtime(thread);
@@ -2082,7 +2091,8 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 	tprev = perf_evsel__get_time(evsel, sample->cpu);
 
 	timehist_update_runtime_stats(tr, sample->time, tprev);
-	timehist_print_sample(sample, thread);
+	if (!sched->summary_only)
+		timehist_print_sample(sample, thread);
 
 out:
 	if (tr) {
@@ -2122,6 +2132,131 @@ static int process_lost(struct perf_tool *tool __maybe_unused,
 }
 
 
+static void print_thread_runtime(struct thread *t,
+				 struct thread_runtime *r)
+{
+	double mean = avg_stats(&r->run_stats);
+	float stddev;
+
+	printf("%*s   %5d  %9" PRIu64 " ",
+	       comm_width, timehist_get_commstr(t), t->ppid,
+	       (u64) r->run_stats.n);
+
+	print_sched_time(r->total_run_time, 8);
+	stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean);
+	print_sched_time(r->run_stats.min, 6);
+	printf(" ");
+	print_sched_time((u64) mean, 6);
+	printf(" ");
+	print_sched_time(r->run_stats.max, 6);
+	printf("  ");
+	printf("%5.2f", stddev);
+	printf("\n");
+}
+
+struct total_run_stats {
+	u64  sched_count;
+	u64  task_count;
+	u64  total_run_time;
+};
+
+static int __show_thread_runtime(struct thread *t, void *priv)
+{
+	struct total_run_stats *stats = priv;
+	struct thread_runtime *r;
+
+	if (thread__is_filtered(t))
+		return 0;
+
+	r = thread__priv(t);
+	if (r && r->run_stats.n) {
+		stats->task_count++;
+		stats->sched_count += r->run_stats.n;
+		stats->total_run_time += r->total_run_time;
+		print_thread_runtime(t, r);
+	}
+
+	return 0;
+}
+
+static int show_thread_runtime(struct thread *t, void *priv)
+{
+	if (t->dead)
+		return 0;
+
+	return __show_thread_runtime(t, priv);
+}
+
+static int show_deadthread_runtime(struct thread *t, void *priv)
+{
+	if (!t->dead)
+		return 0;
+
+	return __show_thread_runtime(t, priv);
+}
+
+static void timehist_print_summary(struct perf_sched *sched,
+				   struct perf_session *session)
+{
+	struct machine *m = &session->machines.host;
+	struct total_run_stats totals;
+	u64 task_count;
+	struct thread *t;
+	struct thread_runtime *r;
+	int i;
+
+	memset(&totals, 0, sizeof(totals));
+
+	if (comm_width < 30)
+		comm_width = 30;
+
+	printf("\nRuntime summary\n");
+	printf("%*s  parent   sched-in  ", comm_width, "comm");
+	printf("   run-time    min-run     avg-run     max-run  stddev\n");
+	printf("%*s            (count)  ", comm_width, "");
+	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
+	printf("%.105s\n", graph_dotted_line);
+
+	machine__for_each_thread(m, show_thread_runtime, &totals);
+	task_count = totals.task_count;
+	if (!task_count)
+		printf("<no still running tasks>\n");
+
+	printf("\nTerminated tasks:\n");
+	machine__for_each_thread(m, show_deadthread_runtime, &totals);
+	if (task_count == totals.task_count)
+		printf("<no terminated tasks>\n");
+
+	/* CPU idle stats not tracked when samples were skipped */
+	if (sched->skipped_samples)
+		return;
+
+	printf("\nIdle stats:\n");
+	for (i = 0; i <= idle_max_cpu; ++i) {
+		t = idle_threads[i];
+		if (!t)
+			continue;
+
+		r = thread__priv(t);
+		if (r && r->run_stats.n) {
+			totals.sched_count += r->run_stats.n;
+			printf("    CPU %2d idle for ", i);
+			print_sched_time(r->total_run_time, 6);
+			printf(" msec\n");
+		} else
+			printf("    CPU %2d idle entire time window\n", i);
+	}
+
+	printf("\n"
+	       "    Total number of unique tasks: %" PRIu64 "\n"
+	       "Total number of context switches: %" PRIu64 "\n"
+	       "           Total run time (msec): ",
+	       totals.task_count, totals.sched_count);
+
+	print_sched_time(totals.total_run_time, 2);
+	printf("\n");
+}
+
 typedef int (*sched_handler)(struct perf_tool *tool,
 			  union perf_event *event,
 			  struct perf_evsel *evsel,
@@ -2163,6 +2298,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	};
 
 	struct perf_session *session;
+	struct perf_evlist *evlist;
 	int err = -1;
 
 	/*
@@ -2185,6 +2321,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (session == NULL)
 		return -ENOMEM;
 
+	evlist = session->evlist;
+
 	symbol__init(&session->header.env);
 
 	setup_pager();
@@ -2203,7 +2341,12 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (init_idle_threads(sched->max_cpu))
 		goto out;
 
-	timehist_header();
+	/* summary_only implies summary option, but don't overwrite summary if set */
+	if (sched->summary_only)
+		sched->summary = sched->summary_only;
+
+	if (!sched->summary_only)
+		timehist_header();
 
 	err = perf_session__process_events(session);
 	if (err) {
@@ -2211,6 +2354,13 @@ static int perf_sched__timehist(struct perf_sched *sched)
 		goto out;
 	}
 
+	sched->nr_events      = evlist->stats.nr_events[0];
+	sched->nr_lost_events = evlist->stats.total_lost;
+	sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST];
+
+	if (sched->summary)
+		timehist_print_summary(sched, session);
+
 out:
 	free_idle_threads();
 	perf_session__delete(session);
@@ -2569,6 +2719,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 		   "file", "kallsyms pathname"),
 	OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
 		    "Look for files with symbols relative to this directory"),
+	OPT_BOOLEAN('s', "summary", &sched.summary_only,
+		    "Show only syscall summary with statistics"),
+	OPT_BOOLEAN('S', "with-summary", &sched.summary,
+		    "Show all syscalls and summary with statistics"),
 	OPT_PARENT(sched_options)
 	};
 
-- 
2.10.1

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


#1528966 — [tip:perf/core] perf sched timehist: Add summary options

Fromtip-bot for David Ahern <tipbot@zytor.com>
Date2016-11-24 05:30 +0100
Subject[tip:perf/core] perf sched timehist: Add summary options
Message-ID<sGTPz-5W3-5@gated-at.bofh.it>
In reply to#1523249
Commit-ID:  52df138caaa8daaaf4e0dc64428ef06f303a8dbf
Gitweb:     http://git.kernel.org/tip/52df138caaa8daaaf4e0dc64428ef06f303a8dbf
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:30 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:08 -0300

perf sched timehist: Add summary options

The -s/--summary option is to show process runtime statistics.  And the
 -S/--with-summary option is to show the stats with the normal output.

  $ perf sched timehist -s

  Runtime summary
                            comm  parent   sched-in     run-time    min-run     avg-run     max-run  stddev
                                            (count)       (msec)     (msec)      (msec)      (msec)       %
  ---------------------------------------------------------------------------------------------------------
                  ksoftirqd/0[3]       2          2        0.011      0.004       0.005       0.006   14.87
                  rcu_preempt[7]       2         11        0.071      0.002       0.006       0.017   20.23
                  watchdog/0[11]       2          1        0.002      0.002       0.002       0.002    0.00
                  watchdog/1[12]       2          1        0.004      0.004       0.004       0.004    0.00
  ...

  Terminated tasks:
                     sleep[7220]    7219          3        0.770      0.087       0.256       0.576   62.28

  Idle stats:
      CPU  0 idle for   2352.006  msec
      CPU  1 idle for   2764.497  msec
      CPU  2 idle for   2998.229  msec
      CPU  3 idle for   2967.800  msec

      Total number of unique tasks: 52
  Total number of context switches: 2532
             Total run time (msec): 218.036

Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-5-namhyung@kernel.org
[ Add documentation from last commit, so that docs comes with the cset that introduces the feature ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 160 insertions(+), 6 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index c0ac0c9..1e7d81a 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -194,6 +194,11 @@ struct perf_sched {
 	bool force;
 	bool skip_merge;
 	struct perf_sched_map map;
+
+	/* options for timehist command */
+	bool		summary;
+	bool		summary_only;
+	u64		skipped_samples;
 };
 
 /* per thread run time data */
@@ -2010,12 +2015,15 @@ static struct thread *timehist_get_thread(struct perf_sample *sample,
 	return thread;
 }
 
-static bool timehist_skip_sample(struct thread *thread)
+static bool timehist_skip_sample(struct perf_sched *sched,
+				 struct thread *thread)
 {
 	bool rc = false;
 
-	if (thread__is_filtered(thread))
+	if (thread__is_filtered(thread)) {
 		rc = true;
+		sched->skipped_samples++;
+	}
 
 	return rc;
 }
@@ -2045,7 +2053,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
 	return 0;
 }
 
-static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
+static int timehist_sched_change_event(struct perf_tool *tool,
 				       union perf_event *event,
 				       struct perf_evsel *evsel,
 				       struct perf_sample *sample,
@@ -2056,6 +2064,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 	struct thread_runtime *tr = NULL;
 	u64 tprev;
 	int rc = 0;
+	struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
 
 	if (machine__resolve(machine, &al, sample) < 0) {
 		pr_err("problem processing %d event. skipping it\n",
@@ -2070,7 +2079,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 		goto out;
 	}
 
-	if (timehist_skip_sample(thread))
+	if (timehist_skip_sample(sched, thread))
 		goto out;
 
 	tr = thread__get_runtime(thread);
@@ -2082,7 +2091,8 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
 	tprev = perf_evsel__get_time(evsel, sample->cpu);
 
 	timehist_update_runtime_stats(tr, sample->time, tprev);
-	timehist_print_sample(sample, thread);
+	if (!sched->summary_only)
+		timehist_print_sample(sample, thread);
 
 out:
 	if (tr) {
@@ -2122,6 +2132,131 @@ static int process_lost(struct perf_tool *tool __maybe_unused,
 }
 
 
+static void print_thread_runtime(struct thread *t,
+				 struct thread_runtime *r)
+{
+	double mean = avg_stats(&r->run_stats);
+	float stddev;
+
+	printf("%*s   %5d  %9" PRIu64 " ",
+	       comm_width, timehist_get_commstr(t), t->ppid,
+	       (u64) r->run_stats.n);
+
+	print_sched_time(r->total_run_time, 8);
+	stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean);
+	print_sched_time(r->run_stats.min, 6);
+	printf(" ");
+	print_sched_time((u64) mean, 6);
+	printf(" ");
+	print_sched_time(r->run_stats.max, 6);
+	printf("  ");
+	printf("%5.2f", stddev);
+	printf("\n");
+}
+
+struct total_run_stats {
+	u64  sched_count;
+	u64  task_count;
+	u64  total_run_time;
+};
+
+static int __show_thread_runtime(struct thread *t, void *priv)
+{
+	struct total_run_stats *stats = priv;
+	struct thread_runtime *r;
+
+	if (thread__is_filtered(t))
+		return 0;
+
+	r = thread__priv(t);
+	if (r && r->run_stats.n) {
+		stats->task_count++;
+		stats->sched_count += r->run_stats.n;
+		stats->total_run_time += r->total_run_time;
+		print_thread_runtime(t, r);
+	}
+
+	return 0;
+}
+
+static int show_thread_runtime(struct thread *t, void *priv)
+{
+	if (t->dead)
+		return 0;
+
+	return __show_thread_runtime(t, priv);
+}
+
+static int show_deadthread_runtime(struct thread *t, void *priv)
+{
+	if (!t->dead)
+		return 0;
+
+	return __show_thread_runtime(t, priv);
+}
+
+static void timehist_print_summary(struct perf_sched *sched,
+				   struct perf_session *session)
+{
+	struct machine *m = &session->machines.host;
+	struct total_run_stats totals;
+	u64 task_count;
+	struct thread *t;
+	struct thread_runtime *r;
+	int i;
+
+	memset(&totals, 0, sizeof(totals));
+
+	if (comm_width < 30)
+		comm_width = 30;
+
+	printf("\nRuntime summary\n");
+	printf("%*s  parent   sched-in  ", comm_width, "comm");
+	printf("   run-time    min-run     avg-run     max-run  stddev\n");
+	printf("%*s            (count)  ", comm_width, "");
+	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
+	printf("%.105s\n", graph_dotted_line);
+
+	machine__for_each_thread(m, show_thread_runtime, &totals);
+	task_count = totals.task_count;
+	if (!task_count)
+		printf("<no still running tasks>\n");
+
+	printf("\nTerminated tasks:\n");
+	machine__for_each_thread(m, show_deadthread_runtime, &totals);
+	if (task_count == totals.task_count)
+		printf("<no terminated tasks>\n");
+
+	/* CPU idle stats not tracked when samples were skipped */
+	if (sched->skipped_samples)
+		return;
+
+	printf("\nIdle stats:\n");
+	for (i = 0; i <= idle_max_cpu; ++i) {
+		t = idle_threads[i];
+		if (!t)
+			continue;
+
+		r = thread__priv(t);
+		if (r && r->run_stats.n) {
+			totals.sched_count += r->run_stats.n;
+			printf("    CPU %2d idle for ", i);
+			print_sched_time(r->total_run_time, 6);
+			printf(" msec\n");
+		} else
+			printf("    CPU %2d idle entire time window\n", i);
+	}
+
+	printf("\n"
+	       "    Total number of unique tasks: %" PRIu64 "\n"
+	       "Total number of context switches: %" PRIu64 "\n"
+	       "           Total run time (msec): ",
+	       totals.task_count, totals.sched_count);
+
+	print_sched_time(totals.total_run_time, 2);
+	printf("\n");
+}
+
 typedef int (*sched_handler)(struct perf_tool *tool,
 			  union perf_event *event,
 			  struct perf_evsel *evsel,
@@ -2163,6 +2298,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	};
 
 	struct perf_session *session;
+	struct perf_evlist *evlist;
 	int err = -1;
 
 	/*
@@ -2185,6 +2321,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (session == NULL)
 		return -ENOMEM;
 
+	evlist = session->evlist;
+
 	symbol__init(&session->header.env);
 
 	setup_pager();
@@ -2203,7 +2341,12 @@ static int perf_sched__timehist(struct perf_sched *sched)
 	if (init_idle_threads(sched->max_cpu))
 		goto out;
 
-	timehist_header();
+	/* summary_only implies summary option, but don't overwrite summary if set */
+	if (sched->summary_only)
+		sched->summary = sched->summary_only;
+
+	if (!sched->summary_only)
+		timehist_header();
 
 	err = perf_session__process_events(session);
 	if (err) {
@@ -2211,6 +2354,13 @@ static int perf_sched__timehist(struct perf_sched *sched)
 		goto out;
 	}
 
+	sched->nr_events      = evlist->stats.nr_events[0];
+	sched->nr_lost_events = evlist->stats.total_lost;
+	sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST];
+
+	if (sched->summary)
+		timehist_print_summary(sched, session);
+
 out:
 	free_idle_threads();
 	perf_session__delete(session);
@@ -2569,6 +2719,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 		   "file", "kallsyms pathname"),
 	OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
 		    "Look for files with symbols relative to this directory"),
+	OPT_BOOLEAN('s', "summary", &sched.summary_only,
+		    "Show only syscall summary with statistics"),
+	OPT_BOOLEAN('S', "with-summary", &sched.summary,
+		    "Show all syscalls and summary with statistics"),
 	OPT_PARENT(sched_options)
 	};
 

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


#1523269

FromIngo Molnar <mingo@kernel.org>
Date2016-11-16 09:00 +0100
Message-ID<sE3ip-8p6-5@gated-at.bofh.it>
In reply to#1523247
* Namhyung Kim <namhyung@kernel.org> wrote:

> Hello,
> 
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good.  It seems David is busy
> these days, so I'm retrying it by myself.
> 
>  * changes in v2)
>   - change name 'b/n time' to 'wait time'  (Ingo)
>   - show arrow between functions in the callchain  (Ingo)
>   - fix a bug in calculating initial run time
>   
> This implements only basic feature and a few options.  I just split
> the patch to make it easier to review and did some cosmetic changes.
> More patches will come later.
> 
> The below is from the David's original description (w/ slight change):
> 
> ------------------------8<-------------------------
> 'perf sched timehist' provides an analysis of scheduling events.
> 
> Example usage:
>     perf sched record -- sleep 1
>     perf sched timehist
> 
> By default it shows the individual schedule events, including the time between
> sched-in events for the task, the task scheduling delay (time between wakeup
> and actually running) and run time for the task:
> 
>            time cpu  task name[tid/pid]   wait time sch delay  run time
>   ------------- ---- -------------------- --------- --------- ---------
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011
>    79371.874604 [11] <idle>                   1.148     0.000     0.035
>    79371.874723 [05] <idle>                   0.016     0.000     1.383
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022
> ...
> 
> Times are in msec.usec.
> 
> If callchains were recorded they are appended to the line with a default stack depth of 5:
> 
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148  wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024  __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011  smpboot_thread_fn <- kthread <- ret_from_fork
>    79371.874604 [11] <idle>                   1.148     0.000     0.035  cpu_startup_entry <- start_secondary
>    79371.874723 [05] <idle>                   0.016     0.000     1.383  cpu_startup_entry <- start_secondary
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022  do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
> 
> --no-call-graph can be used to not show the callchains. --max-stack is used
> to control the number of frames shown (default of 5). -x/--excl options can
> be used to collapse redundant callchains to get more relevant data on screen.
> 
> Similar to perf-trace -s and -S can be used to dump a statistical summary
> without or with events (respectively). Statistics include min run time,
> average run time and max run time. Stats are also shown for run time by
> cpu.
> 
> The cpu-visual option provides a visual aid for sched switches by cpu:
> ...
>    79371.874569 [11]            s      gcc[31949]                  0.014     0.000     1.148
>    79371.874591 [10]           s       gcc[31951]                  0.000     0.000     0.024
>    79371.874603 [10]           s       migration/10[59]            3.350     0.004     0.011
>    79371.874604 [11]            i      <idle>                      1.148     0.000     0.035
>    79371.874723 [05]      i            <idle>                      0.016     0.000     1.383
>    79371.874746 [05]      s            gcc[31949]                  0.153     0.078     0.022
> ...

Looks great to me!

Acked-by: Ingo Molnar <mingo@kernel.org>

Thanks,

	Ingo

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


#1523612

FromJiri Olsa <jolsa@redhat.com>
Date2016-11-16 16:40 +0100
Message-ID<sEatA-4HA-53@gated-at.bofh.it>
In reply to#1523247
On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> Hello,
> 
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good.  It seems David is busy
> these days, so I'm retrying it by myself.
> 
>  * changes in v2)
>   - change name 'b/n time' to 'wait time'  (Ingo)
>   - show arrow between functions in the callchain  (Ingo)
>   - fix a bug in calculating initial run time

you might want to add some column width cuts.. I've got this:

           time    cpu  task name             wait time  sch delay   run time
                        [tid/pid]                (msec)     (msec)     (msec)
--------------- ------  --------------------  ---------  ---------  ---------
  482381.387934 [0000]  perf[6870]                0.000      0.000      0.000 
  482381.388838 [0002]  <idle>                    0.000      0.000      0.000 
  482381.388845 [0002]  plugin-containe[25990/25970]      0.000      0.004      0.007 
  482381.388897 [0003]  <idle>                            0.000      0.000      0.000 
  482381.388919 [0002]  <idle>                            0.007      0.000      0.074 
  482381.388925 [0003]  Timer[15210/15178]                0.000      0.002      0.027 



other than that:

Acked-by: Jiri Olsa <jolsa@redhat.com>

thanks,
jirka

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


#1527263

FromNamhyung Kim <namhyung@kernel.org>
Date2016-11-22 08:10 +0100
Message-ID<sGdnk-3ZT-11@gated-at.bofh.it>
In reply to#1523612
Hi Jiri,

On Wed, Nov 16, 2016 at 04:34:28PM +0100, Jiri Olsa wrote:
> On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> > Hello,
> > 
> > This patchset is a rebased version of David's sched timehist work [1].
> > I plan to improve perf sched command more and think that having
> > timehist command before the work looks good.  It seems David is busy
> > these days, so I'm retrying it by myself.
> > 
> >  * changes in v2)
> >   - change name 'b/n time' to 'wait time'  (Ingo)
> >   - show arrow between functions in the callchain  (Ingo)
> >   - fix a bug in calculating initial run time
> 
> you might want to add some column width cuts.. I've got this:

The task name column width is initially set to 20, and grow
dynamically when longer name + tid/pid is found.  Maybe I need to
change it to have the max width initially.. (in later patch).

> 
>            time    cpu  task name             wait time  sch delay   run time
>                         [tid/pid]                (msec)     (msec)     (msec)
> --------------- ------  --------------------  ---------  ---------  ---------
>   482381.387934 [0000]  perf[6870]                0.000      0.000      0.000 
>   482381.388838 [0002]  <idle>                    0.000      0.000      0.000 
>   482381.388845 [0002]  plugin-containe[25990/25970]      0.000      0.004      0.007 
>   482381.388897 [0003]  <idle>                            0.000      0.000      0.000 
>   482381.388919 [0002]  <idle>                            0.007      0.000      0.074 
>   482381.388925 [0003]  Timer[15210/15178]                0.000      0.002      0.027 
> 
> 
> 
> other than that:
> 
> Acked-by: Jiri Olsa <jolsa@redhat.com>

Thanks,
Namhyung

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


#1527262

FromNamhyung Kim <namhyung@kernel.org>
Date2016-11-22 08:10 +0100
Message-ID<sGdnk-3ZT-1@gated-at.bofh.it>
In reply to#1523247
Hi Arnaldo,

Could you please take a look at this?

Thanks,
Namhyung


On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> Hello,
> 
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good.  It seems David is busy
> these days, so I'm retrying it by myself.
> 
>  * changes in v2)
>   - change name 'b/n time' to 'wait time'  (Ingo)
>   - show arrow between functions in the callchain  (Ingo)
>   - fix a bug in calculating initial run time
>   
> This implements only basic feature and a few options.  I just split
> the patch to make it easier to review and did some cosmetic changes.
> More patches will come later.
> 
> The below is from the David's original description (w/ slight change):
> 
> ------------------------8<-------------------------
> 'perf sched timehist' provides an analysis of scheduling events.
> 
> Example usage:
>     perf sched record -- sleep 1
>     perf sched timehist
> 
> By default it shows the individual schedule events, including the time between
> sched-in events for the task, the task scheduling delay (time between wakeup
> and actually running) and run time for the task:
> 
>            time cpu  task name[tid/pid]   wait time sch delay  run time
>   ------------- ---- -------------------- --------- --------- ---------
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011
>    79371.874604 [11] <idle>                   1.148     0.000     0.035
>    79371.874723 [05] <idle>                   0.016     0.000     1.383
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022
> ...
> 
> Times are in msec.usec.
> 
> If callchains were recorded they are appended to the line with a default stack depth of 5:
> 
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148  wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024  __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011  smpboot_thread_fn <- kthread <- ret_from_fork
>    79371.874604 [11] <idle>                   1.148     0.000     0.035  cpu_startup_entry <- start_secondary
>    79371.874723 [05] <idle>                   0.016     0.000     1.383  cpu_startup_entry <- start_secondary
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022  do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
> 
> --no-call-graph can be used to not show the callchains. --max-stack is used
> to control the number of frames shown (default of 5). -x/--excl options can
> be used to collapse redundant callchains to get more relevant data on screen.
> 
> Similar to perf-trace -s and -S can be used to dump a statistical summary
> without or with events (respectively). Statistics include min run time,
> average run time and max run time. Stats are also shown for run time by
> cpu.
> 
> The cpu-visual option provides a visual aid for sched switches by cpu:
> ...
>    79371.874569 [11]            s      gcc[31949]                  0.014     0.000     1.148
>    79371.874591 [10]           s       gcc[31951]                  0.000     0.000     0.024
>    79371.874603 [10]           s       migration/10[59]            3.350     0.004     0.011
>    79371.874604 [11]            i      <idle>                      1.148     0.000     0.035
>    79371.874723 [05]      i            <idle>                      0.016     0.000     1.383
>    79371.874746 [05]      s            gcc[31949]                  0.153     0.078     0.022
> ...
> 
> ------------------------8<-------------------------
> 
> This code is available at 'perf/timehist-v2' branch in my tree
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
> 
> Any feedback is welcomed.
> 
> Thanks,
> Namhyung
> 
> 
> [1] https://lkml.org/lkml/2013/12/1/129
> 
> David Ahern (6):
>   perf sched timehist: Introduce timehist command
>   perf sched timehist: Add summary options
>   perf sched timehist: Add -w/--wakeups option
>   perf sched timehist: Add call graph options
>   perf sched timehist: Add -V/--cpu-visual option
>   perf sched: Add documentation for timehist options
> 
> Namhyung Kim (2):
>   perf symbol: Print symbol offsets conditionally
>   perf tools: Support printing callchains with arrows
> 
>  tools/perf/Documentation/perf-sched.txt |  46 +-
>  tools/perf/builtin-sched.c              | 914 +++++++++++++++++++++++++++++++-
>  tools/perf/util/evsel.h                 |   1 +
>  tools/perf/util/evsel_fprintf.c         |  12 +-
>  tools/perf/util/symbol.h                |   3 +-
>  tools/perf/util/symbol_fprintf.c        |  11 +-
>  6 files changed, 972 insertions(+), 15 deletions(-)
> 
> -- 
> 2.10.1
> 

[toc] | [prev] | [standalone]


Back to top | Article view | linux.kernel


csiph-web