[PATCH 1/3] perf sched timehist: Account thread wait time separately

[PATCH 1/3] perf sched timehist: Account thread wait time separately

[Namhyung Kim]

Separate thread wait time into 3 parts - sleep, iowait and preempt
based on the prev_state of the last event.

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 5b134b0d1ff3..0f2fdeebfd2e 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -77,6 +77,22 @@ struct sched_atom {
 
 #define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
 
+/* task state bitmask, copied from include/linux/sched.h */
+#define TASK_RUNNING		0
+#define TASK_INTERRUPTIBLE	1
+#define TASK_UNINTERRUPTIBLE	2
+#define __TASK_STOPPED		4
+#define __TASK_TRACED		8
+/* in tsk->exit_state */
+#define EXIT_DEAD		16
+#define EXIT_ZOMBIE		32
+#define EXIT_TRACE		(EXIT_ZOMBIE | EXIT_DEAD)
+/* in tsk->state again */
+#define TASK_DEAD		64
+#define TASK_WAKEKILL		128
+#define TASK_WAKING		256
+#define TASK_PARKED		512
+
 enum thread_state {
 	THREAD_SLEEPING = 0,
 	THREAD_WAIT_CPU,
@@ -216,13 +232,16 @@ struct perf_sched {
 struct thread_runtime {
 	u64 last_time;      /* time of previous sched in/out event */
 	u64 dt_run;         /* run time */
-	u64 dt_wait;        /* time between CPU access (off cpu) */
+	u64 dt_sleep;       /* time between CPU access by sleep (off cpu) */
+	u64 dt_iowait;      /* time between CPU access by iowait (off cpu) */
+	u64 dt_preempt;     /* time between CPU access by preempt (off cpu) */
 	u64 dt_delay;       /* time between wakeup and sched-in */
 	u64 ready_to_run;   /* time of wakeup */
 
 	struct stats run_stats;
 	u64 total_run_time;
 
+	int last_state;
 	u64 migrations;
 };
 
@@ -1858,6 +1877,7 @@ static void timehist_print_sample(struct perf_sched *sched,
 	struct thread_runtime *tr = thread__priv(thread);
 	u32 max_cpus = sched->max_cpu + 1;
 	char tstr[64];
+	u64 wait_time;
 
 	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
 	printf("%15s [%04d] ", tstr, sample->cpu);
@@ -1880,7 +1900,9 @@ static void timehist_print_sample(struct perf_sched *sched,
 
 	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
 
-	print_sched_time(tr->dt_wait, 6);
+	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
+	print_sched_time(wait_time, 6);
+
 	print_sched_time(tr->dt_delay, 6);
 	print_sched_time(tr->dt_run, 6);
 
@@ -1930,8 +1952,11 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 					 u64 t, u64 tprev)
 {
 	r->dt_delay   = 0;
-	r->dt_wait    = 0;
+	r->dt_sleep   = 0;
+	r->dt_iowait  = 0;
+	r->dt_preempt = 0;
 	r->dt_run     = 0;
+
 	if (tprev) {
 		r->dt_run = t - tprev;
 		if (r->ready_to_run) {
@@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 
 		if (r->last_time > tprev)
 			pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
-		else if (r->last_time)
-			r->dt_wait = tprev - r->last_time;
+		else if (r->last_time) {
+			u64 wait = tprev - r->last_time;
+
+			if (r->last_state == TASK_RUNNING)
+				r->dt_preempt = wait;
+			else if (r->last_state == TASK_UNINTERRUPTIBLE)
+				r->dt_iowait = wait;
+			else
+				r->dt_sleep = wait;
+		}
 	}
 
 	update_stats(&r->run_stats, r->dt_run);
@@ -2447,8 +2480,10 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 			 * time.  we only care total run time and run stat.
 			 */
 			last_tr->dt_run = 0;
-			last_tr->dt_wait = 0;
 			last_tr->dt_delay = 0;
+			last_tr->dt_sleep = 0;
+			last_tr->dt_iowait = 0;
+			last_tr->dt_preempt = 0;
 
 			if (itr->cursor.nr)
 				callchain_append(&itr->callchain, &itr->cursor, t - tprev);
@@ -2470,6 +2505,9 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 		/* time of this sched_switch event becomes last time task seen */
 		tr->last_time = sample->time;
 
+		/* last state is used to determine where to account wait time */
+		tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+
 		/* sched out event for task so reset ready to run time */
 		tr->ready_to_run = 0;
 	}
-- 
2.11.0

[PATCH 2/3] perf sched timehist: Add --state option

[Namhyung Kim]

The --state option is to show task state when switched out.  The state
is printed as a single character like in the /proc but I added 'I' for
idle state rather than 'R'.

  $ perf sched timehist --state | head
  Samples do not have callchains.
             time    cpu  task name                       wait time  sch delay   run time  state
                          [tid/pid]                          (msec)     (msec)     (msec)
  --------------- ------  ------------------------------  ---------  ---------  ---------  -----
    197731.753791 [0003]  <idle>                              0.000      0.000      0.000      I
    197731.753834 [0001]  perf[27469]                         0.000      0.000      0.000      S
    197731.753904 [0003]  perf[27470]                         0.000      0.006      0.112      S
    197731.753914 [0001]  <idle>                              0.000      0.000      0.079      I
    197731.753915 [0003]  migration/3[23]                     0.000      0.002      0.011      S
    197731.754287 [0002]  <idle>                              0.000      0.000      0.000      I
    197731.754335 [0002]  transmission-gt[17773/17739]        0.000      0.004      0.047      S

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

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 76173969ab80..d33deddb0146 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -143,6 +143,8 @@ OPTIONS for 'perf sched timehist'
 	stop time is not given (i.e, time string is 'x.y,') then analysis goes
 	to end of file.
 
+--state::
+	Show task state when it switched out.
 
 SEE ALSO
 --------
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 0f2fdeebfd2e..ec51494e660b 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -222,6 +222,7 @@ struct perf_sched {
 	bool		show_cpu_visual;
 	bool		show_wakeups;
 	bool		show_migrations;
+	bool		show_state;
 	u64		skipped_samples;
 	const char	*time_str;
 	struct perf_time_interval ptime;
@@ -1840,6 +1841,9 @@ static void timehist_header(struct perf_sched *sched)
 	printf(" %-*s  %9s  %9s  %9s", comm_width,
 		"task name", "wait time", "sch delay", "run time");
 
+	if (sched->show_state)
+		printf("  %s", "state");
+
 	printf("\n");
 
 	/*
@@ -1850,9 +1854,14 @@ static void timehist_header(struct perf_sched *sched)
 	if (sched->show_cpu_visual)
 		printf(" %*s ", ncpus, "");
 
-	printf(" %-*s  %9s  %9s  %9s\n", comm_width,
+	printf(" %-*s  %9s  %9s  %9s", comm_width,
 	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
 
+	if (sched->show_state)
+		printf("  %5s", "");
+
+	printf("\n");
+
 	/*
 	 * separator
 	 */
@@ -1865,14 +1874,29 @@ static void timehist_header(struct perf_sched *sched)
 		graph_dotted_line, graph_dotted_line, graph_dotted_line,
 		graph_dotted_line);
 
+	if (sched->show_state)
+		printf("  %.5s", graph_dotted_line);
+
 	printf("\n");
 }
 
+static char task_state_char(struct thread *thread, int state)
+{
+	static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
+	unsigned bit = state ? ffs(state) : 0;
+
+	/* 'I' for idle */
+	if (thread->tid == 0)
+		return 'I';
+
+	return bit < sizeof(state_to_char) - 1 ? state_to_char[bit] : '?';
+}
+
 static void timehist_print_sample(struct perf_sched *sched,
 				  struct perf_sample *sample,
 				  struct addr_location *al,
 				  struct thread *thread,
-				  u64 t)
+				  u64 t, int state)
 {
 	struct thread_runtime *tr = thread__priv(thread);
 	u32 max_cpus = sched->max_cpu + 1;
@@ -1906,6 +1930,9 @@ static void timehist_print_sample(struct perf_sched *sched,
 	print_sched_time(tr->dt_delay, 6);
 	print_sched_time(tr->dt_run, 6);
 
+	if (sched->show_state)
+		printf(" %5c ", task_state_char(thread, state));
+
 	if (sched->show_wakeups)
 		printf("  %-*s", comm_width, "");
 
@@ -2406,6 +2433,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	struct thread_runtime *tr = NULL;
 	u64 tprev, t = sample->time;
 	int rc = 0;
+	int state = perf_evsel__intval(evsel, sample, "prev_state");
+
 
 	if (machine__resolve(machine, &al, sample) < 0) {
 		pr_err("problem processing %d event. skipping it\n",
@@ -2493,7 +2522,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	}
 
 	if (!sched->summary_only)
-		timehist_print_sample(sched, sample, &al, thread, t);
+		timehist_print_sample(sched, sample, &al, thread, t, state);
 
 out:
 	if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -2506,7 +2535,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 		tr->last_time = sample->time;
 
 		/* last state is used to determine where to account wait time */
-		tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+		tr->last_state = state;
 
 		/* sched out event for task so reset ready to run time */
 		tr->ready_to_run = 0;
@@ -3278,6 +3307,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
 	OPT_STRING(0, "time", &sched.time_str, "str",
 		   "Time span for analysis (start,stop)"),
+	OPT_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
 	OPT_PARENT(sched_options)
 	};
 
-- 
2.11.0

[PATCH 3/3] perf sched timehist: Show total wait times for summary

[Namhyung Kim]

When --state option is given, the summary will show total run, sleep,
iowait, preempt and delay time instead of statistics of runtime.

  $ perf sched timehist -s --state

  Wait-time summary
                            comm  parent   sched-in     run-time      sleep      iowait     preempt       delay
                                            (count)       (msec)     (msec)      (msec)      (msec)       (msec)
  ---------------------------------------------------------------------------------------------------------------------
                      systemd[1]       0          3        0.497      1.685       0.000       0.000       0.061
                  ksoftirqd/0[3]       2         21        0.434    989.948       0.000       0.000       0.325
                  rcu_preempt[7]       2         28        0.386    993.211       0.000       0.000       0.712
                 migration/0[10]       2         12        0.126     50.174       0.000       0.000       0.044
                  watchdog/0[11]       2          1        0.009      0.000       0.000       0.000       0.016
                 migration/1[13]       2          2        0.029     11.755       0.000       0.000       0.007
  <SNIP>

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index ec51494e660b..abc58851452b 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -241,6 +241,10 @@ struct thread_runtime {
 
 	struct stats run_stats;
 	u64 total_run_time;
+	u64 total_sleep_time;
+	u64 total_iowait_time;
+	u64 total_preempt_time;
+	u64 total_delay_time;
 
 	int last_state;
 	u64 migrations;
@@ -2008,7 +2012,12 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 	}
 
 	update_stats(&r->run_stats, r->dt_run);
-	r->total_run_time += r->dt_run;
+
+	r->total_run_time     += r->dt_run;
+	r->total_delay_time   += r->dt_delay;
+	r->total_sleep_time   += r->dt_sleep;
+	r->total_iowait_time  += r->dt_iowait;
+	r->total_preempt_time += r->dt_preempt;
 }
 
 static bool is_idle_sample(struct perf_sample *sample,
@@ -2593,7 +2602,26 @@ static void print_thread_runtime(struct thread *t,
 	printf("\n");
 }
 
+static void print_thread_waittime(struct thread *t,
+				  struct thread_runtime *r)
+{
+	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);
+	print_sched_time(r->total_sleep_time, 6);
+	printf(" ");
+	print_sched_time(r->total_iowait_time, 6);
+	printf(" ");
+	print_sched_time(r->total_preempt_time, 6);
+	printf(" ");
+	print_sched_time(r->total_delay_time, 6);
+	printf("\n");
+}
+
 struct total_run_stats {
+	struct perf_sched *sched;
 	u64  sched_count;
 	u64  task_count;
 	u64  total_run_time;
@@ -2612,7 +2640,11 @@ static int __show_thread_runtime(struct thread *t, void *priv)
 		stats->task_count++;
 		stats->sched_count += r->run_stats.n;
 		stats->total_run_time += r->total_run_time;
-		print_thread_runtime(t, r);
+
+		if (stats->sched->show_state)
+			print_thread_waittime(t, r);
+		else
+			print_thread_runtime(t, r);
 	}
 
 	return 0;
@@ -2700,18 +2732,24 @@ static void timehist_print_summary(struct perf_sched *sched,
 	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
 
 	memset(&totals, 0, sizeof(totals));
+	totals.sched = sched;
 
 	if (sched->idle_hist) {
 		printf("\nIdle-time summary\n");
 		printf("%*s  parent  sched-out  ", comm_width, "comm");
 		printf("  idle-time   min-idle    avg-idle    max-idle  stddev  migrations\n");
+	} else if (sched->show_state) {
+		printf("\nWait-time summary\n");
+		printf("%*s  parent   sched-in  ", comm_width, "comm");
+		printf("   run-time      sleep      iowait     preempt       delay\n");
 	} else {
 		printf("\nRuntime summary\n");
 		printf("%*s  parent   sched-in  ", comm_width, "comm");
 		printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
 	}
 	printf("%*s            (count)  ", comm_width, "");
-	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
+	printf("     (msec)     (msec)      (msec)      (msec)       %s\n",
+	       sched->show_state ? "(msec)" : "%");
 	printf("%.117s\n", graph_dotted_line);
 
 	machine__for_each_thread(m, show_thread_runtime, &totals);
-- 
2.11.0

Re: [PATCH 1/3] perf sched timehist: Account thread wait time separately

[Arnaldo Carvalho de Melo]

Em Fri, Jan 13, 2017 at 07:45:21PM +0900, Namhyung Kim escreveu:
> Separate thread wait time into 3 parts - sleep, iowait and preempt
> based on the prev_state of the last event.

Thanks, looks good, tested and applied,

- Arnaldo
 
> Cc: David Ahern <dsahern@gmail.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-sched.c | 50 ++++++++++++++++++++++++++++++++++++++++------
>  1 file changed, 44 insertions(+), 6 deletions(-)
> 
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 5b134b0d1ff3..0f2fdeebfd2e 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -77,6 +77,22 @@ struct sched_atom {
>  
>  #define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
>  
> +/* task state bitmask, copied from include/linux/sched.h */
> +#define TASK_RUNNING		0
> +#define TASK_INTERRUPTIBLE	1
> +#define TASK_UNINTERRUPTIBLE	2
> +#define __TASK_STOPPED		4
> +#define __TASK_TRACED		8
> +/* in tsk->exit_state */
> +#define EXIT_DEAD		16
> +#define EXIT_ZOMBIE		32
> +#define EXIT_TRACE		(EXIT_ZOMBIE | EXIT_DEAD)
> +/* in tsk->state again */
> +#define TASK_DEAD		64
> +#define TASK_WAKEKILL		128
> +#define TASK_WAKING		256
> +#define TASK_PARKED		512
> +
>  enum thread_state {
>  	THREAD_SLEEPING = 0,
>  	THREAD_WAIT_CPU,
> @@ -216,13 +232,16 @@ struct perf_sched {
>  struct thread_runtime {
>  	u64 last_time;      /* time of previous sched in/out event */
>  	u64 dt_run;         /* run time */
> -	u64 dt_wait;        /* time between CPU access (off cpu) */
> +	u64 dt_sleep;       /* time between CPU access by sleep (off cpu) */
> +	u64 dt_iowait;      /* time between CPU access by iowait (off cpu) */
> +	u64 dt_preempt;     /* time between CPU access by preempt (off cpu) */
>  	u64 dt_delay;       /* time between wakeup and sched-in */
>  	u64 ready_to_run;   /* time of wakeup */
>  
>  	struct stats run_stats;
>  	u64 total_run_time;
>  
> +	int last_state;
>  	u64 migrations;
>  };
>  
> @@ -1858,6 +1877,7 @@ static void timehist_print_sample(struct perf_sched *sched,
>  	struct thread_runtime *tr = thread__priv(thread);
>  	u32 max_cpus = sched->max_cpu + 1;
>  	char tstr[64];
> +	u64 wait_time;
>  
>  	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
>  	printf("%15s [%04d] ", tstr, sample->cpu);
> @@ -1880,7 +1900,9 @@ static void timehist_print_sample(struct perf_sched *sched,
>  
>  	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
>  
> -	print_sched_time(tr->dt_wait, 6);
> +	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
> +	print_sched_time(wait_time, 6);
> +
>  	print_sched_time(tr->dt_delay, 6);
>  	print_sched_time(tr->dt_run, 6);
>  
> @@ -1930,8 +1952,11 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
>  					 u64 t, u64 tprev)
>  {
>  	r->dt_delay   = 0;
> -	r->dt_wait    = 0;
> +	r->dt_sleep   = 0;
> +	r->dt_iowait  = 0;
> +	r->dt_preempt = 0;
>  	r->dt_run     = 0;
> +
>  	if (tprev) {
>  		r->dt_run = t - tprev;
>  		if (r->ready_to_run) {
> @@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
>  
>  		if (r->last_time > tprev)
>  			pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
> -		else if (r->last_time)
> -			r->dt_wait = tprev - r->last_time;
> +		else if (r->last_time) {
> +			u64 wait = tprev - r->last_time;
> +
> +			if (r->last_state == TASK_RUNNING)
> +				r->dt_preempt = wait;
> +			else if (r->last_state == TASK_UNINTERRUPTIBLE)
> +				r->dt_iowait = wait;
> +			else
> +				r->dt_sleep = wait;
> +		}
>  	}
>  
>  	update_stats(&r->run_stats, r->dt_run);
> @@ -2447,8 +2480,10 @@ static int timehist_sched_change_event(struct perf_tool *tool,
>  			 * time.  we only care total run time and run stat.
>  			 */
>  			last_tr->dt_run = 0;
> -			last_tr->dt_wait = 0;
>  			last_tr->dt_delay = 0;
> +			last_tr->dt_sleep = 0;
> +			last_tr->dt_iowait = 0;
> +			last_tr->dt_preempt = 0;
>  
>  			if (itr->cursor.nr)
>  				callchain_append(&itr->callchain, &itr->cursor, t - tprev);
> @@ -2470,6 +2505,9 @@ static int timehist_sched_change_event(struct perf_tool *tool,
>  		/* time of this sched_switch event becomes last time task seen */
>  		tr->last_time = sample->time;
>  
> +		/* last state is used to determine where to account wait time */
> +		tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
> +
>  		/* sched out event for task so reset ready to run time */
>  		tr->ready_to_run = 0;
>  	}
> -- 
> 2.11.0

Re: [PATCH 1/3] perf sched timehist: Account thread wait time separately

[Arnaldo Carvalho de Melo]

Em Fri, Jan 13, 2017 at 07:45:21PM +0900, Namhyung Kim escreveu:
> @@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
>  
>  		if (r->last_time > tprev)
>  			pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
> -		else if (r->last_time)
> -			r->dt_wait = tprev - r->last_time;
> +		else if (r->last_time) {
> +			u64 wait = tprev - r->last_time;
> +
> +			if (r->last_state == TASK_RUNNING)
> +				r->dt_preempt = wait;
> +			else if (r->last_state == TASK_UNINTERRUPTIBLE)
> +				r->dt_iowait = wait;
> +			else
> +				r->dt_sleep = wait;
> +		}

s/wait/dt_wait/g to fix the build on older distros where 'wait' shadows
a global declaration.

- Arnaldo

[tip:perf/core] perf sched timehist: Account thread wait time separately

[tip-bot for Namhyung Kim]

Commit-ID:  941bdea79e194dec7e7b42780aa5620020548f8a
Gitweb:     http://git.kernel.org/tip/941bdea79e194dec7e7b42780aa5620020548f8a
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:21 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:35:44 -0300

perf sched timehist: Account thread wait time separately

Separate thread wait time into 3 parts - sleep, iowait and preempt based
on the prev_state of the last event.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-1-namhyung@kernel.org
[ Fix the build on centos:5 where 'wait' shadows a global declaration ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 50 ++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 44 insertions(+), 6 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 5b134b0..6d3c3e8 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -77,6 +77,22 @@ struct sched_atom {
 
 #define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
 
+/* task state bitmask, copied from include/linux/sched.h */
+#define TASK_RUNNING		0
+#define TASK_INTERRUPTIBLE	1
+#define TASK_UNINTERRUPTIBLE	2
+#define __TASK_STOPPED		4
+#define __TASK_TRACED		8
+/* in tsk->exit_state */
+#define EXIT_DEAD		16
+#define EXIT_ZOMBIE		32
+#define EXIT_TRACE		(EXIT_ZOMBIE | EXIT_DEAD)
+/* in tsk->state again */
+#define TASK_DEAD		64
+#define TASK_WAKEKILL		128
+#define TASK_WAKING		256
+#define TASK_PARKED		512
+
 enum thread_state {
 	THREAD_SLEEPING = 0,
 	THREAD_WAIT_CPU,
@@ -216,13 +232,16 @@ struct perf_sched {
 struct thread_runtime {
 	u64 last_time;      /* time of previous sched in/out event */
 	u64 dt_run;         /* run time */
-	u64 dt_wait;        /* time between CPU access (off cpu) */
+	u64 dt_sleep;       /* time between CPU access by sleep (off cpu) */
+	u64 dt_iowait;      /* time between CPU access by iowait (off cpu) */
+	u64 dt_preempt;     /* time between CPU access by preempt (off cpu) */
 	u64 dt_delay;       /* time between wakeup and sched-in */
 	u64 ready_to_run;   /* time of wakeup */
 
 	struct stats run_stats;
 	u64 total_run_time;
 
+	int last_state;
 	u64 migrations;
 };
 
@@ -1858,6 +1877,7 @@ static void timehist_print_sample(struct perf_sched *sched,
 	struct thread_runtime *tr = thread__priv(thread);
 	u32 max_cpus = sched->max_cpu + 1;
 	char tstr[64];
+	u64 wait_time;
 
 	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
 	printf("%15s [%04d] ", tstr, sample->cpu);
@@ -1880,7 +1900,9 @@ static void timehist_print_sample(struct perf_sched *sched,
 
 	printf(" %-*s ", comm_width, timehist_get_commstr(thread));
 
-	print_sched_time(tr->dt_wait, 6);
+	wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
+	print_sched_time(wait_time, 6);
+
 	print_sched_time(tr->dt_delay, 6);
 	print_sched_time(tr->dt_run, 6);
 
@@ -1930,8 +1952,11 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 					 u64 t, u64 tprev)
 {
 	r->dt_delay   = 0;
-	r->dt_wait    = 0;
+	r->dt_sleep   = 0;
+	r->dt_iowait  = 0;
+	r->dt_preempt = 0;
 	r->dt_run     = 0;
+
 	if (tprev) {
 		r->dt_run = t - tprev;
 		if (r->ready_to_run) {
@@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 
 		if (r->last_time > tprev)
 			pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
-		else if (r->last_time)
-			r->dt_wait = tprev - r->last_time;
+		else if (r->last_time) {
+			u64 dt_wait = tprev - r->last_time;
+
+			if (r->last_state == TASK_RUNNING)
+				r->dt_preempt = dt_wait;
+			else if (r->last_state == TASK_UNINTERRUPTIBLE)
+				r->dt_iowait = dt_wait;
+			else
+				r->dt_sleep = dt_wait;
+		}
 	}
 
 	update_stats(&r->run_stats, r->dt_run);
@@ -2447,8 +2480,10 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 			 * time.  we only care total run time and run stat.
 			 */
 			last_tr->dt_run = 0;
-			last_tr->dt_wait = 0;
 			last_tr->dt_delay = 0;
+			last_tr->dt_sleep = 0;
+			last_tr->dt_iowait = 0;
+			last_tr->dt_preempt = 0;
 
 			if (itr->cursor.nr)
 				callchain_append(&itr->callchain, &itr->cursor, t - tprev);
@@ -2470,6 +2505,9 @@ out:
 		/* time of this sched_switch event becomes last time task seen */
 		tr->last_time = sample->time;
 
+		/* last state is used to determine where to account wait time */
+		tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+
 		/* sched out event for task so reset ready to run time */
 		tr->ready_to_run = 0;
 	}

[tip:perf/core] perf sched timehist: Add --state option

[tip-bot for Namhyung Kim]

Commit-ID:  414e050c68ec2a3dd815544ea48ff6016f1a7a11
Gitweb:     http://git.kernel.org/tip/414e050c68ec2a3dd815544ea48ff6016f1a7a11
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:22 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:36:44 -0300

perf sched timehist: Add --state option

The --state option is to show task state when switched out.  The state
is printed as a single character like in the /proc but I added 'I' for
idle state rather than 'R'.

  $ perf sched timehist --state | head
  Samples do not have callchains.
      time cpu task name              wait time sch delay run time state
               [tid/pid]                 (msec)    (msec)   (msec)
  -------- --- ----------------------- -------- ------------------ -----
  1.753791 [3] <idle>                     0.000     0.000    0.000     I
  1.753834 [1] perf[27469]                0.000     0.000    0.000     S
  1.753904 [3] perf[27470]                0.000     0.006    0.112     S
  1.753914 [1] <idle>                     0.000     0.000    0.079     I
  1.753915 [3] migration/3[23]            0.000     0.002    0.011     S
  1.754287 [2] <idle>                     0.000     0.000    0.000     I
  1.754335 [2] transmission[1773/1739]    0.000     0.004    0.047     S

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-2-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/Documentation/perf-sched.txt |  2 ++
 tools/perf/builtin-sched.c              | 38 +++++++++++++++++++++++++++++----
 2 files changed, 36 insertions(+), 4 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 7617396..d33dedd 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -143,6 +143,8 @@ OPTIONS for 'perf sched timehist'
 	stop time is not given (i.e, time string is 'x.y,') then analysis goes
 	to end of file.
 
+--state::
+	Show task state when it switched out.
 
 SEE ALSO
 --------
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 6d3c3e8..a8ac766 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -222,6 +222,7 @@ struct perf_sched {
 	bool		show_cpu_visual;
 	bool		show_wakeups;
 	bool		show_migrations;
+	bool		show_state;
 	u64		skipped_samples;
 	const char	*time_str;
 	struct perf_time_interval ptime;
@@ -1840,6 +1841,9 @@ static void timehist_header(struct perf_sched *sched)
 	printf(" %-*s  %9s  %9s  %9s", comm_width,
 		"task name", "wait time", "sch delay", "run time");
 
+	if (sched->show_state)
+		printf("  %s", "state");
+
 	printf("\n");
 
 	/*
@@ -1850,9 +1854,14 @@ static void timehist_header(struct perf_sched *sched)
 	if (sched->show_cpu_visual)
 		printf(" %*s ", ncpus, "");
 
-	printf(" %-*s  %9s  %9s  %9s\n", comm_width,
+	printf(" %-*s  %9s  %9s  %9s", comm_width,
 	       "[tid/pid]", "(msec)", "(msec)", "(msec)");
 
+	if (sched->show_state)
+		printf("  %5s", "");
+
+	printf("\n");
+
 	/*
 	 * separator
 	 */
@@ -1865,14 +1874,29 @@ static void timehist_header(struct perf_sched *sched)
 		graph_dotted_line, graph_dotted_line, graph_dotted_line,
 		graph_dotted_line);
 
+	if (sched->show_state)
+		printf("  %.5s", graph_dotted_line);
+
 	printf("\n");
 }
 
+static char task_state_char(struct thread *thread, int state)
+{
+	static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
+	unsigned bit = state ? ffs(state) : 0;
+
+	/* 'I' for idle */
+	if (thread->tid == 0)
+		return 'I';
+
+	return bit < sizeof(state_to_char) - 1 ? state_to_char[bit] : '?';
+}
+
 static void timehist_print_sample(struct perf_sched *sched,
 				  struct perf_sample *sample,
 				  struct addr_location *al,
 				  struct thread *thread,
-				  u64 t)
+				  u64 t, int state)
 {
 	struct thread_runtime *tr = thread__priv(thread);
 	u32 max_cpus = sched->max_cpu + 1;
@@ -1906,6 +1930,9 @@ static void timehist_print_sample(struct perf_sched *sched,
 	print_sched_time(tr->dt_delay, 6);
 	print_sched_time(tr->dt_run, 6);
 
+	if (sched->show_state)
+		printf(" %5c ", task_state_char(thread, state));
+
 	if (sched->show_wakeups)
 		printf("  %-*s", comm_width, "");
 
@@ -2406,6 +2433,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	struct thread_runtime *tr = NULL;
 	u64 tprev, t = sample->time;
 	int rc = 0;
+	int state = perf_evsel__intval(evsel, sample, "prev_state");
+
 
 	if (machine__resolve(machine, &al, sample) < 0) {
 		pr_err("problem processing %d event. skipping it\n",
@@ -2493,7 +2522,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	}
 
 	if (!sched->summary_only)
-		timehist_print_sample(sched, sample, &al, thread, t);
+		timehist_print_sample(sched, sample, &al, thread, t, state);
 
 out:
 	if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -2506,7 +2535,7 @@ out:
 		tr->last_time = sample->time;
 
 		/* last state is used to determine where to account wait time */
-		tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+		tr->last_state = state;
 
 		/* sched out event for task so reset ready to run time */
 		tr->ready_to_run = 0;
@@ -3278,6 +3307,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
 	OPT_STRING(0, "time", &sched.time_str, "str",
 		   "Time span for analysis (start,stop)"),
+	OPT_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
 	OPT_PARENT(sched_options)
 	};
 

[tip:perf/core] perf sched timehist: Show total wait times for summary

[tip-bot for Namhyung Kim]

Commit-ID:  587782c52a83b35673201fd9a54364fa2b189b33
Gitweb:     http://git.kernel.org/tip/587782c52a83b35673201fd9a54364fa2b189b33
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:23 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:36:44 -0300

perf sched timehist: Show total wait times for summary

When --state option is given, the summary will show total run, sleep,
iowait, preempt and delay time instead of statistics of runtime.

  $ perf sched timehist -s --state

  Wait-time summary
            comm  parent sched-in run-time  sleep iowait preempt delay
                          (count)   (msec) (msec) (msec)  (msec) (msec)
  ---------------------------------------------------------------------
       systemd[1]      0        3    0.497   1.685 0.000   0.000 0.061
   ksoftirqd/0[3]      2       21    0.434 989.948 0.000   0.000 0.325
   rcu_preempt[7]      2       28    0.386 993.211 0.000   0.000 0.712
  migration/0[10]      2       12    0.126  50.174 0.000   0.000 0.044
   watchdog/0[11]      2        1    0.009   0.000 0.000   0.000 0.016
  migration/1[13]      2        2    0.029  11.755 0.000   0.000 0.007
  <SNIP>

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 44 +++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 41 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index a8ac766..daceb32 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -241,6 +241,10 @@ struct thread_runtime {
 
 	struct stats run_stats;
 	u64 total_run_time;
+	u64 total_sleep_time;
+	u64 total_iowait_time;
+	u64 total_preempt_time;
+	u64 total_delay_time;
 
 	int last_state;
 	u64 migrations;
@@ -2008,7 +2012,12 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 	}
 
 	update_stats(&r->run_stats, r->dt_run);
-	r->total_run_time += r->dt_run;
+
+	r->total_run_time     += r->dt_run;
+	r->total_delay_time   += r->dt_delay;
+	r->total_sleep_time   += r->dt_sleep;
+	r->total_iowait_time  += r->dt_iowait;
+	r->total_preempt_time += r->dt_preempt;
 }
 
 static bool is_idle_sample(struct perf_sample *sample,
@@ -2593,7 +2602,26 @@ static void print_thread_runtime(struct thread *t,
 	printf("\n");
 }
 
+static void print_thread_waittime(struct thread *t,
+				  struct thread_runtime *r)
+{
+	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);
+	print_sched_time(r->total_sleep_time, 6);
+	printf(" ");
+	print_sched_time(r->total_iowait_time, 6);
+	printf(" ");
+	print_sched_time(r->total_preempt_time, 6);
+	printf(" ");
+	print_sched_time(r->total_delay_time, 6);
+	printf("\n");
+}
+
 struct total_run_stats {
+	struct perf_sched *sched;
 	u64  sched_count;
 	u64  task_count;
 	u64  total_run_time;
@@ -2612,7 +2640,11 @@ static int __show_thread_runtime(struct thread *t, void *priv)
 		stats->task_count++;
 		stats->sched_count += r->run_stats.n;
 		stats->total_run_time += r->total_run_time;
-		print_thread_runtime(t, r);
+
+		if (stats->sched->show_state)
+			print_thread_waittime(t, r);
+		else
+			print_thread_runtime(t, r);
 	}
 
 	return 0;
@@ -2700,18 +2732,24 @@ static void timehist_print_summary(struct perf_sched *sched,
 	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
 
 	memset(&totals, 0, sizeof(totals));
+	totals.sched = sched;
 
 	if (sched->idle_hist) {
 		printf("\nIdle-time summary\n");
 		printf("%*s  parent  sched-out  ", comm_width, "comm");
 		printf("  idle-time   min-idle    avg-idle    max-idle  stddev  migrations\n");
+	} else if (sched->show_state) {
+		printf("\nWait-time summary\n");
+		printf("%*s  parent   sched-in  ", comm_width, "comm");
+		printf("   run-time      sleep      iowait     preempt       delay\n");
 	} else {
 		printf("\nRuntime summary\n");
 		printf("%*s  parent   sched-in  ", comm_width, "comm");
 		printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
 	}
 	printf("%*s            (count)  ", comm_width, "");
-	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
+	printf("     (msec)     (msec)      (msec)      (msec)       %s\n",
+	       sched->show_state ? "(msec)" : "%");
 	printf("%.117s\n", graph_dotted_line);
 
 	machine__for_each_thread(m, show_thread_runtime, &totals);