perf sched timehist: Enlarge default comm_width
Namhyung Kim
maintainerPATCH 1/3 perf sched timehist: Enlarge default comm_width
Current default value is 20 but it's easily changed to a bigger value as task has a long name and different tid and pid. And it makes the output not aligned. So change it to have a large value as summary shows.
--- tools/perf/builtin-sched.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-)
tools/perf/builtin-sched.c +5 -7
@@ -1775,7 +1775,7 @@ static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)return r->last_time[cpu]; } -static int comm_width =20 ; +static int comm_width =30 ;static char *timehist_get_commstr (struct thread *thread) {
@@ -1817,7 +1817,7 @@ static void timehist_header(struct perf_sched *sched)printf (" " ); } -printf (" %-20s %9s %9s %9s" , +printf (" %-*s %9s %9s %9s" , comm_width,"task name" ,"wait time" ,"sch delay" ,"run time" );printf ("\n" );
@@ -1830,7 +1830,8 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %*s " , ncpus,"" ); -printf (" %-20s %9s %9s %9s\n" ,"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" ); +printf (" %-*s %9s %9s %9s\n" , comm_width, +"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" );/* * separator
@@ -1840,7 +1841,7 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %.*s " , ncpus, graph_dotted_line); -printf (" %.20s %.9s %.9s %.9s" , +printf (" %.*s %.9s %.9s %.9s" , comm_width, graph_dotted_line, graph_dotted_line, graph_dotted_line, graph_dotted_line);
@@ -2626,9 +2627,6 @@ static void timehist_print_summary(struct perf_sched *sched,memset (&totals,0 ,sizeof (totals)); -if (comm_width <30 ) - comm_width =30 ; -if (sched->idle_hist) {printf ("\nIdle-time summary\n" );printf ("%*s parent sched-out " , comm_width,"comm" );
Signature · 1 line
2.10.0
Namhyung Kim
maintainerPATCH 2/3 perf sched timehist: Fix invalid period calculation
When --time option is given with a value outside recorded time, the last sample time (tprev) was set to that value and run time calculation might be incorrect. This is a problem of the first samples for each cpus since it would skip the runtime update when tprev is 0. But with --time option it had non-zero (which is invalid) value so the calculation is also incorrect.
For example, let's see the followging:
$ perf sched timehist
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- ---------
3195.968367 [0003] <idle> 0.000 0.000 0.000
3195.968386 [0002] Timer[4306/4277] 0.000 0.000 0.018
3195.968397 [0002] Web Content[4277] 0.000 0.000 0.000
3195.968595 [0001] JS Helper[4302/4277] 0.000 0.000 0.000
3195.969217 [0000] <idle> 0.000 0.000 0.621
3195.969251 [0001] kworker/1:1H[291] 0.000 0.000 0.033The sample starts at 3195.968367 but when I gave a time interval from 3194 to 3196 (in sec) it will calculate the whole 2 second as runtime. In below, 2 cpus accounted it as runtime, other 2 cpus accounted it as idle time.
Before:
$ perf sched timehist --time 3194,3196 -s | tail
Idle stats:
CPU 0 idle for 1995.991 msec
CPU 1 idle for 20.793 msec
CPU 2 idle for 30.191 msec
CPU 3 idle for 1999.852 msec Total number of unique tasks: 23
Total number of context switches: 128
Total run time (msec): 3724.940
After:
$ perf sched timehist --time 3194,3196 -s | tail
Idle stats:
CPU 0 idle for 10.811 msec
CPU 1 idle for 20.793 msec
CPU 2 idle for 30.191 msec
CPU 3 idle for 18.337 msec Total number of unique tasks: 23
Total number of context switches: 128
Total run time (msec): 18.139
--- tools/perf/builtin-sched.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
tools/perf/builtin-sched.c +1 -1
@@ -2405,7 +2405,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,if (ptime->start && ptime->start > t) goto out; -if (ptime->start > tprev) +if (tprev && ptime->start > tprev) tprev = ptime->start;/*
Signature · 1 line
2.10.0
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Fix invalid period calculation
perf sched timehist: Fix invalid period calculation
Commit-ID: bdd75729e5d279d734e8d3fb41ef4818ac1598ab Gitweb: http://git.kernel.org/tip/bdd75729e5d279d734e8d3fb41ef4818ac1598ab Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 22 Dec 2016 15:03:49 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 22 Dec 2016 16:35:46 -0300
perf sched timehist: Fix invalid period calculation
When --time option is given with a value outside recorded time, the last sample time (tprev) was set to that value and run time calculation might be incorrect. This is a problem of the first samples for each cpus since it would skip the runtime update when tprev is 0. But with --time option it had non-zero (which is invalid) value so the calculation is also incorrect.
For example, let's see the followging:
$ perf sched timehist
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- ---------
3195.968367 [0003] <idle> 0.000 0.000 0.000
3195.968386 [0002] Timer[4306/4277] 0.000 0.000 0.018
3195.968397 [0002] Web Content[4277] 0.000 0.000 0.000
3195.968595 [0001] JS Helper[4302/4277] 0.000 0.000 0.000
3195.969217 [0000] <idle> 0.000 0.000 0.621
3195.969251 [0001] kworker/1:1H[291] 0.000 0.000 0.033The sample starts at 3195.968367 but when I gave a time interval from 3194 to 3196 (in sec) it will calculate the whole 2 second as runtime. In below, 2 cpus accounted it as runtime, other 2 cpus accounted it as idle time.
Before:
$ perf sched timehist --time 3194,3196 -s | tail
Idle stats:
CPU 0 idle for 1995.991 msec
CPU 1 idle for 20.793 msec
CPU 2 idle for 30.191 msec
CPU 3 idle for 1999.852 msec Total number of unique tasks: 23
Total number of context switches: 128
Total run time (msec): 3724.940
After:
$ perf sched timehist --time 3194,3196 -s | tail
Idle stats:
CPU 0 idle for 10.811 msec
CPU 1 idle for 20.793 msec
CPU 2 idle for 30.191 msec
CPU 3 idle for 18.337 msec Total number of unique tasks: 23
Total number of context switches: 128
Total run time (msec): 18.139
Committer notes:
Further testing:
Before:
Idle stats:
CPU 0 idle for 229.785 msec
CPU 1 idle for 937.944 msec
CPU 2 idle for 188.931 msec
CPU 3 idle for 986.185 msecAfter:
# perf sched timehist --time 40602,40603 -s | tail
Idle stats:
CPU 0 idle for 229.785 msec
CPU 1 idle for 175.407 msec
CPU 2 idle for 188.931 msec
CPU 3 idle for 223.657 msec Total number of unique tasks: 68
Total number of context switches: 814
Total run time (msec): 97.688
# for cpu in `seq 0 3` ; do echo -n "CPU $cpu idle for " ; perf sched timehist --time 40602,40603 | grep "\[000${cpu}\].*\<idle\>" | tr -s ' ' | cut -d' ' -f7 | awk '{entries++ ; s+=$1} END {print s " msec (entries: " entries ")"}' ; done
CPU 0 idle for 229.721 msec (entries: 123)
CPU 1 idle for 175.381 msec (entries: 65)
CPU 2 idle for 188.903 msec (entries: 56)
CPU 3 idle for 223.61 msec (entries: 102)Difference due to the idle stats being accounted at nanoseconds precision while the <idle> entries in 'perf sched timehist' are trucated at msec.usec.
--- tools/perf/builtin-sched.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
tools/perf/builtin-sched.c +1 -1
@@ -2405,7 +2405,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,if (ptime->start && ptime->start > t) goto out; -if (ptime->start > tprev) +if (tprev && ptime->start > tprev) tprev = ptime->start;/*
Namhyung Kim
maintainerPATCH 3/3 perf sched timehist: Show total scheduling time
In reply to Namhyung KimShow length of analyzed sample time and rate of idle task running. This also takes care of time range given by --time option.
$ perf sched timehist -sI | tail
Samples do not have callchains.
Idle stats:
CPU 0 idle for 930.316 msec ( 92.93%)
CPU 1 idle for 963.614 msec ( 96.25%)
CPU 2 idle for 885.482 msec ( 88.45%)
CPU 3 idle for 938.635 msec ( 93.76%) Total number of unique tasks: 118
Total number of context switches: 2337
Total run time (msec): 3718.048
Total scheduling time (msec): 1001.131 (x 4)--- tools/perf/builtin-sched.c | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-)
tools/perf/builtin-sched.c +14 -3
@@ -209,6 +209,7 @@ struct perf_sched {u64 skipped_samples;const char *time_str;struct perf_time_interval ptime; +struct perf_time_interval hist_time; };/* per thread run time data */
@@ -2460,6 +2461,11 @@ static int timehist_sched_change_event(struct perf_tool *tool,timehist_print_sample (sched, sample, &al, thread, t); out: +if (sched->hist_time.start ==0 && t >= ptime->start) + sched->hist_time.start = t; +if (ptime->end ==0 || t <= ptime->end) + sched->hist_time.end = t; +if (tr) {/* time of this sched_switch event becomes last time task seen */ tr->last_time = sample->time;
@@ -2624,6 +2630,7 @@ static void timehist_print_summary(struct perf_sched *sched,struct thread *t;struct thread_runtime *r;int i; +u64 hist_time = sched->hist_time.end - sched->hist_time.start;memset (&totals,0 ,sizeof (totals));
@@ -2665,7 +2672,7 @@ static void timehist_print_summary(struct perf_sched *sched, totals.sched_count += r->run_stats.n;printf (" CPU %2d idle for " , i);print_sched_time (r->total_run_time,6 ); -printf (" msec\n" ); +printf (" msec (%6.2f%%)\n" ,100.0 * r->total_run_time / hist_time); }else printf (" CPU %2d idle entire time window\n" , i); }
@@ -2701,12 +2708,16 @@ static void timehist_print_summary(struct perf_sched *sched,printf ("\n" " Total number of unique tasks: %" PRIu64"\n" -"Total number of context switches: %" PRIu64"\n" -" Total run time (msec): " , +"Total number of context switches: %" PRIu64"\n" , totals.task_count, totals.sched_count); +printf (" Total run time (msec): " );print_sched_time (totals.total_run_time,2 );printf ("\n" ); + +printf (" Total scheduling time (msec): " ); +print_sched_time (hist_time,2 ); +printf (" (x %d)\n" , sched->max_cpu); } typedef int (*sched_handler)(struct perf_tool *tool,
Signature · 1 line
2.10.0
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Show total scheduling time
perf sched timehist: Show total scheduling time
Commit-ID: 9396c9cb0d9534ca67bda8a34b2413a2ca1c67e9 Gitweb: http://git.kernel.org/tip/9396c9cb0d9534ca67bda8a34b2413a2ca1c67e9 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 22 Dec 2016 15:03:50 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Tue, 27 Dec 2016 21:47:57 -0300
perf sched timehist: Show total scheduling time
Show length of analyzed sample time and rate of idle task running. This also takes care of time range given by --time option.
$ perf sched timehist -sI | tail
Samples do not have callchains.
Idle stats:
CPU 0 idle for 930.316 msec ( 92.93%)
CPU 1 idle for 963.614 msec ( 96.25%)
CPU 2 idle for 885.482 msec ( 88.45%)
CPU 3 idle for 938.635 msec ( 93.76%) Total number of unique tasks: 118
Total number of context switches: 2337
Total run time (msec): 3718.048
Total scheduling time (msec): 1001.131 (x 4)--- tools/perf/builtin-sched.c | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-)
tools/perf/builtin-sched.c +14 -3
@@ -209,6 +209,7 @@ struct perf_sched {u64 skipped_samples;const char *time_str;struct perf_time_interval ptime; +struct perf_time_interval hist_time; };/* per thread run time data */
@@ -2460,6 +2461,11 @@ static int timehist_sched_change_event(struct perf_tool *tool,timehist_print_sample (sched, sample, &al, thread, t); out: +if (sched->hist_time.start ==0 && t >= ptime->start) + sched->hist_time.start = t; +if (ptime->end ==0 || t <= ptime->end) + sched->hist_time.end = t; +if (tr) {/* time of this sched_switch event becomes last time task seen */ tr->last_time = sample->time;
@@ -2624,6 +2630,7 @@ static void timehist_print_summary(struct perf_sched *sched,struct thread *t;struct thread_runtime *r;int i; +u64 hist_time = sched->hist_time.end - sched->hist_time.start;memset (&totals,0 ,sizeof (totals));
@@ -2665,7 +2672,7 @@ static void timehist_print_summary(struct perf_sched *sched, totals.sched_count += r->run_stats.n;printf (" CPU %2d idle for " , i);print_sched_time (r->total_run_time,6 ); -printf (" msec\n" ); +printf (" msec (%6.2f%%)\n" ,100.0 * r->total_run_time / hist_time); }else printf (" CPU %2d idle entire time window\n" , i); }
@@ -2701,12 +2708,16 @@ static void timehist_print_summary(struct perf_sched *sched,printf ("\n" " Total number of unique tasks: %" PRIu64"\n" -"Total number of context switches: %" PRIu64"\n" -" Total run time (msec): " , +"Total number of context switches: %" PRIu64"\n" , totals.task_count, totals.sched_count); +printf (" Total run time (msec): " );print_sched_time (totals.total_run_time,2 );printf ("\n" ); + +printf (" Total scheduling time (msec): " ); +print_sched_time (hist_time,2 ); +printf (" (x %d)\n" , sched->max_cpu); } typedef int (*sched_handler)(struct perf_tool *tool,
Arnaldo Carvalho de Melo
maintainerEm Thu, Dec 22, 2016 at 03:03:48PM +0900, Namhyung Kim escreveu:
Quoted 3 lines
Current default value is 20 but it's easily changed to a bigger value as task has a long name and different tid and pid. And it makes the output not aligned. So change it to have a large value as summary shows.
So you're doing multiple things here:
1) making more places honour the comm_width (header)
2) changing its default from 20 to 30 and due to this, removing the setting to 30 done at timehist_print_summary
I'll break it into two to reflect that.
- Arnaldo
Quoted 58 lines
Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-)tools/perf/builtin-sched.c +5
-7@@ -1775,7 +1775,7 @@ static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)return r->last_time[cpu]; } -static int comm_width =20 ; +static int comm_width =30 ;static char *timehist_get_commstr (struct thread *thread) {@@ -1817,7 +1817,7 @@ static void timehist_header(struct perf_sched *sched)printf (" " ); } -printf (" %-20s %9s %9s %9s" , +printf (" %-*s %9s %9s %9s" , comm_width,"task name" ,"wait time" ,"sch delay" ,"run time" );printf ("\n" );@@ -1830,7 +1830,8 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %*s " , ncpus,"" ); -printf (" %-20s %9s %9s %9s\n" ,"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" ); +printf (" %-*s %9s %9s %9s\n" , comm_width, +"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" );/* * separator @@ -1840,7 +1841,7 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %.*s " , ncpus, graph_dotted_line); -printf (" %.20s %.9s %.9s %.9s" , +printf (" %.*s %.9s %.9s %.9s" , comm_width, graph_dotted_line, graph_dotted_line, graph_dotted_line, graph_dotted_line);@@ -2626,9 +2627,6 @@ static void timehist_print_summary(struct perf_sched *sched,memset (&totals,0 ,sizeof (totals)); -if (comm_width <30 ) - comm_width =30 ; -if (sched->idle_hist) {printf ("\nIdle-time summary\n" );printf ("%*s parent sched-out " , comm_width,"comm" );Signature · 1 line
2.10.0
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Enlarge default 'comm_width'
In reply to Namhyung Kimperf sched timehist: Enlarge default 'comm_width'
Commit-ID: 9b8087d72086b249ff744cee237ad12cc5e9255d Gitweb: http://git.kernel.org/tip/9b8087d72086b249ff744cee237ad12cc5e9255d Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 22 Dec 2016 15:03:48 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 22 Dec 2016 16:35:45 -0300
perf sched timehist: Enlarge default 'comm_width'
Current default value is 20 but it's easily changed to a bigger value as task has a long name and different tid and pid. And it makes the output not aligned. So change it to have a large value as summary shows.
Committer notes:
Before:
# perf sched record
^C
# perf sched timehist
<SNIP>
40602.770537 [0001] rcuos/2[29] 7.970 0.002 0.020
40602.771512 [0003] <idle> 0.003 0.000 0.986
40602.771586 [0001] <idle> 0.020 0.000 1.049
40602.771606 [0001] qemu-system-x86[3593/3510] 0.000 0.002 0.020
40602.771629 [0003] qemu-system-x86[3510] 0.000 0.003 0.116
40602.771776 [0000] <idle> 0.001 0.000 1.892
<SNIP>After:
# perf sched timehist <SNIP> 40602.770537 [0001] rcuos/2[29] 7.970 0.002 0.020 40602.771512 [0003] <idle> 0.003 0.000 0.986 40602.771586 [0001] <idle> 0.020 0.000 1.049 40602.771606 [0001] qemu-system-x86[3593/3510] 0.000 0.002 0.020 40602.771629 [0003] qemu-system-x86[3510] 0.000 0.003 0.116 <SNIP>
--- tools/perf/builtin-sched.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
tools/perf/builtin-sched.c +1 -1
@@ -1775,7 +1775,7 @@ static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)return r->last_time[cpu]; } -static int comm_width =20 ; +static int comm_width =30 ;static char *timehist_get_commstr (struct thread *thread) {
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Honour 'comm_width' when aligning the headers
In reply to Namhyung Kimperf sched timehist: Honour 'comm_width' when aligning the headers
Commit-ID: 0e6758e8231d5905c2e267566e9bd679a68a7b00 Gitweb: http://git.kernel.org/tip/0e6758e8231d5905c2e267566e9bd679a68a7b00 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 22 Dec 2016 15:03:48 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 22 Dec 2016 16:35:45 -0300
perf sched timehist: Honour 'comm_width' when aligning the headers
Current default value is 20, but that may change in the future, so make places where we have 20 hardcoded use 'comm_width'.
--- tools/perf/builtin-sched.c | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-)
tools/perf/builtin-sched.c +4 -3
@@ -1817,7 +1817,7 @@ static void timehist_header(struct perf_sched *sched)printf (" " ); } -printf (" %-20s %9s %9s %9s" , +printf (" %-*s %9s %9s %9s" , comm_width,"task name" ,"wait time" ,"sch delay" ,"run time" );printf ("\n" );
@@ -1830,7 +1830,8 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %*s " , ncpus,"" ); -printf (" %-20s %9s %9s %9s\n" ,"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" ); +printf (" %-*s %9s %9s %9s\n" , comm_width, +"[tid/pid]" ,"(msec)" ,"(msec)" ,"(msec)" );/* * separator
@@ -1840,7 +1841,7 @@ static void timehist_header(struct perf_sched *sched)if (sched->show_cpu_visual)printf (" %.*s " , ncpus, graph_dotted_line); -printf (" %.20s %.9s %.9s %.9s" , +printf (" %.*s %.9s %.9s %.9s" , comm_width, graph_dotted_line, graph_dotted_line, graph_dotted_line, graph_dotted_line);
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Remove hardcoded 'comm_width' check at print_summary
In reply to Namhyung Kimperf sched timehist: Remove hardcoded 'comm_width' check at print_summary
Commit-ID: 4fa0d1aa2711a5053fb2422331bdf6bce99b5f87 Gitweb: http://git.kernel.org/tip/4fa0d1aa2711a5053fb2422331bdf6bce99b5f87 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 22 Dec 2016 15:03:48 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 22 Dec 2016 16:35:46 -0300
perf sched timehist: Remove hardcoded 'comm_width' check at print_summary
Now that the default 'comm_width' value is 30, no need to check that at print_summary,
--- tools/perf/builtin-sched.c | 3 --- 1 file changed, 3 deletions(-)
tools/perf/builtin-sched.c +0 -3
@@ -2627,9 +2627,6 @@ static void timehist_print_summary(struct perf_sched *sched,memset (&totals,0 ,sizeof (totals)); -if (comm_width <30 ) - comm_width =30 ; -if (sched->idle_hist) {printf ("\nIdle-time summary\n" );printf ("%*s parent sched-out " , comm_width,"comm" );