Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1521807 > unrolled thread
| Started by | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| First post | 2016-11-14 17:20 +0100 |
| Last post | 2016-11-15 19:30 +0100 |
| Articles | 14 — 3 participants |
Back to article view | Back to linux.kernel
[PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 4/7] perf sched timehist: Add -w/--wakeups option Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 5/7] perf sched timehist: Add call graph options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 6/7] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 3/7] perf sched timehist: Add summary options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 7/7] perf sched: Add documentation for timehist options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:30 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-14 17:30 +0100
[PATCH RESEND 1/7] perf symbol: Print symbol offsets conditionally Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Ingo Molnar <mingo@kernel.org> - 2016-11-15 07:50 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-15 08:00 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Ingo Molnar <mingo@kernel.org> - 2016-11-15 08:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-15 16:20 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-15 16:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-15 19:30 +0100
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:20 +0100 |
| Subject | [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) |
| Message-ID | <sDs9b-RG-3@gated-at.bofh.it> |
Hello,
This patchset is a rebased version of David's sched timehist work [1].
I plan to improve perf sched command more and think that having
timehist command before the work looks good. It seems David is busy
these days, so I'm retrying it by myself.
This implements only basic feature and a few options. I just split
the patch to make it easier to review and did some cosmetic changes.
More patches will come later.
The below is from the David's original description:
------------------------8<-------------------------
'perf sched timehist' provides an analysis of scheduling events.
Example usage:
perf sched record -- sleep 1
perf sched timehist
By default it shows the individual schedule events, including the time between
sched-in events for the task, the task scheduling delay (time between wakeup
and actually running) and run time for the task:
time cpu task name[tid/pid] b/n time sch delay run time
------------- ---- -------------------- --------- --------- ---------
79371.874569 [11] gcc[31949] 0.014 0.000 1.148
79371.874591 [10] gcc[31951] 0.000 0.000 0.024
79371.874603 [10] migration/10[59] 3.350 0.004 0.011
79371.874604 [11] <idle> 1.148 0.000 0.035
79371.874723 [05] <idle> 0.016 0.000 1.383
79371.874746 [05] gcc[31949] 0.153 0.078 0.022
...
Times are in msec.usec.
If callchains were recorded they are appended to the line with a default stack depth of 5:
79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork
79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec
79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork
79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary
79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary
79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid
--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.
Similar to perf-trace -s and -S can be used to dump a statistical summary
without or with events (respectively). Statistics include min run time,
average run time and max run time. Stats are also shown for run time by
cpu.
The cpu-visual option provides a visual aid for sched switches by cpu:
...
79371.874569 [11] s gcc[31949] 0.000014 0.000000 0.001148
79371.874591 [10] s gcc[31951] 0.000000 0.000000 0.000024
79371.874603 [10] s migration/10[59] 0.003350 0.000004 0.000011
79371.874604 [11] i <idle> 0.001148 0.000000 0.000035
79371.874723 [05] i <idle> 0.000016 0.000000 0.001383
79371.874746 [05] s gcc[31949] 0.000153 0.000078 0.000022
...
------------------------8<-------------------------
This code is available at 'perf/timehist-v1' branch in my tree
git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
Any feedback is welcomed, David?
Thanks,
Namhyung
[1] https://lkml.org/lkml/2013/12/1/129
David Ahern (6):
perf sched timehist: Introduce timehist command
perf sched timehist: Add summary options
perf sched timehist: Add -w/--wakeups option
perf sched timehist: Add call graph options
perf sched timehist: Add -V/--cpu-visual option
perf sched: Add documentation for timehist options
Namhyung Kim (1):
perf symbol: Print symbol offsets conditionally
tools/perf/Documentation/perf-sched.txt | 46 +-
tools/perf/builtin-sched.c | 912 +++++++++++++++++++++++++++++++-
tools/perf/util/evsel_fprintf.c | 6 +-
tools/perf/util/symbol.h | 3 +-
tools/perf/util/symbol_fprintf.c | 11 +-
5 files changed, 963 insertions(+), 15 deletions(-)
--
2.10.1
[toc] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:20 +0100 |
| Subject | [PATCH 4/7] perf sched timehist: Add -w/--wakeups option |
| Message-ID | <sDs9b-RG-7@gated-at.bofh.it> |
| In reply to | #1521807 |
From: David Ahern <dsahern@gmail.com>
The -w option is to show wakeup events with timehist.
$ perf sched timehist -w
time cpu task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
2412598.429689 [0002] perf[7219] awakened: perf[7220]
2412598.429696 [0009] <idle> 0.000 0.000 0.000
2412598.429767 [0002] perf[7219] 0.000 0.000 0.000
2412598.429780 [0009] perf[7220] awakened: migration/9[53]
...
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 58 ++++++++++++++++++++++++++++++++++++++++++----
1 file changed, 54 insertions(+), 4 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 4b38f1411444..e59cd7574d0f 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -198,6 +198,7 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_wakeups;
u64 skipped_samples;
};
@@ -1808,7 +1809,8 @@ static void timehist_header(void)
printf("\n");
}
-static void timehist_print_sample(struct perf_sample *sample,
+static void timehist_print_sample(struct perf_sched *sched,
+ struct perf_sample *sample,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1822,6 +1824,10 @@ static void timehist_print_sample(struct perf_sample *sample,
print_sched_time(tr->dt_between, 6);
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
+
+ if (sched->show_wakeups)
+ printf(" %-*s", comm_width, "");
+
printf("\n");
}
@@ -2029,12 +2035,44 @@ static bool timehist_skip_sample(struct perf_sched *sched,
return rc;
}
-static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+static void timehist_print_wakeup_event(struct perf_sched *sched,
+ struct perf_sample *sample,
+ struct machine *machine,
+ struct thread *awakened)
+{
+ struct thread *thread;
+ char tstr[64];
+
+ thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+ if (thread == NULL)
+ return;
+
+ /* show wakeup unless both awakee and awaker are filtered */
+ if (timehist_skip_sample(sched, thread) &&
+ timehist_skip_sample(sched, awakened)) {
+ return;
+ }
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s [%04d] ", tstr, sample->cpu);
+
+ printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+ /* dt spacer */
+ printf(" %9s %9s %9s ", "", "", "");
+
+ printf("awakened: %s", timehist_get_commstr(awakened));
+
+ printf("\n");
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool,
union perf_event *event __maybe_unused,
struct perf_evsel *evsel,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct thread *thread;
struct thread_runtime *tr = NULL;
/* want pid of awakened task not pid in sample */
@@ -2051,6 +2089,10 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
if (tr->ready_to_run == 0)
tr->ready_to_run = sample->time;
+ /* show wakeups if requested */
+ if (sched->show_wakeups)
+ timehist_print_wakeup_event(sched, sample, machine, thread);
+
return 0;
}
@@ -2060,12 +2102,12 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct addr_location al;
struct thread *thread;
struct thread_runtime *tr = NULL;
u64 tprev;
int rc = 0;
- struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
if (machine__resolve(machine, &al, sample) < 0) {
pr_err("problem processing %d event. skipping it\n",
@@ -2093,7 +2135,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sample, thread);
+ timehist_print_sample(sched, sample, thread);
out:
if (tr) {
@@ -2724,6 +2766,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"Show only syscall summary with statistics"),
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
+ OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
OPT_PARENT(sched_options)
};
@@ -2815,6 +2858,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
if (argc)
usage_with_options(timehist_usage, timehist_options);
}
+ if (sched.show_wakeups && sched.summary_only) {
+ pr_err(" Error: -s and -w are mutually exclusive.\n");
+ parse_options_usage(timehist_usage, timehist_options, "s", true);
+ parse_options_usage(NULL, timehist_options, "w", true);
+ return -EINVAL;
+ }
+
return perf_sched__timehist(&sched);
} else {
usage_with_options(sched_usage, sched_options);
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:20 +0100 |
| Subject | [PATCH 5/7] perf sched timehist: Add call graph options |
| Message-ID | <sDs9b-RG-21@gated-at.bofh.it> |
| In reply to | #1521807 |
From: David Ahern <dsahern@gmail.com>
If callchains were recorded they are appended to the line with a default stack depth of 5:
79371.874569 [0011] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork
79371.874591 [0010] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec
79371.874603 [0010] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork
79371.874604 [0011] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary
79371.874723 [0005] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary
79371.874746 [0005] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid
--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 79 ++++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 76 insertions(+), 3 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index e59cd7574d0f..69a575b59d05 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -14,6 +14,7 @@
#include "util/thread_map.h"
#include "util/color.h"
#include "util/stat.h"
+#include "util/callchain.h"
#include <subcmd/parse-options.h>
#include "util/trace-event.h"
@@ -198,6 +199,8 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_callchain;
+ unsigned int max_stack;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1811,6 +1814,7 @@ static void timehist_header(void)
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
+ struct addr_location *al,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1828,6 +1832,17 @@ static void timehist_print_sample(struct perf_sched *sched,
if (sched->show_wakeups)
printf(" %-*s", comm_width, "");
+ if (thread->tid == 0)
+ goto out;
+
+ if (sched->show_callchain)
+ printf(" ");
+
+ sample__fprintf_sym(sample, al, 0,
+ EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE,
+ &callchain_cursor, stdout);
+
+out:
printf("\n");
}
@@ -1880,8 +1895,12 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
}
static bool is_idle_sample(struct perf_sample *sample,
- struct perf_evsel *evsel)
+ struct perf_evsel *evsel,
+ struct machine *machine)
{
+ struct thread *thread;
+ struct callchain_cursor *cursor = &callchain_cursor;
+
/* pid 0 == swapper == idle task */
if (sample->pid == 0)
return true;
@@ -1890,6 +1909,25 @@ static bool is_idle_sample(struct perf_sample *sample,
if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
return true;
}
+
+ /* 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;
+ }
+
+ if (!symbol_conf.use_callchain || sample->callchain == NULL)
+ return false;
+
+ if (thread__resolve_callchain(thread, cursor, evsel, sample,
+ NULL, NULL, PERF_MAX_STACK_DEPTH) != 0) {
+ if (verbose)
+ error("Failed to resolve callchain. Skipping\n");
+
+ return false;
+ }
+ callchain_cursor_commit(cursor);
return false;
}
@@ -2006,7 +2044,7 @@ static struct thread *timehist_get_thread(struct perf_sample *sample,
{
struct thread *thread;
- if (is_idle_sample(sample, evsel)) {
+ if (is_idle_sample(sample, evsel, machine)) {
thread = get_idle_thread(sample->cpu);
if (thread == NULL)
pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
@@ -2135,7 +2173,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sched, sample, thread);
+ timehist_print_sample(sched, sample, &al, thread);
out:
if (tr) {
@@ -2328,6 +2366,30 @@ static int perf_timehist__process_sample(struct perf_tool *tool,
return err;
}
+static int timehist_check_attr(struct perf_sched *sched,
+ struct perf_evlist *evlist)
+{
+ struct perf_evsel *evsel;
+ struct evsel_runtime *er;
+
+ list_for_each_entry(evsel, &evlist->entries, node) {
+ er = perf_evsel__get_runtime(evsel);
+ if (er == NULL) {
+ pr_err("Failed to allocate memory for evsel runtime data\n");
+ return -1;
+ }
+
+ if (sched->show_callchain &&
+ !(evsel->attr.sample_type & PERF_SAMPLE_CALLCHAIN)) {
+ pr_info("Samples do not have callchains.\n");
+ sched->show_callchain = 0;
+ symbol_conf.use_callchain = 0;
+ }
+ }
+
+ return 0;
+}
+
static int perf_sched__timehist(struct perf_sched *sched)
{
const struct perf_evsel_str_handler handlers[] = {
@@ -2360,6 +2422,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->tool.ordered_events = true;
sched->tool.ordering_requires_timestamps = true;
+ symbol_conf.use_callchain = sched->show_callchain;
+
session = perf_session__new(&file, false, &sched->tool);
if (session == NULL)
return -ENOMEM;
@@ -2368,6 +2432,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
symbol__init(&session->header.env);
+ if (timehist_check_attr(sched, evlist) != 0)
+ goto out;
+
setup_pager();
/* setup per-evsel handlers */
@@ -2715,6 +2782,8 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
.next_shortname1 = 'A',
.next_shortname2 = '0',
.skip_merge = 0,
+ .show_callchain = 1,
+ .max_stack = 5,
};
const struct option sched_options[] = {
OPT_STRING('i', "input", &input_name, "file",
@@ -2760,6 +2829,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"file", "vmlinux pathname"),
OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
"file", "kallsyms pathname"),
+ OPT_BOOLEAN('g', "call-graph", &sched.show_callchain,
+ "Display call chains if present (default on)"),
+ OPT_UINTEGER(0, "max-stack", &sched.max_stack,
+ "Maximum number of functions to display backtrace."),
OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
"Look for files with symbols relative to this directory"),
OPT_BOOLEAN('s', "summary", &sched.summary_only,
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:20 +0100 |
| Subject | [PATCH 6/7] perf sched timehist: Add -V/--cpu-visual option |
| Message-ID | <sDs9b-RG-15@gated-at.bofh.it> |
| In reply to | #1521807 |
From: David Ahern <dsahern@gmail.com>
The -V option provides a visual aid for sched switches by cpu:
$ perf sched timehist -V
time cpu 0123456789abc task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------- -------------------- --------- --------- ---------
...
2412598.429696 [0009] i <idle> 0.000 0.000 0.000
2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
2412598.429794 [0010] i <idle> 0.000 0.000 0.000
2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
2412598.432584 [0003] i <idle> 0.000 0.000 0.000
...
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 42 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 69a575b59d05..7b7d74b37ef1 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -201,6 +201,7 @@ struct perf_sched {
bool summary_only;
bool show_callchain;
unsigned int max_stack;
+ bool show_cpu_visual;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1784,10 +1785,23 @@ static char *timehist_get_commstr(struct thread *thread)
return str;
}
-static void timehist_header(void)
+static void timehist_header(struct perf_sched *sched)
{
+ u32 ncpus = sched->max_cpu + 1;
+ u32 i, j;
+
printf("%15s %6s ", "time", "cpu");
+ if (sched->show_cpu_visual) {
+ printf(" ");
+ for (i = 0, j = 0; i < ncpus; ++i) {
+ printf("%x", j++);
+ if (j > 15)
+ j = 0;
+ }
+ printf(" ");
+ }
+
printf(" %-20s %9s %9s %9s",
"task name", "b/n time", "sch delay", "run time");
@@ -1798,6 +1812,9 @@ static void timehist_header(void)
*/
printf("%15s %-6s ", "", "");
+ if (sched->show_cpu_visual)
+ printf(" %*s ", ncpus, "");
+
printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
/*
@@ -1805,6 +1822,9 @@ static void timehist_header(void)
*/
printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
+ if (sched->show_cpu_visual)
+ printf(" %.*s ", ncpus, graph_dotted_line);
+
printf(" %.20s %.9s %.9s %.9s",
graph_dotted_line, graph_dotted_line, graph_dotted_line,
graph_dotted_line);
@@ -1818,11 +1838,28 @@ static void timehist_print_sample(struct perf_sched *sched,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
+ u32 max_cpus = sched->max_cpu + 1;
char tstr[64];
timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual) {
+ u32 i;
+ char c;
+
+ printf(" ");
+ for (i = 0; i < max_cpus; ++i) {
+ /* flag idle times with 'i'; others are sched events */
+ if (i == sample->cpu)
+ c = (thread->tid == 0) ? 'i' : 's';
+ else
+ c = ' ';
+ printf("%c", c);
+ }
+ printf(" ");
+ }
+
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
print_sched_time(tr->dt_between, 6);
@@ -2093,6 +2130,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual)
+ printf(" %*s ", sched->max_cpu + 1, "");
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
@@ -2456,7 +2495,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->summary = sched->summary_only;
if (!sched->summary_only)
- timehist_header();
+ timehist_header(sched);
err = perf_session__process_events(session);
if (err) {
@@ -2840,6 +2879,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+ OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
OPT_PARENT(sched_options)
};
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:20 +0100 |
| Subject | [PATCH 3/7] perf sched timehist: Add summary options |
| Message-ID | <sDs9c-RG-37@gated-at.bofh.it> |
| In reply to | #1521807 |
From: David Ahern <dsahern@gmail.com>
The -s/--summary option is to show process runtime statistics. And the
-S/--with-summary option is to show the stats with the normal output.
$ perf sched timehist -s
Runtime summary
comm parent sched-in run-time min-run avg-run max-run stddev
(count) (msec) (msec) (msec) (msec) %
---------------------------------------------------------------------------------------------------------
ksoftirqd/0[3] 2 2 0.011 0.004 0.005 0.006 14.87
rcu_preempt[7] 2 11 0.071 0.002 0.006 0.017 20.23
watchdog/0[11] 2 1 0.002 0.002 0.002 0.002 0.00
watchdog/1[12] 2 1 0.004 0.004 0.004 0.004 0.00
...
Terminated tasks:
sleep[7220] 7219 3 0.770 0.087 0.256 0.576 62.28
Idle stats:
CPU 0 idle for 2352.006 msec
CPU 1 idle for 2764.497 msec
CPU 2 idle for 2998.229 msec
CPU 3 idle for 2967.800 msec
Total number of unique tasks: 52
Total number of context switches: 2532
Total run time (msec): 218.036
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 160 insertions(+), 6 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index f55900c833dd..4b38f1411444 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -194,6 +194,11 @@ struct perf_sched {
bool force;
bool skip_merge;
struct perf_sched_map map;
+
+ /* options for timehist command */
+ bool summary;
+ bool summary_only;
+ u64 skipped_samples;
};
/* per thread run time data */
@@ -2011,12 +2016,15 @@ static struct thread *timehist_get_thread(struct perf_sample *sample,
return thread;
}
-static bool timehist_skip_sample(struct thread *thread)
+static bool timehist_skip_sample(struct perf_sched *sched,
+ struct thread *thread)
{
bool rc = false;
- if (thread__is_filtered(thread))
+ if (thread__is_filtered(thread)) {
rc = true;
+ sched->skipped_samples++;
+ }
return rc;
}
@@ -2046,7 +2054,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
return 0;
}
-static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
+static int timehist_sched_change_event(struct perf_tool *tool,
union perf_event *event,
struct perf_evsel *evsel,
struct perf_sample *sample,
@@ -2057,6 +2065,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
struct thread_runtime *tr = NULL;
u64 tprev;
int rc = 0;
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
if (machine__resolve(machine, &al, sample) < 0) {
pr_err("problem processing %d event. skipping it\n",
@@ -2071,7 +2080,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
goto out;
}
- if (timehist_skip_sample(thread))
+ if (timehist_skip_sample(sched, thread))
goto out;
tr = thread__get_runtime(thread);
@@ -2083,7 +2092,8 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
tprev = perf_evsel__get_time(evsel, sample->cpu);
timehist_update_runtime_stats(tr, sample->time, tprev);
- timehist_print_sample(sample, thread);
+ if (!sched->summary_only)
+ timehist_print_sample(sample, thread);
out:
if (tr) {
@@ -2123,6 +2133,131 @@ static int process_lost(struct perf_tool *tool __maybe_unused,
}
+static void print_thread_runtime(struct thread *t,
+ struct thread_runtime *r)
+{
+ double mean = avg_stats(&r->run_stats);
+ float stddev;
+
+ printf("%*s %5d %9" PRIu64 " ",
+ comm_width, timehist_get_commstr(t), t->ppid,
+ (u64) r->run_stats.n);
+
+ print_sched_time(r->total_run_time, 8);
+ stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean);
+ print_sched_time(r->run_stats.min, 6);
+ printf(" ");
+ print_sched_time((u64) mean, 6);
+ printf(" ");
+ print_sched_time(r->run_stats.max, 6);
+ printf(" ");
+ printf("%5.2f", stddev);
+ printf("\n");
+}
+
+struct total_run_stats {
+ u64 sched_count;
+ u64 task_count;
+ u64 total_run_time;
+};
+
+static int __show_thread_runtime(struct thread *t, void *priv)
+{
+ struct total_run_stats *stats = priv;
+ struct thread_runtime *r;
+
+ if (thread__is_filtered(t))
+ return 0;
+
+ r = thread__priv(t);
+ if (r && r->run_stats.n) {
+ stats->task_count++;
+ stats->sched_count += r->run_stats.n;
+ stats->total_run_time += r->total_run_time;
+ print_thread_runtime(t, r);
+ }
+
+ return 0;
+}
+
+static int show_thread_runtime(struct thread *t, void *priv)
+{
+ if (t->dead)
+ return 0;
+
+ return __show_thread_runtime(t, priv);
+}
+
+static int show_deadthread_runtime(struct thread *t, void *priv)
+{
+ if (!t->dead)
+ return 0;
+
+ return __show_thread_runtime(t, priv);
+}
+
+static void timehist_print_summary(struct perf_sched *sched,
+ struct perf_session *session)
+{
+ struct machine *m = &session->machines.host;
+ struct total_run_stats totals;
+ u64 task_count;
+ struct thread *t;
+ struct thread_runtime *r;
+ int i;
+
+ memset(&totals, 0, sizeof(totals));
+
+ if (comm_width < 30)
+ comm_width = 30;
+
+ printf("\nRuntime summary\n");
+ printf("%*s parent sched-in ", comm_width, "comm");
+ printf(" run-time min-run avg-run max-run stddev\n");
+ printf("%*s (count) ", comm_width, "");
+ printf(" (msec) (msec) (msec) (msec) %%\n");
+ printf("%.105s\n", graph_dotted_line);
+
+ machine__for_each_thread(m, show_thread_runtime, &totals);
+ task_count = totals.task_count;
+ if (!task_count)
+ printf("<no still running tasks>\n");
+
+ printf("\nTerminated tasks:\n");
+ machine__for_each_thread(m, show_deadthread_runtime, &totals);
+ if (task_count == totals.task_count)
+ printf("<no terminated tasks>\n");
+
+ /* CPU idle stats not tracked when samples were skipped */
+ if (sched->skipped_samples)
+ return;
+
+ printf("\nIdle stats:\n");
+ for (i = 0; i <= idle_max_cpu; ++i) {
+ t = idle_threads[i];
+ if (!t)
+ continue;
+
+ r = thread__priv(t);
+ if (r && r->run_stats.n) {
+ totals.sched_count += r->run_stats.n;
+ printf(" CPU %2d idle for ", i);
+ print_sched_time(r->total_run_time, 6);
+ printf(" msec\n");
+ } else
+ printf(" CPU %2d idle entire time window\n", i);
+ }
+
+ printf("\n"
+ " Total number of unique tasks: %" PRIu64 "\n"
+ "Total number of context switches: %" PRIu64 "\n"
+ " Total run time (msec): ",
+ totals.task_count, totals.sched_count);
+
+ print_sched_time(totals.total_run_time, 2);
+ printf("\n");
+}
+
typedef int (*sched_handler)(struct perf_tool *tool,
union perf_event *event,
struct perf_evsel *evsel,
@@ -2164,6 +2299,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
};
struct perf_session *session;
+ struct perf_evlist *evlist;
int err = -1;
/*
@@ -2186,6 +2322,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
if (session == NULL)
return -ENOMEM;
+ evlist = session->evlist;
+
symbol__init(&session->header.env);
setup_pager();
@@ -2204,7 +2342,12 @@ static int perf_sched__timehist(struct perf_sched *sched)
if (init_idle_threads(sched->max_cpu))
goto out;
- timehist_header();
+ /* summary_only implies summary option, but don't overwrite summary if set */
+ if (sched->summary_only)
+ sched->summary = sched->summary_only;
+
+ if (!sched->summary_only)
+ timehist_header();
err = perf_session__process_events(session);
if (err) {
@@ -2212,6 +2355,13 @@ static int perf_sched__timehist(struct perf_sched *sched)
goto out;
}
+ sched->nr_events = evlist->stats.nr_events[0];
+ sched->nr_lost_events = evlist->stats.total_lost;
+ sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST];
+
+ if (sched->summary)
+ timehist_print_summary(sched, session);
+
out:
free_idle_threads();
perf_session__delete(session);
@@ -2570,6 +2720,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"file", "kallsyms pathname"),
OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
"Look for files with symbols relative to this directory"),
+ OPT_BOOLEAN('s', "summary", &sched.summary_only,
+ "Show only syscall summary with statistics"),
+ OPT_BOOLEAN('S', "with-summary", &sched.summary,
+ "Show all syscalls and summary with statistics"),
OPT_PARENT(sched_options)
};
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:30 +0100 |
| Subject | [PATCH 7/7] perf sched: Add documentation for timehist options |
| Message-ID | <sDsiR-Vh-13@gated-at.bofh.it> |
| In reply to | #1521807 |
From: David Ahern <dsahern@gmail.com>
Add entry to perf-sched documentation for timehist command and its
options.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/Documentation/perf-sched.txt | 46 +++++++++++++++++++++++++++++++--
1 file changed, 44 insertions(+), 2 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 1cc08cc47ac5..a0344643f008 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -8,11 +8,11 @@ perf-sched - Tool to trace/measure scheduler properties (latencies)
SYNOPSIS
--------
[verse]
-'perf sched' {record|latency|map|replay|script}
+'perf sched' {record|latency|map|replay|script|timehist}
DESCRIPTION
-----------
-There are five variants of perf sched:
+There are several variants of perf sched:
'perf sched record <command>' to record the scheduling events
of an arbitrary workload.
@@ -36,6 +36,11 @@ There are five variants of perf sched:
are running on a CPU. A '*' denotes the CPU that had the event, and
a dot signals an idle CPU.
+ 'perf sched timehist' to show context-switching analysis with times
+ between schedule-in, schedule delay, and run time. If callchains are
+ present stack trace is dumped at the end of the line. A summary of
+ run times can be shown as well.
+
OPTIONS
-------
-i::
@@ -66,6 +71,43 @@ OPTIONS for 'perf sched map'
--color-pids::
Highlight the given pids.
+OPTIONS for 'perf sched timehist'
+---------------------------------
+-k::
+--vmlinux=<file>::
+ vmlinux pathname
+
+--kallsyms=<file>::
+ kallsyms pathname
+
+-s::
+--summary::
+ Show only a summary of scheduling by thread with min, max, and average
+ run times (in sec) and relative stddev.
+
+-S::
+--with-summary::
+ Show all scheduling events followed by a summary by thread with min,
+ max, and average run times (in sec) and relative stddev.
+
+-w::
+--wakeups::
+ Show wakeup events.
+
+--call-graph::
+ Display call chains. Default is on. Use --no-call-graph to suppress
+
+--max-stack::
+ Set the stack depth limit when showing the callchains. Default: 5
+
+--symfs=<directory>::
+ Look for files with symbols relative to this directory.
+
+-V::
+--cpu-visual::
+ Add a visual that better emphasizes activity by cpu. Idle times
+ are denoted with 'i'; schedule events with an 's'.
+
SEE ALSO
--------
linkperf:perf-record[1]
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | David Ahern <dsahern@gmail.com> |
|---|---|
| Date | 2016-11-14 17:30 +0100 |
| Message-ID | <sDsiS-Vh-39@gated-at.bofh.it> |
| In reply to | #1521807 |
On 11/14/16 9:12 AM, Namhyung Kim wrote: > Hello, > > This patchset is a rebased version of David's sched timehist work [1]. > I plan to improve perf sched command more and think that having > timehist command before the work looks good. It seems David is busy > these days, so I'm retrying it by myself. > > This implements only basic feature and a few options. I just split > the patch to make it easier to review and did some cosmetic changes. > More patches will come later. > > The below is from the David's original description: > -----8<----- > > This code is available at 'perf/timehist-v1' branch in my tree > > git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git > > Any feedback is welcomed, David? > Love to see this go in. Thanks for reviving the patches.
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-14 17:40 +0100 |
| Subject | [PATCH RESEND 1/7] perf symbol: Print symbol offsets conditionally |
| Message-ID | <sDssx-YN-37@gated-at.bofh.it> |
| In reply to | #1521807 |
The __symbol__fprintf_symname_offs() always shows symbol offsets. So
there's no difference between 'perf script -F ip,sym' and 'perf script
-F ip,sym,symoff'. I don't think it's a desired behavior..
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/util/evsel_fprintf.c | 6 ++++--
tools/perf/util/symbol.h | 3 ++-
tools/perf/util/symbol_fprintf.c | 11 ++++++-----
3 files changed, 12 insertions(+), 8 deletions(-)
diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index 662a0a6182e7..ccb602397b60 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -137,7 +137,8 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(node->sym, &node_al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(node->sym, &node_al,
print_unknown_as_addr, fp);
@@ -188,7 +189,8 @@ int sample__fprintf_sym(struct perf_sample *sample, struct addr_location *al,
printed += fprintf(fp, " ");
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(al->sym, al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(al->sym, al,
print_unknown_as_addr, fp);
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index d964844eb314..18f63f65607a 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -281,7 +281,8 @@ int symbol__annotation_init(void);
struct symbol *symbol__new(u64 start, u64 len, u8 binding, const char *name);
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp);
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp);
size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al, FILE *fp);
size_t __symbol__fprintf_symname(const struct symbol *sym,
diff --git a/tools/perf/util/symbol_fprintf.c b/tools/perf/util/symbol_fprintf.c
index a680bdaa65dc..7c6b33e8e2d2 100644
--- a/tools/perf/util/symbol_fprintf.c
+++ b/tools/perf/util/symbol_fprintf.c
@@ -15,14 +15,15 @@ size_t symbol__fprintf(struct symbol *sym, FILE *fp)
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp)
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp)
{
unsigned long offset;
size_t length;
if (sym && sym->name) {
length = fprintf(fp, "%s", sym->name);
- if (al) {
+ if (al && print_offsets) {
if (al->addr < sym->end)
offset = al->addr - sym->start;
else
@@ -40,19 +41,19 @@ size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, false, fp);
+ return __symbol__fprintf_symname_offs(sym, al, false, true, fp);
}
size_t __symbol__fprintf_symname(const struct symbol *sym,
const struct addr_location *al,
bool unknown_as_addr, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, fp);
+ return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, false, fp);
}
size_t symbol__fprintf_symname(const struct symbol *sym, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, NULL, false, fp);
+ return __symbol__fprintf_symname_offs(sym, NULL, false, false, fp);
}
size_t dso__fprintf_symbols_by_name(struct dso *dso,
--
2.10.1
[toc] | [prev] | [next] | [standalone]
| From | Ingo Molnar <mingo@kernel.org> |
|---|---|
| Date | 2016-11-15 07:50 +0100 |
| Message-ID | <sDFJ8-1pY-13@gated-at.bofh.it> |
| In reply to | #1521807 |
* Namhyung Kim <namhyung@kernel.org> wrote: > Hello, > > This patchset is a rebased version of David's sched timehist work [1]. > I plan to improve perf sched command more and think that having > timehist command before the work looks good. It seems David is busy > these days, so I'm retrying it by myself. > > This implements only basic feature and a few options. I just split > the patch to make it easier to review and did some cosmetic changes. > More patches will come later. > > The below is from the David's original description: > > ------------------------8<------------------------- > 'perf sched timehist' provides an analysis of scheduling events. > > Example usage: > perf sched record -- sleep 1 > perf sched timehist Cool, very nice! > By default it shows the individual schedule events, including the time between > sched-in events for the task, the task scheduling delay (time between wakeup > and actually running) and run time for the task: > > time cpu task name[tid/pid] b/n time sch delay run time > ------------- ---- -------------------- --------- --------- --------- > 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 > 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 > 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 > 79371.874604 [11] <idle> 1.148 0.000 0.035 > 79371.874723 [05] <idle> 0.016 0.000 1.383 > 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 > ... What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column 'sch wait' instead, or so? > Times are in msec.usec. > > If callchains were recorded they are appended to the line with a default stack depth of 5: > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid So when I first saw this it was hard for me to disambiguate individual function names. Wouldn't this be a bit more readable: > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() Or: > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() (i.e. visually separate the first entry - and list the rest.) Or maybe it could be ASCII color coded so that the different entries are easier to separate: for example the functions could be printed in alternating white/grey color? Thanks, Ingo
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-15 08:00 +0100 |
| Message-ID | <sDFSN-1t7-1@gated-at.bofh.it> |
| In reply to | #1522387 |
Hi Ingo, On Tue, Nov 15, 2016 at 07:42:14AM +0100, Ingo Molnar wrote: > > * Namhyung Kim <namhyung@kernel.org> wrote: > > > Hello, > > > > This patchset is a rebased version of David's sched timehist work [1]. > > I plan to improve perf sched command more and think that having > > timehist command before the work looks good. It seems David is busy > > these days, so I'm retrying it by myself. > > > > This implements only basic feature and a few options. I just split > > the patch to make it easier to review and did some cosmetic changes. > > More patches will come later. > > > > The below is from the David's original description: > > > > ------------------------8<------------------------- > > 'perf sched timehist' provides an analysis of scheduling events. > > > > Example usage: > > perf sched record -- sleep 1 > > perf sched timehist > > > Cool, very nice! :) > > > By default it shows the individual schedule events, including the time between > > sched-in events for the task, the task scheduling delay (time between wakeup > > and actually running) and run time for the task: > > > > time cpu task name[tid/pid] b/n time sch delay run time > > ------------- ---- -------------------- --------- --------- --------- > > 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 > > 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 > > 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 > > 79371.874604 [11] <idle> 1.148 0.000 0.035 > > 79371.874723 [05] <idle> 0.016 0.000 1.383 > > 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 > > ... > > What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column > 'sch wait' instead, or so? Looks better, or what about 'wait time'? > > > > Times are in msec.usec. > > > > If callchains were recorded they are appended to the line with a default stack depth of 5: > > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid > > So when I first saw this it was hard for me to disambiguate individual function > names. Wouldn't this be a bit more readable: > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() > > Or: > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() > > (i.e. visually separate the first entry - and list the rest.) > > Or maybe it could be ASCII color coded so that the different entries are easier to > separate: for example the functions could be printed in alternating white/grey > color? I'd go with the first option - simply adding arrows. It's good enough to identify each function IMHO. Thanks, Namhyung
[toc] | [prev] | [next] | [standalone]
| From | Ingo Molnar <mingo@kernel.org> |
|---|---|
| Date | 2016-11-15 08:40 +0100 |
| Message-ID | <sDGvw-1V4-15@gated-at.bofh.it> |
| In reply to | #1522389 |
* Namhyung Kim <namhyung@kernel.org> wrote: > > > By default it shows the individual schedule events, including the time between > > > sched-in events for the task, the task scheduling delay (time between wakeup > > > and actually running) and run time for the task: > > > > > > time cpu task name[tid/pid] b/n time sch delay run time > > > ------------- ---- -------------------- --------- --------- --------- > > > 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 > > > 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 > > > 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 > > > 79371.874604 [11] <idle> 1.148 0.000 0.035 > > > 79371.874723 [05] <idle> 0.016 0.000 1.383 > > > 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 > > > ... > > > > What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column > > 'sch wait' instead, or so? > > Looks better, or what about 'wait time'? Works for me! > I'd go with the first option - simply adding arrows. It's good enough to > identify each function IMHO. Ok! Thanks, Ingo
[toc] | [prev] | [next] | [standalone]
| From | David Ahern <dsahern@gmail.com> |
|---|---|
| Date | 2016-11-15 16:20 +0100 |
| Message-ID | <sDNGH-6CK-63@gated-at.bofh.it> |
| In reply to | #1522410 |
On 11/15/16 12:34 AM, Ingo Molnar wrote: > > * Namhyung Kim <namhyung@kernel.org> wrote: > >>>> By default it shows the individual schedule events, including the time between >>>> sched-in events for the task, the task scheduling delay (time between wakeup >>>> and actually running) and run time for the task: >>>> >>>> time cpu task name[tid/pid] b/n time sch delay run time >>>> ------------- ---- -------------------- --------- --------- --------- >>>> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 >>>> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 >>>> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 >>>> 79371.874604 [11] <idle> 1.148 0.000 0.035 >>>> 79371.874723 [05] <idle> 0.016 0.000 1.383 >>>> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 >>>> ... >>> >>> What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column >>> 'sch wait' instead, or so? >> >> Looks better, or what about 'wait time'? > > Works for me! That column generically is time not running -- time between the last sched out and the current sched in. It could be expected (sleep, select, read, ...), waiting for a resource (disk I/O, mutex) or preemption. > >> I'd go with the first option - simply adding arrows. It's good enough to >> identify each function IMHO. > > Ok! I'd prefer the arrows too for a default. Color can be an add-on option.
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2016-11-15 16:40 +0100 |
| Message-ID | <sDO03-6JS-65@gated-at.bofh.it> |
| In reply to | #1522812 |
Hi David, On Tue, Nov 15, 2016 at 08:14:24AM -0700, David Ahern wrote: > On 11/15/16 12:34 AM, Ingo Molnar wrote: > > > > * Namhyung Kim <namhyung@kernel.org> wrote: > > > >>>> By default it shows the individual schedule events, including the time between > >>>> sched-in events for the task, the task scheduling delay (time between wakeup > >>>> and actually running) and run time for the task: > >>>> > >>>> time cpu task name[tid/pid] b/n time sch delay run time > >>>> ------------- ---- -------------------- --------- --------- --------- > >>>> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 > >>>> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 > >>>> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 > >>>> 79371.874604 [11] <idle> 1.148 0.000 0.035 > >>>> 79371.874723 [05] <idle> 0.016 0.000 1.383 > >>>> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 > >>>> ... > >>> > >>> What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column > >>> 'sch wait' instead, or so? > >> > >> Looks better, or what about 'wait time'? > > > > Works for me! > > That column generically is time not running -- time between the last > sched out and the current sched in. It could be expected (sleep, > select, read, ...), waiting for a resource (disk I/O, mutex) or > preemption. Right. Maybe it'd be better to show the prev_state as well to identify the reason (roughly). So, are you ok with the name 'wait time'? My thinking is that they are all waiting for something - timer, resource or cpu. Thanks, Namhyung > > > > >> I'd go with the first option - simply adding arrows. It's good enough to > >> identify each function IMHO. > > > > Ok! > > I'd prefer the arrows too for a default. Color can be an add-on option.
[toc] | [prev] | [next] | [standalone]
| From | David Ahern <dsahern@gmail.com> |
|---|---|
| Date | 2016-11-15 19:30 +0100 |
| Message-ID | <sDQEy-5I-35@gated-at.bofh.it> |
| In reply to | #1522853 |
On 11/15/16 8:32 AM, Namhyung Kim wrote: > So, are you ok with the name 'wait time'? My thinking is that they > are all waiting for something - timer, resource or cpu. sure.
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web