perf sched timehist: Introduce --idle-hist option (v2)
Namhyung Kim
maintainercover perf sched timehist: Introduce --idle-hist option (v2)
Hi,
This patchset implements the idle hist feature which analyze reason of system idle. Sometimes I need to investigate what makes CPUs to go idle even though I have jobs to do. It may be due to I/O, waiting on lock or whatever.
To identify the reasons it only accounts events related to idle task. Also it shows callchains when entering to idle and time how long it's in the idle. Although it's not perfect, it works well to help finding the reasons.
With --idle-hist option, only idle task's runtime is accounted to previous task (which makes the cpu go to idle). With --summary(-only) option, you can see the total idle stat by task or callchains.
* v2 changes
- check prev_pid instead of sample->pid for idle task (due to race in exit path)
- factor idle task initialization (David)
The example output looks like below:
Idle-time summary
comm parent sched-out idle-time min-idle avg-idle max-idle stddev migrations
(count) (msec) (msec) (msec) (msec) %
---------------------------------------------------------------------------------------------------------------------
rcu_preempt[7] 2 95 550.872 0.011 5.798 23.146 7.63 0
migration/1[16] 2 1 15.558 15.558 15.558 15.558 0.00 0
khugepaged[39] 2 1 3.062 3.062 3.062 3.062 0.00 0
kworker/0:1H[124] 2 2 4.728 0.611 2.364 4.116 74.12 0
systemd-journal[167] 1 1 4.510 4.510 4.510 4.510 0.00 0
kworker/u16:3[558] 2 13 74.737 0.080 5.749 12.960 21.96 0
irq/34-iwlwifi[628] 2 21 118.403 0.032 5.638 23.990 24.00 0
kworker/u17:0[673] 2 1 3.523 3.523 3.523 3.523 0.00 0
dbus-daemon[722] 1 1 6.743 6.743 6.743 6.743 0.00 0
ifplugd[741] 1 1 58.826 58.826 58.826 58.826 0.00 0
wpa_supplicant[1490] 1 1 13.302 13.302 13.302 13.302 0.00 0
wpa_actiond[1492] 1 2 4.064 0.168 2.032 3.896 91.72 0
dockerd[1500] 1 1 0.055 0.055 0.055 0.055 0.00 0
dockerd[1516/1500] 1500 1 5.732 5.732 5.732 5.732 0.00 0
dockerd[1571/1500] 1500 1 0.020 0.020 0.020 0.020 0.00 0...
Idle stats:
CPU 0 idle for 902.195 msec
CPU 1 idle for 899.932 msec
CPU 2 idle for 941.218 msec
CPU 3 idle for 822.453 msec Idle stats by callchain:
CPU 0: 902.195 msec
Idle time (msec) Count Callchains
---------------- -------- --------------------------------------------------
370.589 69 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
178.799 17 worker_thread <- kthread <- ret_from_fork
128.352 17 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
125.111 19 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
71.599 50 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
23.146 1 rcu_gp_kthread <- kthread <- ret_from_fork
4.510 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
0.085 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- do_restart_poll
...
The code is available at 'perf/timehist-idle-v2' branch in my tree:
git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
Any comments are welcome!
Thanks,
Namhyung
Namhyung Kim (6):
perf sched timehist: Split is_idle_sample() perf sched timehist: Introduce struct idle_time_data perf sched timehist: Save callchain when entering idle perf sched timehist: Skip non-idle events when necessary perf sched timehist: Add -I/--idle-hist option perf sched timehist: Show callchains for idle stat
tools/perf/Documentation/perf-sched.txt | 4 + tools/perf/builtin-sched.c | 252 +++++++++++++++++++++++++++----- 2 files changed, 222 insertions(+), 34 deletions(-)
Signature · 1 line
2.10.1
Namhyung Kim
maintainerPATCH v2 1/6 perf sched timehist: Split is_idle_sample()
The is_idle_sample() function actually does more than determining whether sample come from idle task. Split the callchain part into save_task_callchain() to make it clearer.
Also checking prev_pid from trace data looks preferred than just checking sample->pid since it's possible, although rare, to have invalid 0 pid/tid on scheduling an exiting task.
--- tools/perf/builtin-sched.c | 39 ++++++++++++++++++++------------------- 1 file changed, 20 insertions(+), 19 deletions(-)
tools/perf/builtin-sched.c +20 -19
@@ -1939,39 +1939,40 @@ static void timehist_update_runtime_stats(struct thread_runtime *r, r->total_run_time += r->dt_run; } -static bool is_idle_sample (struct perf_sched *sched, -struct perf_sample *sample, -struct perf_evsel *evsel, -struct machine *machine) +static bool is_idle_sample (struct perf_sample *sample, +struct perf_evsel *evsel) { -struct thread *thread; -struct callchain_cursor *cursor = &callchain_cursor; -/* pid 0 == swapper == idle task */ -if (sample->pid ==0 ) -return true; +if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" ) ==0 ) +return (perf_evsel__intval (evsel, sample,"prev_pid" ) ==0 ); -if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" ) ==0 ) { -if (perf_evsel__intval (evsel, sample,"prev_pid" ) ==0 ) -return true; - } +return (sample->pid ==0 ); +} + +static void save_task_callchain (struct perf_sched *sched, +struct perf_sample *sample, +struct perf_evsel *evsel, +struct machine *machine) +{ +struct callchain_cursor *cursor = &callchain_cursor; +struct thread *thread;/* want main thread for process - has maps */ thread =machine__findnew_thread (machine, sample->pid, sample->pid);if (thread ==NULL ) {pr_debug ("Failed to get thread for pid %d.\n" , sample->pid); -return false; +return ; }if (!symbol_conf.use_callchain || sample->callchain ==NULL ) -return false; +return ;if (thread__resolve_callchain (thread, cursor, evsel, sample,NULL ,NULL , sched->max_stack +2 ) !=0 ) {if (verbose)error ("Failed to resolve callchain. Skipping\n" ); -return false; +return ; }callchain_cursor_commit (cursor);
@@ -1994,8 +1995,6 @@ static bool is_idle_sample(struct perf_sched *sched,callchain_cursor_advance (cursor); } - -return false; }/*
@@ -2111,7 +2110,7 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, {struct thread *thread; -if (is_idle_sample (sched, sample, evsel, machine)) { +if (is_idle_sample (sample, evsel)) { thread =get_idle_thread (sample->cpu);if (thread ==NULL )pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu);
@@ -2124,6 +2123,8 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,pr_debug ("Failed to get thread for tid %d. skipping sample.\n" , sample->tid); } + +save_task_callchain (sched, sample, evsel, machine); }return thread;
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Split is_idle_sample()
perf sched timehist: Split is_idle_sample()
Commit-ID: 96039c7c52e03b7d6dd773664e74b79e3ae9856a Gitweb: http://git.kernel.org/tip/96039c7c52e03b7d6dd773664e74b79e3ae9856a Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:50 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:44 -0300
perf sched timehist: Split is_idle_sample()
The is_idle_sample() function actually does more than determining whether sample come from idle task. Split the callchain part into save_task_callchain() to make it clearer.
Also checking prev_pid from trace data looks preferred than just checking sample->pid since it's possible, although rare, to have invalid 0 pid/tid on scheduling an exiting task.
--- tools/perf/builtin-sched.c | 39 ++++++++++++++++++++------------------- 1 file changed, 20 insertions(+), 19 deletions(-)
tools/perf/builtin-sched.c +20 -19
@@ -1939,39 +1939,40 @@ static void timehist_update_runtime_stats(struct thread_runtime *r, r->total_run_time += r->dt_run; } -static bool is_idle_sample (struct perf_sched *sched, -struct perf_sample *sample, -struct perf_evsel *evsel, -struct machine *machine) +static bool is_idle_sample (struct perf_sample *sample, +struct perf_evsel *evsel) { -struct thread *thread; -struct callchain_cursor *cursor = &callchain_cursor; -/* pid 0 == swapper == idle task */ -if (sample->pid ==0 ) -return true; +if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" ) ==0 ) +return perf_evsel__intval (evsel, sample,"prev_pid" ) ==0 ; -if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" ) ==0 ) { -if (perf_evsel__intval (evsel, sample,"prev_pid" ) ==0 ) -return true; - } +return sample->pid ==0 ; +} + +static void save_task_callchain (struct perf_sched *sched, +struct perf_sample *sample, +struct perf_evsel *evsel, +struct machine *machine) +{ +struct callchain_cursor *cursor = &callchain_cursor; +struct thread *thread;/* want main thread for process - has maps */ thread =machine__findnew_thread (machine, sample->pid, sample->pid);if (thread ==NULL ) {pr_debug ("Failed to get thread for pid %d.\n" , sample->pid); -return false; +return ; }if (!symbol_conf.use_callchain || sample->callchain ==NULL ) -return false; +return ;if (thread__resolve_callchain (thread, cursor, evsel, sample,NULL ,NULL , sched->max_stack +2 ) !=0 ) {if (verbose)error ("Failed to resolve callchain. Skipping\n" ); -return false; +return ; }callchain_cursor_commit (cursor);
@@ -1994,8 +1995,6 @@ static bool is_idle_sample(struct perf_sched *sched,callchain_cursor_advance (cursor); } - -return false; }/*
@@ -2111,7 +2110,7 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, {struct thread *thread; -if (is_idle_sample (sched, sample, evsel, machine)) { +if (is_idle_sample (sample, evsel)) { thread =get_idle_thread (sample->cpu);if (thread ==NULL )pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu);
@@ -2124,6 +2123,8 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,pr_debug ("Failed to get thread for tid %d. skipping sample.\n" , sample->tid); } + +save_task_callchain (sched, sample, evsel, machine); }return thread;
Namhyung Kim
maintainerPATCH v2 2/6 perf sched timehist: Introduce struct idle_time_data
In reply to Namhyung KimThe struct idle_time_data is to keep idle stats with callchains entering to the idle task. The normal thread_runtime calculation is done transparently since it extends the struct thread_runtime.
--- tools/perf/builtin-sched.c | 37 +++++++++++++++++++++++++++++++++---- 1 file changed, 33 insertions(+), 4 deletions(-)
tools/perf/builtin-sched.c +33 -4
@@ -230,6 +230,15 @@ struct evsel_runtime {u32 ncpu;/* highest cpu slot allocated */ }; +/* per cpu idle time data */ +struct idle_thread_runtime { +struct thread_runtime tr; +struct thread *last_thread; +struct rb_root sorted_root; +struct callchain_root callchain; +struct callchain_cursor cursor; +}; +/* track idle times per cpu */ static struct thread **idle_threads;static int idle_max_cpu;
@@ -1997,13 +2006,31 @@ static void save_task_callchain(struct perf_sched *sched, } } +static int init_idle_thread (struct thread *thread) +{ +struct idle_thread_runtime *itr; + +thread__set_comm (thread, idle_comm,0 ); + + itr =zalloc (sizeof (*itr)); +if (itr ==NULL ) +return -ENOMEM ; + +init_stats (&itr->tr.run_stats); +callchain_init (&itr->callchain); +callchain_cursor_reset (&itr->cursor); +thread__set_priv (thread, itr); + +return 0 ; +} +/* * Track idle stats per cpu by maintaining a local thread * struct for the idle task on each cpu. */ static int init_idle_threads (int ncpu) { -int i; +int i, ret; idle_threads =zalloc (ncpu *sizeof (struct thread *));if (!idle_threads)
@@ -2017,7 +2044,9 @@ static int init_idle_threads(int ncpu)if (idle_threads[i] ==NULL )return -ENOMEM ; -thread__set_comm (idle_threads[i], idle_comm,0 ); + ret =init_idle_thread (idle_threads[i]); +if (ret <0 ) +return ret; }return 0 ;
@@ -2064,8 +2093,8 @@ static struct thread *get_idle_thread(int cpu) idle_threads[cpu] =thread__new (0 ,0 );if (idle_threads[cpu]) { - idle_threads[cpu]->tid =0 ; -thread__set_comm (idle_threads[cpu], idle_comm,0 ); +if (init_idle_thread (idle_threads[cpu]) <0 ) +return NULL ; } }
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Introduce struct idle_time_data
perf sched timehist: Introduce struct idle_time_data
Commit-ID: 3bc2fa9cb829ccf6527e7117d9af769d93ee6d39 Gitweb: http://git.kernel.org/tip/3bc2fa9cb829ccf6527e7117d9af769d93ee6d39 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:51 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:44 -0300
perf sched timehist: Introduce struct idle_time_data
The struct idle_time_data is to keep idle stats with callchains entering to the idle task. The normal thread_runtime calculation is done transparently since it extends the struct thread_runtime.
--- tools/perf/builtin-sched.c | 37 +++++++++++++++++++++++++++++++++---- 1 file changed, 33 insertions(+), 4 deletions(-)
tools/perf/builtin-sched.c +33 -4
@@ -230,6 +230,15 @@ struct evsel_runtime {u32 ncpu;/* highest cpu slot allocated */ }; +/* per cpu idle time data */ +struct idle_thread_runtime { +struct thread_runtime tr; +struct thread *last_thread; +struct rb_root sorted_root; +struct callchain_root callchain; +struct callchain_cursor cursor; +}; +/* track idle times per cpu */ static struct thread **idle_threads;static int idle_max_cpu;
@@ -1997,13 +2006,31 @@ static void save_task_callchain(struct perf_sched *sched, } } +static int init_idle_thread (struct thread *thread) +{ +struct idle_thread_runtime *itr; + +thread__set_comm (thread, idle_comm,0 ); + + itr =zalloc (sizeof (*itr)); +if (itr ==NULL ) +return -ENOMEM ; + +init_stats (&itr->tr.run_stats); +callchain_init (&itr->callchain); +callchain_cursor_reset (&itr->cursor); +thread__set_priv (thread, itr); + +return 0 ; +} +/* * Track idle stats per cpu by maintaining a local thread * struct for the idle task on each cpu. */ static int init_idle_threads (int ncpu) { -int i; +int i, ret; idle_threads =zalloc (ncpu *sizeof (struct thread *));if (!idle_threads)
@@ -2017,7 +2044,9 @@ static int init_idle_threads(int ncpu)if (idle_threads[i] ==NULL )return -ENOMEM ; -thread__set_comm (idle_threads[i], idle_comm,0 ); + ret =init_idle_thread (idle_threads[i]); +if (ret <0 ) +return ret; }return 0 ;
@@ -2064,8 +2093,8 @@ static struct thread *get_idle_thread(int cpu) idle_threads[cpu] =thread__new (0 ,0 );if (idle_threads[cpu]) { - idle_threads[cpu]->tid =0 ; -thread__set_comm (idle_threads[cpu], idle_comm,0 ); +if (init_idle_thread (idle_threads[cpu]) <0 ) +return NULL ; } }
Namhyung Kim
maintainerPATCH v2 3/6 perf sched timehist: Save callchain when entering idle
In reply to Namhyung KimIn order to investigate reason of idle, it needs to keep the callchains when entering to idle. This can be identified sched_switch event having next_pid as 0.
--- tools/perf/builtin-sched.c | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+)
tools/perf/builtin-sched.c +29 -0
@@ -200,6 +200,7 @@ struct perf_sched {/* options for timehist command */ bool summary;bool summary_only; +bool idle_hist;bool show_callchain;unsigned int max_stack;bool show_cpu_visual;
@@ -2101,6 +2102,29 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } +static void save_idle_callchain (struct thread *thread, +struct perf_sample *sample) +{ +struct thread *idle; +struct idle_thread_runtime *itr; + +if (!symbol_conf.use_callchain || sample->callchain ==NULL ) +return ; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return ; + + itr->last_thread = thread; +callchain_cursor__copy (&itr->cursor, &callchain_cursor); +} +/* * handle runtime stats saved per thread */
@@ -2154,6 +2178,11 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, }save_task_callchain (sched, sample, evsel, machine); +if (sched->idle_hist) { +/* copy task callchain when entering to idle */ +if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) +save_idle_callchain (thread, sample); + } }return thread;
Signature · 1 line
2.10.1
Namhyung Kim
maintainerPATCH v2 4/6 perf sched timehist: Skip non-idle events when necessary
In reply to Namhyung KimSometimes it only focuses on idle-related events like upcoming idle-hist feature. In this case we don't want to see other event to reduce noise.
--- tools/perf/builtin-sched.c | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-)
tools/perf/builtin-sched.c +18 -7
@@ -2189,7 +2189,9 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, }static bool timehist_skip_sample (struct perf_sched *sched, -struct thread *thread) +struct thread *thread, +struct perf_evsel *evsel, +struct perf_sample *sample) {bool rc = false;
@@ -2198,10 +2200,19 @@ static bool timehist_skip_sample(struct perf_sched *sched, sched->skipped_samples++; } +if (sched->idle_hist) { +if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" )) + rc = true; +else if (perf_evsel__intval (evsel, sample,"prev_pid" ) !=0 && +perf_evsel__intval (evsel, sample,"next_pid" ) !=0 ) + rc = true; + } +return rc; }static void timehist_print_wakeup_event (struct perf_sched *sched, +struct perf_evsel *evsel,struct perf_sample *sample,struct machine *machine,struct thread *awakened)
@@ -2214,8 +2225,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,return ;/* show wakeup unless both awakee and awaker are filtered */ -if (timehist_skip_sample (sched, thread) && -timehist_skip_sample (sched, awakened)) { +if (timehist_skip_sample (sched, thread, evsel, sample) && +timehist_skip_sample (sched, awakened, evsel, sample)) {return ; }
@@ -2260,7 +2271,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,/* show wakeups if requested */ if (sched->show_wakeups && !perf_time__skip_sample (&sched->ptime, sample->time)) -timehist_print_wakeup_event (sched, sample, machine, thread); +timehist_print_wakeup_event (sched, evsel, sample, machine, thread);return 0 ; }
@@ -2287,8 +2298,8 @@ static void timehist_print_migration_event(struct perf_sched *sched,if (thread ==NULL )return ; -if (timehist_skip_sample (sched, thread) && -timehist_skip_sample (sched, migrated)) { +if (timehist_skip_sample (sched, thread, evsel, sample) && +timehist_skip_sample (sched, migrated, evsel, sample)) {return ; }
@@ -2373,7 +2384,7 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out; } -if (timehist_skip_sample (sched, thread)) +if (timehist_skip_sample (sched, thread, evsel, sample)) goto out; tr =thread__get_runtime (thread);
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Skip non-idle events when necessary
perf sched timehist: Skip non-idle events when necessary
Commit-ID: a4b2b6f56e0cfe729cf89318d44b6a875b31d95a Gitweb: http://git.kernel.org/tip/a4b2b6f56e0cfe729cf89318d44b6a875b31d95a Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:53 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:44 -0300
perf sched timehist: Skip non-idle events when necessary
Sometimes it only focuses on idle-related events like upcoming idle-hist feature. In this case we don't want to see other event to reduce noise.
--- tools/perf/builtin-sched.c | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-)
tools/perf/builtin-sched.c +18 -7
@@ -2190,7 +2190,9 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, }static bool timehist_skip_sample (struct perf_sched *sched, -struct thread *thread) +struct thread *thread, +struct perf_evsel *evsel, +struct perf_sample *sample) {bool rc = false;
@@ -2199,10 +2201,19 @@ static bool timehist_skip_sample(struct perf_sched *sched, sched->skipped_samples++; } +if (sched->idle_hist) { +if (strcmp (perf_evsel__name (evsel),"sched:sched_switch" )) + rc = true; +else if (perf_evsel__intval (evsel, sample,"prev_pid" ) !=0 && +perf_evsel__intval (evsel, sample,"next_pid" ) !=0 ) + rc = true; + } +return rc; }static void timehist_print_wakeup_event (struct perf_sched *sched, +struct perf_evsel *evsel,struct perf_sample *sample,struct machine *machine,struct thread *awakened)
@@ -2215,8 +2226,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,return ;/* show wakeup unless both awakee and awaker are filtered */ -if (timehist_skip_sample (sched, thread) && -timehist_skip_sample (sched, awakened)) { +if (timehist_skip_sample (sched, thread, evsel, sample) && +timehist_skip_sample (sched, awakened, evsel, sample)) {return ; }
@@ -2261,7 +2272,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,/* show wakeups if requested */ if (sched->show_wakeups && !perf_time__skip_sample (&sched->ptime, sample->time)) -timehist_print_wakeup_event (sched, sample, machine, thread); +timehist_print_wakeup_event (sched, evsel, sample, machine, thread);return 0 ; }
@@ -2288,8 +2299,8 @@ static void timehist_print_migration_event(struct perf_sched *sched,if (thread ==NULL )return ; -if (timehist_skip_sample (sched, thread) && -timehist_skip_sample (sched, migrated)) { +if (timehist_skip_sample (sched, thread, evsel, sample) && +timehist_skip_sample (sched, migrated, evsel, sample)) {return ; }
@@ -2374,7 +2385,7 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out; } -if (timehist_skip_sample (sched, thread)) +if (timehist_skip_sample (sched, thread, evsel, sample)) goto out; tr =thread__get_runtime (thread);
Namhyung Kim
maintainerPATCH v2 5/6 perf sched timehist: Add -I/--idle-hist option
In reply to Namhyung KimThe --idle-hist option is to analyze system idle state so which process makes cpu to go idle. If this option is specified, non-idle events will be skipped and processes switching to/from idle will be shown.
This option is mostly useful when used with --summary(-only) option. In the idle-time summary view, idle time is accounted to previous thread which is run before idle task.
The example output looks like following:
Idle-time summary
comm parent sched-out idle-time min-idle avg-idle max-idle stddev migrations
(count) (msec) (msec) (msec) (msec) %
-------------------------------------------------------------------------------------------------------------------
rcu_preempt[7] 2 95 550.872 0.011 5.798 23.146 7.63 0
migration/1[16] 2 1 15.558 15.558 15.558 15.558 0.00 0
khugepaged[39] 2 1 3.062 3.062 3.062 3.062 0.00 0
kworker/0:1H[124] 2 2 4.728 0.611 2.364 4.116 74.12 0
systemd-journal[167] 1 1 4.510 4.510 4.510 4.510 0.00 0
kworker/u16:3[558] 2 13 74.737 0.080 5.749 12.960 21.96 0
irq/34-iwlwifi[628] 2 21 118.403 0.032 5.638 23.990 24.00 0
kworker/u17:0[673] 2 1 3.523 3.523 3.523 3.523 0.00 0
dbus-daemon[722] 1 1 6.743 6.743 6.743 6.743 0.00 0
ifplugd[741] 1 1 58.826 58.826 58.826 58.826 0.00 0
wpa_supplicant[1490] 1 1 13.302 13.302 13.302 13.302 0.00 0
wpa_actiond[1492] 1 2 4.064 0.168 2.032 3.896 91.72 0
dockerd[1500] 1 1 0.055 0.055 0.055 0.055 0.00 0...
--- tools/perf/Documentation/perf-sched.txt | 4 ++++ tools/perf/builtin-sched.c | 38 ++++++++++++++++++++++++++++----- 2 files changed, 37 insertions(+), 5 deletions(-)
tools/perf/Documentation/perf-sched.txt +4 -0
@@ -132,6 +132,10 @@ OPTIONS for 'perf sched timehist' --migrations:: Show migration events. +-I:: +--idle-hist:: + Show idle-related events only. + --time:: Only analyze samples within given time window: <start>,<stop>. Times have the format seconds.microseconds. If start is not given (i.e., time
tools/perf/builtin-sched.c +33 -5
@@ -2420,7 +2420,28 @@ static int timehist_sched_change_event(struct perf_tool *tool, t = ptime->end; } -timehist_update_runtime_stats (tr, t, tprev); +if (!sched->idle_hist || thread->tid ==0 ) { +timehist_update_runtime_stats (tr, t, tprev); + +if (sched->idle_hist) { +struct idle_thread_runtime *itr = (void *)tr; +struct thread_runtime *last_tr; + +BUG_ON (thread->tid !=0 ); + +if (itr->last_thread ==NULL ) + goto out; + +/* add current idle time as last thread's runtime */ + last_tr =thread__get_runtime (itr->last_thread); +if (last_tr ==NULL ) + goto out; + +timehist_update_runtime_stats (last_tr, t, tprev); + + itr->last_thread =NULL ; + } + }if (!sched->summary_only)timehist_print_sample (sched, sample, &al, thread, t);
@@ -2542,9 +2563,15 @@ static void timehist_print_summary(struct perf_sched *sched,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 migrations\n" ); +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 { +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 ("%.117s\n" , graph_dotted_line);
@@ -2560,7 +2587,7 @@ static void timehist_print_summary(struct perf_sched *sched,printf ("<no terminated tasks>\n" );/* CPU idle stats not tracked when samples were skipped */ -if (sched->skipped_samples) +if (sched->skipped_samples && !sched->idle_hist)return ;printf ("\nIdle stats:\n" );
@@ -3106,6 +3133,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)OPT_BOOLEAN ('w' ,"wakeups" , &sched.show_wakeups,"Show wakeup events" ),OPT_BOOLEAN ('M' ,"migrations" , &sched.show_migrations,"Show migration events" ),OPT_BOOLEAN ('V' ,"cpu-visual" , &sched.show_cpu_visual,"Add CPU visual" ), +OPT_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_PARENT (sched_options)
Signature · 1 line
2.10.1
Namhyung Kim
maintainerPATCH v2 6/6 perf sched timehist: Show callchains for idle stat
In reply to Namhyung KimWhen --idle-hist option is used with --summary, it now shows idle stats with callchains like below:
Idle stats by callchain:
CPU 0: 902.195 msec
Idle time (msec) Count Callchains
---------------- -------- --------------------------------------------------
370.589 69 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
178.799 17 worker_thread <- kthread <- ret_from_fork
128.352 17 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
125.111 19 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
71.599 50 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
23.146 1 rcu_gp_kthread <- kthread <- ret_from_fork
4.510 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
0.085 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- do_restart_poll
...
--- tools/perf/builtin-sched.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 86 insertions(+)
tools/perf/builtin-sched.c +86 -0
@@ -2438,6 +2438,9 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out;timehist_update_runtime_stats (last_tr, t, tprev); +if (itr->cursor.nr) +callchain_append (&itr->callchain, &itr->cursor, + t - tprev); itr->last_thread =NULL ; }
@@ -2548,6 +2551,60 @@ static int show_deadthread_runtime(struct thread *t, void *priv)return __show_thread_runtime (t, priv); } +static size_t callchain__fprintf_folded (FILE *fp,struct callchain_node *node) +{ +const char *sep =" <- " ; +struct callchain_list *chain; +size_t ret =0 ; +char bf[1024 ]; +bool first; + +if (node ==NULL ) +return 0 ; + + ret =callchain__fprintf_folded (fp, node->parent); + first = (ret ==0 ); + +list_for_each_entry (chain, &node->val, list) { +if (chain->ip >=PERF_CONTEXT_MAX ) +continue ; +if (chain->ms.sym && chain->ms.sym->ignore) +continue ; + ret +=fprintf (fp,"%s%s" , first ?"" : sep, +callchain_list__sym_name (chain, bf,sizeof (bf), + false)); + first = false; + } + +return ret; +} + +static size_t timehist_print_idlehist_callchain (struct rb_root *root) +{ +size_t ret =0 ; +FILE *fp = stdout; +struct callchain_node *chain; +struct rb_node *rb_node =rb_first (root); + +printf (" %16s %8s %s\n" ,"Idle time (msec)" ,"Count" ,"Callchains" ); +printf (" %.16s %.8s %.50s\n" , graph_dotted_line, graph_dotted_line, + graph_dotted_line); + +while (rb_node) { + chain = rb_entry(rb_node, struct callchain_node, rb_node); + rb_node =rb_next (rb_node); + + ret +=fprintf (fp," " ); +print_sched_time (chain->hit,12 ); + ret +=16 ;/* print_sched_time returns 2nd arg + 4 */ + ret +=fprintf (fp," %8d " , chain->count); + ret +=callchain__fprintf_folded (fp, chain); + ret +=fprintf (fp,"\n" ); + } + +return ret; +} +static void timehist_print_summary (struct perf_sched *sched,struct perf_session *session) {
@@ -2606,6 +2663,35 @@ static void timehist_print_summary(struct perf_sched *sched,printf (" CPU %2d idle entire time window\n" , i); } +if (sched->idle_hist && symbol_conf.use_callchain) { + callchain_param.mode =CHAIN_FOLDED ; + callchain_param.value =CCVAL_PERIOD ; + +callchain_register_param (&callchain_param); + +printf ("\nIdle stats by callchain:\n" ); +for (i =0 ; i < idle_max_cpu; ++i) { +struct idle_thread_runtime *itr; + + t = idle_threads[i]; +if (!t) +continue ; + + itr =thread__priv (t); +if (itr ==NULL ) +continue ; + + callchain_param.sort (&itr->sorted_root, &itr->callchain, +0 , &callchain_param); + +printf (" CPU %2d:" , i); +print_sched_time (itr->tr.total_run_time,6 ); +printf (" msec\n" ); +timehist_print_idlehist_callchain (&itr->sorted_root); +printf ("\n" ); + } + } +printf ("\n" " Total number of unique tasks: %" PRIu64"\n" "Total number of context switches: %" PRIu64 "\n"
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Show callchains for idle stat
perf sched timehist: Show callchains for idle stat
Commit-ID: ba957ebb54893acaf3dc846031073a63f021cee1 Gitweb: http://git.kernel.org/tip/ba957ebb54893acaf3dc846031073a63f021cee1 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:55 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:45 -0300
perf sched timehist: Show callchains for idle stat
When --idle-hist option is used with --summary, it now shows idle stats with callchains like below:
Idle stats by callchain:
CPU 0: 902.195 msec
Idle time (msec) Count Callchains
---------------- ------- --------------------------------------------------
370.589 69 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
178.799 17 worker_thread <- kthread <- ret_from_fork
128.352 17 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
125.111 19 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
71.599 50 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
23.146 1 rcu_gp_kthread <- kthread <- ret_from_fork
4.510 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
0.085 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- do_restart_poll...
Committer notes:
Extra testing:
# uname -a Linux jouet 4.8.8-300.fc25.x86_64 #1 SMP Tue Nov 15 18:10:06 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
1) Run 'perf sched record -g'
2) Run 'perf sched timehist --idle --summary'
<SNIP>
Idle stats by callchain:
CPU 0: 13456.840 msec
Idle time (msec) Count Callchains
---------------- ----- --------------------------------------------------
5386.637 3283 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
2750.238 2299 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- do_syscall_64
1275.672 1287 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- entry_SYSCALL_64_fastpath
936.322 452 worker_thread <- kthread <- ret_from_fork
741.311 385 rcu_nocb_kthread <- kthread <- ret_from_fork
729.385 248 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_ppoll
365.386 229 irq_thread <- kthread <- ret_from_fork
338.934 265 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
219.488 201 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
186.839 410 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
142.541 59 kvm_vcpu_block <- kvm_arch_vcpu_ioctl_run <- kvm_vcpu_ioctl <- do_vfs_ioctl <- sys_ioctl
83.887 92 smpboot_thread_fn <- kthread <- ret_from_fork
62.722 96 do_exit <- do_group_exit <- 0x2a5594 <- entry_SYSCALL_64_fastpath
47.894 83 pipe_wait <- pipe_read <- __vfs_read <- vfs_read <- sys_read
46.554 61 rcu_gp_kthread <- kthread <- ret_from_fork
34.337 21 schedule_timeout <- intel_fbc_work_fn <- process_one_work <- worker_thread <- kthread
29.521 14 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
20.274 10 schedule_timeout <- io_schedule_timeout <- bit_wait_io <- __wait_on_bit <- out_of_line_wait_on_bit
15.085 55 schedule_timeout <- unix_stream_read_generic <- unix_stream_recvmsg <- sock_recvmsg <- SYSC_recvfrom<SNIP>
--- tools/perf/builtin-sched.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 86 insertions(+)
tools/perf/builtin-sched.c +86 -0
@@ -2448,6 +2448,9 @@ static int timehist_sched_change_event(struct perf_tool *tool, last_tr->dt_wait =0 ; last_tr->dt_delay =0 ; +if (itr->cursor.nr) +callchain_append (&itr->callchain, &itr->cursor, t - tprev); + itr->last_thread =NULL ; } }
@@ -2557,6 +2560,60 @@ static int show_deadthread_runtime(struct thread *t, void *priv)return __show_thread_runtime (t, priv); } +static size_t callchain__fprintf_folded (FILE *fp,struct callchain_node *node) +{ +const char *sep =" <- " ; +struct callchain_list *chain; +size_t ret =0 ; +char bf[1024 ]; +bool first; + +if (node ==NULL ) +return 0 ; + + ret =callchain__fprintf_folded (fp, node->parent); + first = (ret ==0 ); + +list_for_each_entry (chain, &node->val, list) { +if (chain->ip >=PERF_CONTEXT_MAX ) +continue ; +if (chain->ms.sym && chain->ms.sym->ignore) +continue ; + ret +=fprintf (fp,"%s%s" , first ?"" : sep, +callchain_list__sym_name (chain, bf,sizeof (bf), + false)); + first = false; + } + +return ret; +} + +static size_t timehist_print_idlehist_callchain (struct rb_root *root) +{ +size_t ret =0 ; +FILE *fp = stdout; +struct callchain_node *chain; +struct rb_node *rb_node =rb_first (root); + +printf (" %16s %8s %s\n" ,"Idle time (msec)" ,"Count" ,"Callchains" ); +printf (" %.16s %.8s %.50s\n" , graph_dotted_line, graph_dotted_line, + graph_dotted_line); + +while (rb_node) { + chain = rb_entry(rb_node, struct callchain_node, rb_node); + rb_node =rb_next (rb_node); + + ret +=fprintf (fp," " ); +print_sched_time (chain->hit,12 ); + ret +=16 ;/* print_sched_time returns 2nd arg + 4 */ + ret +=fprintf (fp," %8d " , chain->count); + ret +=callchain__fprintf_folded (fp, chain); + ret +=fprintf (fp,"\n" ); + } + +return ret; +} +static void timehist_print_summary (struct perf_sched *sched,struct perf_session *session) {
@@ -2615,6 +2672,35 @@ static void timehist_print_summary(struct perf_sched *sched,printf (" CPU %2d idle entire time window\n" , i); } +if (sched->idle_hist && symbol_conf.use_callchain) { + callchain_param.mode =CHAIN_FOLDED ; + callchain_param.value =CCVAL_PERIOD ; + +callchain_register_param (&callchain_param); + +printf ("\nIdle stats by callchain:\n" ); +for (i =0 ; i < idle_max_cpu; ++i) { +struct idle_thread_runtime *itr; + + t = idle_threads[i]; +if (!t) +continue ; + + itr =thread__priv (t); +if (itr ==NULL ) +continue ; + + callchain_param.sort (&itr->sorted_root, &itr->callchain, +0 , &callchain_param); + +printf (" CPU %2d:" , i); +print_sched_time (itr->tr.total_run_time,6 ); +printf (" msec\n" ); +timehist_print_idlehist_callchain (&itr->sorted_root); +printf ("\n" ); + } + } +printf ("\n" " Total number of unique tasks: %" PRIu64"\n" "Total number of context switches: %" PRIu64 "\n"
Quoted 6 lines · Namhyung Kim
Hi,
This patchset implements the idle hist feature which analyze reason of system idle. Sometimes I need to investigate what makes CPUs to go idle even though I have jobs to do. It may be due to I/O, waiting on lock or whatever.
...
Quoted 8 lines
Namhyung Kim (6):
perf sched timehist: Splitis_idle_sample()perf sched timehist: Introduce structidle_time_dataperf sched timehist: Save callchain when entering idle perf sched timehist: Skip non-idle events when necessary perf sched timehist: Add -I/--idle-hist option perf sched timehist: Show callchains for idle stat
Quoted 4 lines
tools/perf/Documentation/perf-sched.txt | 4 + tools/perf/builtin-sched.c | 252 +++++++++++++++++++++++++++----- 2 files changed, 222 insertions(+), 34 deletions(-)
LGTM
Suggested improvement: Add the length of the time window. ie., data collected (or analyzed over if --time is used) for N.M seconds. Puts the amount of idle time into perspective.
Namhyung Kim
maintainerHi David,
Quoted 18 lines · David Ahern
Quoted 6 lines · Namhyung Kim
Hi,
This patchset implements the idle hist feature which analyze reason of system idle. Sometimes I need to investigate what makes CPUs to go idle even though I have jobs to do. It may be due to I/O, waiting on lock or whatever.
...
Quoted 8 lines
Namhyung Kim (6):
perf sched timehist: Splitis_idle_sample()perf sched timehist: Introduce structidle_time_dataperf sched timehist: Save callchain when entering idle perf sched timehist: Skip non-idle events when necessary perf sched timehist: Add -I/--idle-hist option perf sched timehist: Show callchains for idle stat
Quoted 8 lines
Quoted 4 lines
tools/perf/Documentation/perf-sched.txt | 4 + tools/perf/builtin-sched.c | 252 +++++++++++++++++++++++++++----- 2 files changed, 222 insertions(+), 34 deletions(-)LGTM
Acked-by David Ahern <[email protected]>
Thanks!
Quoted 4 lines
Suggested improvement: Add the length of the time window. ie., data collected (or analyzed over if --time is used) for N.M seconds. Puts the amount of idle time into perspective.
Do you mean adding an elapsed time so that it can see the cpu utilization (or something similar)? Then we need to expose the elapsed time during record or maybe just use time difference between first and last sample?
Thanks,
Namhyung
Quoted 3 lines · Namhyung Kim
Do you mean adding an elapsed time so that it can see the cpu utilization (or something similar)? Then we need to expose the elapsed time during record or maybe just use time difference between first and last sample?
I was thinking tstart = time of first sample analyzed, tend = time of last sample analyzed, dt = tend - tstart.
If the analysis window (dt) is 5 seconds and each cpu is idle for 0.1 seconds of that 5 second window then the system is under high load.
Namhyung Kim
maintainerQuoted 10 lines · David Ahern
Quoted 3 lines · Namhyung Kim
Do you mean adding an elapsed time so that it can see the cpu utilization (or something similar)? Then we need to expose the elapsed time during record or maybe just use time difference between first and last sample?
I was thinking tstart = time of first sample analyzed, tend = time of last sample analyzed, dt = tend - tstart.
If the analysis window (dt) is 5 seconds and each cpu is idle for 0.1 seconds of that 5 second window then the system is under high load.
Hmm... something like this?
Quoted 1 line
From
5a1702bd15d78b0fe0c31d2d48ec8afa41fbf10cMon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Tue, 13 Dec 2016 15:05:14 +0900
Subject: [PATCH] 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--- tools/perf/builtin-sched.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-)
tools/perf/builtin-sched.c +16 -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 */
@@ -2624,6 +2625,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));
@@ -2668,7 +2670,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); }
@@ -2704,12 +2706,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 ("\n" ); } typedef int (*sched_handler)(struct perf_tool *tool,
@@ -2731,6 +2737,12 @@ static int perf_timehist__process_sample(struct perf_tool *tool,if (this_cpu > sched->max_cpu) sched->max_cpu = this_cpu; +if (sched->hist_time.start ==0 ) + sched->hist_time.start = sample->time; +/* do not update end time if user gave a ptime */ +if (sched->ptime.end ==0 ) + sched->hist_time.end = sample->time; +if (evsel->handler !=NULL ) {sched_handler f = evsel->handler;
@@ -2814,6 +2826,7 @@ static int perf_sched__timehist(struct perf_sched *sched)pr_err ("Invalid time string\n" );return -EINVAL ; } + sched->hist_time = sched->ptime;if (timehist_check_attr (sched, evlist) !=0 ) goto out;
Signature · 1 line
2.10.2
Quoted 1 line · Namhyung Kim
Hmm... something like this?
yes. 1 comment though ...
Quoted 92 lines
From
5a1702bd15d78b0fe0c31d2d48ec8afa41fbf10cMon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Tue, 13 Dec 2016 15:05:14 +0900
Subject: [PATCH] perf sched timehist: Show total scheduling timeShow 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: 2337Total run time (msec): 3718.048 Total scheduling time (msec): 1001.131Suggested-by David Ahern <[email protected]>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-)tools/perf/builtin-sched.c +15
-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 */ @@ -2624,6 +2625,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));@@ -2668,7 +2670,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); }@@ -2704,12 +2706,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 ("\n" ); } typedef int (*sched_handler)(struct perf_tool *tool,@@ -2731,6 +2737,12 @@ static int perf_timehist__process_sample(struct perf_tool *tool,if (this_cpu > sched->max_cpu) sched->max_cpu = this_cpu; +if (sched->hist_time.start ==0 ) + sched->hist_time.start = sample->time; +/* do not update end time if user gave a ptime */ +if (sched->ptime.end ==0 ) + sched->hist_time.end = sample->time; +if (evsel->handler !=NULL ) {sched_handler f = evsel->handler;
tools/perf/builtin-sched.c static int perf_sched__timehist(struct perf_sched *sched) · line 2829
Quoted 4 lines
tools/perf/builtin-sched.c +1
-0@@ -2814,6 +2826,7 @@ static int perf_sched__timehist(struct perf_sched *sched)pr_err ("Invalid time string\n" );return -EINVAL ; } + sched->hist_time = sched->ptime;
The time given by the user does not necessarily correlate with a time in the file. eg., start time could be way before the file starts or end time way after.
Quoted 4 lines
tools/perf/builtin-sched.c +0
-0if (timehist_check_attr (sched, evlist) !=0 ) goto out;
Namhyung Kim
maintainerQuoted 96 lines · David Ahern
Quoted 1 line · Namhyung Kim
Hmm... something like this?
yes. 1 comment though ...
Quoted 91 lines
From
5a1702bd15d78b0fe0c31d2d48ec8afa41fbf10cMon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Tue, 13 Dec 2016 15:05:14 +0900
Subject: [PATCH] perf sched timehist: Show total scheduling timeShow 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: 2337Total run time (msec): 3718.048 Total scheduling time (msec): 1001.131Suggested-by David Ahern <[email protected]>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-)tools/perf/builtin-sched.c +15
-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 */ @@ -2624,6 +2625,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));@@ -2668,7 +2670,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); }@@ -2704,12 +2706,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 ("\n" ); } typedef int (*sched_handler)(struct perf_tool *tool,@@ -2731,6 +2737,12 @@ static int perf_timehist__process_sample(struct perf_tool *tool,if (this_cpu > sched->max_cpu) sched->max_cpu = this_cpu; +if (sched->hist_time.start ==0 ) + sched->hist_time.start = sample->time; +/* do not update end time if user gave a ptime */ +if (sched->ptime.end ==0 ) + sched->hist_time.end = sample->time; +if (evsel->handler !=NULL ) {sched_handler f = evsel->handler;
Quoted 9 lines
tools/perf/builtin-sched.c static int perf_sched__timehist(struct perf_sched *sched) · line 2829
Quoted 5 lines
tools/perf/builtin-sched.c +1
-0@@ -2814,6 +2826,7 @@ static int perf_sched__timehist(struct perf_sched *sched)pr_err ("Invalid time string\n" );return -EINVAL ; } + sched->hist_time = sched->ptime;The time given by the user does not necessarily correlate with a time in the file. eg., start time could be way before the file starts or end time way after.
Right, I'll keep the actual sampling window within the ptime then.
Thanks,
Namhyung
Quoted 6 lines
Quoted 5 lines
tools/perf/builtin-sched.c +0
-0if (timehist_check_attr (sched, evlist) !=0 ) goto out;
Namhyung Kim
maintainerPATCH 1/2 perf sched timehist: Fix --idle-hist when no callchains
When idle hist is enabled, the itr->last_thread should be set so that it can find which thread run before idle task. But it was only set in the save_idle_callchain(). This makes idle task doesn't show up in the output when callchain is not recorded.
Before:
$ perf sched timehist --idle-hist
Samples do not have callchains.
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
197731.753834 [0001] perf[27469] 0.000 0.000 0.000
197731.753915 [0003] migration/3[23] 0.000 0.000 0.000
197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000
197731.754486 [0001] sleep[27470] 0.000 0.000 0.000
197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.000
197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.000
...After:
197731.753834 [0001] perf[27469] 0.000 0.000 0.000
197731.753914 [0001] <idle> 0.000 0.000 0.079
197731.753915 [0003] migration/3[23] 0.000 0.000 0.000
197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000
197731.754486 [0001] sleep[27470] 0.000 0.000 0.000
197731.754903 [0002] <idle> 0.047 0.000 0.567
197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567
197731.755922 [0002] <idle> 0.078 0.000 0.941
197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941
197731.756625 [0003] <idle> 0.123 0.000 2.709
...--- tools/perf/builtin-sched.c | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-)
tools/perf/builtin-sched.c +17 -16
@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } -static void save_idle_callchain (struct thread *thread, +static void save_idle_callchain (struct idle_thread_runtime *itr,struct perf_sample *sample) { -struct thread *idle; -struct idle_thread_runtime *itr; -if (!symbol_conf.use_callchain || sample->callchain ==NULL )return ; - idle =get_idle_thread (sample->cpu); -if (idle ==NULL ) { -pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); -return ; - } - - itr =thread__priv (idle); -if (itr ==NULL ) -return ; - - itr->last_thread = thread;callchain_cursor__copy (&itr->cursor, &callchain_cursor); }
@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,save_task_callchain (sched, sample, evsel, machine);if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; +/* copy task callchain when entering to idle */ if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) -save_idle_callchain (thread, sample); +save_idle_callchain (itr, sample); } }
Signature · 1 line
2.10.2
Namhyung Kim
maintainerPATCH 2/2 perf sched timehist: Fix invalid runtime in the idle hist
When --idle-hist option is used, run/wait time and sched delay value should be shown for idle task only. But due to internal accounting, a last thread has same value of next idle task's and it was shown.
In the below example, firefox after idle task has same run time of idle task's.
$ perf sched timehist --idle-hist
Samples do not have callchains.
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000
197731.754486 [0001] sleep[27470] 0.000 0.000 0.000
197731.754903 [0002] <idle> 0.047 0.000 0.567
197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567
197731.755922 [0002] <idle> 0.078 0.000 0.941
197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941
<SNIP>--- tools/perf/builtin-sched.c | 9 +++++++++ 1 file changed, 9 insertions(+)
tools/perf/builtin-sched.c +9 -0
@@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out;timehist_update_runtime_stats (last_tr, t, tprev); +/* +* remove delta time of last thread as it's not updated +* and otherwise it will show an invalid value next +* 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 ; +if (itr->cursor.nr)callchain_append (&itr->callchain, &itr->cursor, t - tprev);
Signature · 1 line
2.10.2
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
Quoted 6 lines
When --idle-hist option is used, run/wait time and sched delay value should be shown for idle task only. But due to internal accounting, a last thread has same value of next idle task's and it was shown.
In the below example, firefox after idle task has same run time of idle task's.
Same as last message, is this something I can fold into a patch yet in my perf/core branch?
- Arnaldo
Quoted 40 lines
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 <SNIP>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 9 +++++++++ 1 file changed, 9 insertions(+)tools/perf/builtin-sched.c +9
-0@@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out;timehist_update_runtime_stats (last_tr, t, tprev); +/* +* remove delta time of last thread as it's not updated +* and otherwise it will show an invalid value next +* 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 ; +if (itr->cursor.nr)callchain_append (&itr->callchain, &itr->cursor, t - tprev);Signature · 1 line
2.10.2
Namhyung Kim
maintainerRe: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
Quoted 10 lines · Arnaldo Carvalho de Melo
Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
Quoted 6 lines
When --idle-hist option is used, run/wait time and sched delay value should be shown for idle task only. But due to internal accounting, a last thread has same value of next idle task's and it was shown.
In the below example, firefox after idle task has same run time of idle task's.
Same as last message, is this something I can fold into a patch yet in my perf/core branch?
Yep,
I guess it makes a conflict on the callchain code. In case it doesn't look obvious to resolve, please let me know..
Thanks,
Namhyung
Quoted 43 lines
- Arnaldo
Quoted 40 lines
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 <SNIP>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 9 +++++++++ 1 file changed, 9 insertions(+)tools/perf/builtin-sched.c +9
-0@@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out;timehist_update_runtime_stats (last_tr, t, tprev); +/* +* remove delta time of last thread as it's not updated +* and otherwise it will show an invalid value next +* 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 ; +if (itr->cursor.nr)callchain_append (&itr->callchain, &itr->cursor, t - tprev);Signature · 1 line
2.10.2
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
Em Tue, Dec 13, 2016 at 07:54:42PM +0900, Namhyung Kim escreveu:
Quoted 12 lines · Arnaldo Carvalho de Melo
Quoted 10 lines
Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
Quoted 6 lines
When --idle-hist option is used, run/wait time and sched delay value should be shown for idle task only. But due to internal accounting, a last thread has same value of next idle task's and it was shown.
In the below example, firefox after idle task has same run time of idle task's.
Same as last message, is this something I can fold into a patch yet in my perf/core branch?
Quoted 6 lines
Yep,
Fixes 78de3657008b ("perf sched timehist: Add -I/--idle-hist option")I guess it makes a conflict on the callchain code. In case it doesn't look obvious to resolve, please let me know..
Ok, fixed up, after building it, before 'rebase --continue', we get:
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- --------- 47548.582141 [0000] perf[17869] 0.000 0.000 0.000 47548.583814 [0003] rcu_sched[7] 0.000 0.000 0.000 47548.583825 [0003] <idle> 0.005 0.000 0.010 47548.583826 [0002] rcuos/0[9] 0.000 0.000 0.000 47548.583828 [0003] rcu_sched[7] 0.000 0.000 0.000 47548.587797 [0003] <idle> 0.002 0.000 3.969 47548.587799 [0003] rcu_sched[7] 0.000 0.000 0.000 47548.587799 [0002] <idle> 0.011 0.000 3.973 47548.587808 [0002] rcuos/0[9] 0.000 0.000 0.000 47548.594979 [0002] <idle> 0.008 0.000 7.171 47548.595014 [0002] Timer[4869/4832] 0.000 0.000 0.000 47548.595064 [0001] firefox[4832] 0.000 0.000 0.000 47548.603831 [0002] <idle> 0.034 0.000 8.817 47548.603874 [0001] <idle> 0.054 0.000 8.809
Which matches what you state as being the fix (task runtime after idle task).
git rebase --continue next...
- Arnaldo
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Add -I/--idle-hist option
In reply to Namhyung Kimperf sched timehist: Add -I/--idle-hist option
Commit-ID: 07235f84ece6b66f43334881806aad3467cf3d84 Gitweb: http://git.kernel.org/tip/07235f84ece6b66f43334881806aad3467cf3d84 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:54 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:45 -0300
perf sched timehist: Add -I/--idle-hist option
The --idle-hist option is to analyze system idle state so which process makes cpu to go idle. If this option is specified, non-idle events will be skipped and processes switching to/from idle will be shown.
This option is mostly useful when used with --summary(-only) option. In the idle-time summary view, idle time is accounted to previous thread which is run before idle task.
The example output looks like following:
Idle-time summary
comm parent sched-out idle-time min-idle avg-idle max-idle stddev migrations
(count) (msec) (msec) (msec) (msec) %
--------------------------------------------------------------------------------------------
rcu_preempt[7] 2 95 550.872 0.011 5.798 23.146 7.63 0
migration/1[16] 2 1 15.558 15.558 15.558 15.558 0.00 0
khugepaged[39] 2 1 3.062 3.062 3.062 3.062 0.00 0
kworker/0:1H[124] 2 2 4.728 0.611 2.364 4.116 74.12 0
systemd-journal[167] 1 1 4.510 4.510 4.510 4.510 0.00 0
kworker/u16:3[558] 2 13 74.737 0.080 5.749 12.960 21.96 0
irq/34-iwlwifi[628] 2 21 118.403 0.032 5.638 23.990 24.00 0
kworker/u17:0[673] 2 1 3.523 3.523 3.523 3.523 0.00 0
dbus-daemon[722] 1 1 6.743 6.743 6.743 6.743 0.00 0
ifplugd[741] 1 1 58.826 58.826 58.826 58.826 0.00 0
wpa_supplicant[1490] 1 1 13.302 13.302 13.302 13.302 0.00 0
wpa_actiond[1492] 1 2 4.064 0.168 2.032 3.896 91.72 0
dockerd[1500] 1 1 0.055 0.055 0.055 0.055 0.00 0...
--- tools/perf/Documentation/perf-sched.txt | 4 +++ tools/perf/builtin-sched.c | 46 +++++++++++++++++++++++++++++---- 2 files changed, 45 insertions(+), 5 deletions(-)
tools/perf/Documentation/perf-sched.txt +4 -0
@@ -132,6 +132,10 @@ OPTIONS for 'perf sched timehist' --migrations:: Show migration events. +-I:: +--idle-hist:: + Show idle-related events only. + --time:: Only analyze samples within given time window: <start>,<stop>. Times have the format seconds.microseconds. If start is not given (i.e., time
tools/perf/builtin-sched.c +41 -5
70 lines not on this page · raw message
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
In reply to Namhyung KimEm Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
When idle hist is enabled, the
itr->last_threadshould be set so that it can find which thread run before idle task. But it was only set in thesave_idle_callchain(). This makes idle task doesn't show up in the output when callchain is not recorded.
It is important to provide a Fixes: tag so that I can check if the problem was introduced by some patch still not sent to Ingo, in which case I could try and merge them, is this the case here?
- Arnaldo
Quoted 94 lines
Before:
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.000 ...After:
197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753914 [0001] <idle> 0.000 0.000 0.079 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 197731.756625 [0003] <idle> 0.123 0.000 2.709 ...Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-)tools/perf/builtin-sched.c +17
-16@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } -static void save_idle_callchain (struct thread *thread, +static void save_idle_callchain (struct idle_thread_runtime *itr,struct perf_sample *sample) { -struct thread *idle; -struct idle_thread_runtime *itr; -if (!symbol_conf.use_callchain || sample->callchain ==NULL )return ; - idle =get_idle_thread (sample->cpu); -if (idle ==NULL ) { -pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); -return ; - } - - itr =thread__priv (idle); -if (itr ==NULL ) -return ; - - itr->last_thread = thread;callchain_cursor__copy (&itr->cursor, &callchain_cursor); }@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,save_task_callchain (sched, sample, evsel, machine);if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; +/* copy task callchain when entering to idle */ if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) -save_idle_callchain (thread, sample); +save_idle_callchain (itr, sample); } }Signature · 1 line
2.10.2
Namhyung Kim
maintainerRe: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
Hi Arnaldo,
Quoted 9 lines · Arnaldo Carvalho de Melo
Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
When idle hist is enabled, the
itr->last_threadshould be set so that it can find which thread run before idle task. But it was only set in thesave_idle_callchain(). This makes idle task doesn't show up in the output when callchain is not recorded.It is important to provide a Fixes: tag so that I can check if the problem was introduced by some patch still not sent to Ingo, in which case I could try and merge them, is this the case here?
Yes,
Thanks,
Namhyung
Quoted 95 lines
Quoted 95 lines
Before:
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.000 ...After:
197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753914 [0001] <idle> 0.000 0.000 0.079 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 197731.756625 [0003] <idle> 0.123 0.000 2.709 ...Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-)tools/perf/builtin-sched.c +17
-16@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } -static void save_idle_callchain (struct thread *thread, +static void save_idle_callchain (struct idle_thread_runtime *itr,struct perf_sample *sample) { -struct thread *idle; -struct idle_thread_runtime *itr; -if (!symbol_conf.use_callchain || sample->callchain ==NULL )return ; - idle =get_idle_thread (sample->cpu); -if (idle ==NULL ) { -pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); -return ; - } - - itr =thread__priv (idle); -if (itr ==NULL ) -return ; - - itr->last_thread = thread;callchain_cursor__copy (&itr->cursor, &callchain_cursor); }@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,save_task_callchain (sched, sample, evsel, machine);if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; +/* copy task callchain when entering to idle */ if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) -save_idle_callchain (thread, sample); +save_idle_callchain (itr, sample); } }Signature · 1 line
2.10.2
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
Em Tue, Dec 13, 2016 at 07:49:44PM +0900, Namhyung Kim escreveu:
Quoted 9 lines
Hi Arnaldo,
Quoted 6 lines · Arnaldo Carvalho de Melo
Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
When idle hist is enabled, the
itr->last_threadshould be set so that it can find which thread run before idle task. But it was only set in thesave_idle_callchain(). This makes idle task doesn't show up in the output when callchain is not recorded.
Quoted 7 lines
Quoted 3 lines
It is important to provide a Fixes: tag so that I can check if the problem was introduced by some patch still not sent to Ingo, in which case I could try and merge them, is this the case here?
Yes,
Fixes b50c3ab0f1cc ("perf sched timehist: Save callchain when entering idle")
Thanks, will try and merge this and the other one so that we remove those as bisection problems when looking for problems in this area.
- Arnaldo
Quoted 99 lines
Thanks,
NamhyungQuoted 95 lines
Quoted 95 lines
Before:
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.000 ...After:
197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753914 [0001] <idle> 0.000 0.000 0.079 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 197731.756625 [0003] <idle> 0.123 0.000 2.709 ...Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-)tools/perf/builtin-sched.c +17
-16@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } -static void save_idle_callchain (struct thread *thread, +static void save_idle_callchain (struct idle_thread_runtime *itr,struct perf_sample *sample) { -struct thread *idle; -struct idle_thread_runtime *itr; -if (!symbol_conf.use_callchain || sample->callchain ==NULL )return ; - idle =get_idle_thread (sample->cpu); -if (idle ==NULL ) { -pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); -return ; - } - - itr =thread__priv (idle); -if (itr ==NULL ) -return ; - - itr->last_thread = thread;callchain_cursor__copy (&itr->cursor, &callchain_cursor); }@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,save_task_callchain (sched, sample, evsel, machine);if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; +/* copy task callchain when entering to idle */ if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) -save_idle_callchain (thread, sample); +save_idle_callchain (itr, sample); } }Signature · 1 line
2.10.2
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
In reply to Namhyung KimEm Tue, Dec 13, 2016 at 07:49:44PM +0900, Namhyung Kim escreveu:
Quoted 9 lines
Hi Arnaldo,
Quoted 6 lines · Arnaldo Carvalho de Melo
Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
When idle hist is enabled, the
itr->last_threadshould be set so that it can find which thread run before idle task. But it was only set in thesave_idle_callchain(). This makes idle task doesn't show up in the output when callchain is not recorded.
Quoted 7 lines
Quoted 3 lines
It is important to provide a Fixes: tag so that I can check if the problem was introduced by some patch still not sent to Ingo, in which case I could try and merge them, is this the case here?
Yes,
Fixes b50c3ab0f1cc ("perf sched timehist: Save callchain when entering idle")
Ok, merged this fix with b50c3ab0f1cc, adding a second Link tag pointing to this fix, now to the second fix...
- Arnaldo
Quoted 99 lines
Thanks,
NamhyungQuoted 95 lines
Quoted 95 lines
Before:
$ perf sched timehist --idle-hist Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) --------------- ------ -------------------- --------- --------- --------- 197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.000 ...After:
197731.753834 [0001] perf[27469] 0.000 0.000 0.000 197731.753914 [0001] <idle> 0.000 0.000 0.079 197731.753915 [0003] migration/3[23] 0.000 0.000 0.000 197731.754335 [0002] firefox[17773/17739] 0.000 0.000 0.000 197731.754486 [0001] sleep[27470] 0.000 0.000 0.000 197731.754903 [0002] <idle> 0.047 0.000 0.567 197731.754981 [0002] firefox[17773/17739] 0.000 0.000 0.567 197731.755922 [0002] <idle> 0.078 0.000 0.941 197731.755994 [0002] firefox[17773/17739] 0.000 0.000 0.941 197731.756625 [0003] <idle> 0.123 0.000 2.709 ...Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-)tools/perf/builtin-sched.c +17
-16@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } -static void save_idle_callchain (struct thread *thread, +static void save_idle_callchain (struct idle_thread_runtime *itr,struct perf_sample *sample) { -struct thread *idle; -struct idle_thread_runtime *itr; -if (!symbol_conf.use_callchain || sample->callchain ==NULL )return ; - idle =get_idle_thread (sample->cpu); -if (idle ==NULL ) { -pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); -return ; - } - - itr =thread__priv (idle); -if (itr ==NULL ) -return ; - - itr->last_thread = thread;callchain_cursor__copy (&itr->cursor, &callchain_cursor); }@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,save_task_callchain (sched, sample, evsel, machine);if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; +/* copy task callchain when entering to idle */ if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) -save_idle_callchain (thread, sample); +save_idle_callchain (itr, sample); } }Signature · 1 line
2.10.2
tip-bot for Namhyung Kim
merge bot[tip:perf/urgent] perf sched timehist: Save callchain when entering idle
In reply to Namhyung Kimperf sched timehist: Save callchain when entering idle
Commit-ID: 699b5b920db04a6ff5c03a519e4c182aeb350952 Gitweb: http://git.kernel.org/tip/699b5b920db04a6ff5c03a519e4c182aeb350952 Author: Namhyung Kim <[email protected]> AuthorDate: Thu, 8 Dec 2016 23:47:52 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Thu, 15 Dec 2016 16:25:44 -0300
perf sched timehist: Save callchain when entering idle
In order to investigate the idleness reason, it is necessary to keep the callchains when entering idle. This can be identified by the sched:sched_switch event having the next_pid field as 0.
--- tools/perf/builtin-sched.c | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+)
tools/perf/builtin-sched.c +30 -0
@@ -200,6 +200,7 @@ struct perf_sched {/* options for timehist command */ bool summary;bool summary_only; +bool idle_hist;bool show_callchain;unsigned int max_stack;bool show_cpu_visual;
@@ -2101,6 +2102,15 @@ static struct thread *get_idle_thread(int cpu)return idle_threads[cpu]; } +static void save_idle_callchain (struct idle_thread_runtime *itr, +struct perf_sample *sample) +{ +if (!symbol_conf.use_callchain || sample->callchain ==NULL ) +return ; + +callchain_cursor__copy (&itr->cursor, &callchain_cursor); +} +/* * handle runtime stats saved per thread */
@@ -2154,6 +2164,26 @@ static struct thread *timehist_get_thread(struct perf_sched *sched, }save_task_callchain (sched, sample, evsel, machine); +if (sched->idle_hist) { +struct thread *idle; +struct idle_thread_runtime *itr; + + idle =get_idle_thread (sample->cpu); +if (idle ==NULL ) { +pr_err ("Failed to get idle thread for cpu %d.\n" , sample->cpu); +return NULL ; + } + + itr =thread__priv (idle); +if (itr ==NULL ) +return NULL ; + + itr->last_thread = thread; + +/* copy task callchain when entering to idle */ +if (perf_evsel__intval (evsel, sample,"next_pid" ) ==0 ) +save_idle_callchain (itr, sample); + } }return thread;