Messages in this thread Patch in this message | | | From | Namhyung Kim <> | Subject | [RFC/PATCH] perf sched: Implement 'perf sched runtime' command | Date | Tue, 25 Aug 2015 15:11:23 +0900 |
| |
Currently 'perf sched record' commandsrecords various task stat info but other perf sched commands don't use them. This is a very simple implementation of showing those info to users.
$ sudo perf sched record -a sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.346 MB perf.data (774 samples) ]
$ sudo perf sched runtime | head TID:COMM Run-time Sleep-time Wait-time IOWait-time Switch Migrate ---------------------- ------------ ------------ ------------ ------------ ------ ------- 1347:Socket Thread 20901793 4895322293 0 0 2 2 14855:sshd 7404420 660792968 0 0 4 0 1342:firefox 3657944 998405339 82358 0 11 0 1360:Timer 1429014 1002239227 0 0 11 0 170:systemd-journal 1209607 644878917 0 0 1 0 7:rcu_preempt 1081471 958866004 416514 0 26 6 14856:sshd 973632 506809918 0 0 6 0 14859:sleep 887558 1030418783 4055 0 3 1
Cc: David Ahern <dsahern@gmail.com> Signed-off-by: Namhyung Kim <namhyung@kernel.org> --- tools/perf/builtin-sched.c | 361 ++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 359 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index 33962612a5e9..112596121242 100644 --- a/tools/perf/builtin-sched.c +++ b/tools/perf/builtin-sched.c @@ -98,6 +98,18 @@ struct work_atoms { int num_merged; }; +struct task_runtime { + struct list_head list; + struct rb_node node; + struct thread *thread; + u64 run_time; + u64 sleep_time; + u64 wait_time; + u64 iowait_time; + int num_switch; + int num_migrate; +}; + typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *); struct perf_sched; @@ -109,6 +121,15 @@ struct trace_sched_handler { int (*runtime_event)(struct perf_sched *sched, struct perf_evsel *evsel, struct perf_sample *sample, struct machine *machine); + int (*sleep_event)(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine); + + int (*wait_event)(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine); + + int (*iowait_event)(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine); + int (*wakeup_event)(struct perf_sched *sched, struct perf_evsel *evsel, struct perf_sample *sample, struct machine *machine); @@ -170,7 +191,7 @@ struct perf_sched { u64 all_count; u64 cpu_last_switched[MAX_CPUS]; struct rb_root atom_root, sorted_atom_root, merged_atom_root; - struct list_head sort_list, cmp_pid; + struct list_head sort_list, cmp_pid, runtime_list; bool force; bool skip_merge; }; @@ -1424,6 +1445,120 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel, return 0; } +static struct task_runtime *get_task_runtime(struct perf_sched *sched, + struct machine *machine, int pid) +{ + struct thread *th; + struct task_runtime *tr; + + th = machine__findnew_thread(machine, -1, pid); + if (th == NULL) + return NULL; + + tr = thread__priv(th); + if (tr == NULL) { + tr = zalloc(sizeof(*tr)); + if (tr == NULL) + return NULL; + + thread__set_priv(th, tr); + + /* hold a refcnt not to free the thread */ + tr->thread = thread__get(th); + + list_add(&tr->list, &sched->runtime_list); + } + return tr; +} + +static int runtime_switch_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "prev_pid"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->num_switch++; + return 0; +} + +static int runtime_runtime_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "pid"); + const u64 time = perf_evsel__intval(evsel, sample, "runtime"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->run_time += time; + return 0; +} + +static int runtime_sleep_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "pid"); + const u64 time = perf_evsel__intval(evsel, sample, "delay"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->sleep_time += time; + return 0; +} + +static int runtime_wait_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "pid"); + const u64 time = perf_evsel__intval(evsel, sample, "delay"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->wait_time += time; + return 0; +} + +static int runtime_iowait_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "pid"); + const u64 time = perf_evsel__intval(evsel, sample, "delay"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->iowait_time += time; + return 0; +} + +static int runtime_migrate_event(struct perf_sched *sched, struct perf_evsel *evsel, + struct perf_sample *sample, struct machine *machine) +{ + const u32 pid = perf_evsel__intval(evsel, sample, "pid"); + struct task_runtime *tr; + + tr = get_task_runtime(sched, machine, pid); + if (tr == NULL) + return -1; + + tr->num_migrate++; + return 0; +} + static int process_sched_switch_event(struct perf_tool *tool, struct perf_evsel *evsel, struct perf_sample *sample, @@ -1463,6 +1598,45 @@ static int process_sched_runtime_event(struct perf_tool *tool, return 0; } +static int process_sched_sleep_event(struct perf_tool *tool, + struct perf_evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_sched *sched = container_of(tool, struct perf_sched, tool); + + if (sched->tp_handler->sleep_event) + return sched->tp_handler->sleep_event(sched, evsel, sample, machine); + + return 0; +} + +static int process_sched_wait_event(struct perf_tool *tool, + struct perf_evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_sched *sched = container_of(tool, struct perf_sched, tool); + + if (sched->tp_handler->wait_event) + return sched->tp_handler->wait_event(sched, evsel, sample, machine); + + return 0; +} + +static int process_sched_iowait_event(struct perf_tool *tool, + struct perf_evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_sched *sched = container_of(tool, struct perf_sched, tool); + + if (sched->tp_handler->iowait_event) + return sched->tp_handler->iowait_event(sched, evsel, sample, machine); + + return 0; +} + static int perf_sched__process_fork_event(struct perf_tool *tool, union perf_event *event, struct perf_sample *sample, @@ -1560,6 +1734,143 @@ out_delete: return rc; } +static int perf_sched__read_runtime_events(struct perf_sched *sched) +{ + const struct perf_evsel_str_handler handlers[] = { + { "sched:sched_switch", process_sched_switch_event, }, + { "sched:sched_stat_runtime", process_sched_runtime_event, }, + { "sched:sched_stat_sleep", process_sched_sleep_event, }, + { "sched:sched_stat_wait", process_sched_wait_event, }, + { "sched:sched_stat_iowait", process_sched_iowait_event, }, + { "sched:sched_migrate_task", process_sched_migrate_task_event, }, + }; + struct perf_session *session; + struct perf_data_file file = { + .path = input_name, + .mode = PERF_DATA_MODE_READ, + .force = sched->force, + }; + int rc = -1; + + session = perf_session__new(&file, false, &sched->tool); + if (session == NULL) { + pr_debug("No Memory for session\n"); + return -1; + } + + symbol__init(&session->header.env); + + if (perf_session__set_tracepoints_handlers(session, handlers)) + goto out_delete; + + if (perf_session__has_traces(session, "record -R")) { + int err = perf_session__process_events(session); + if (err) { + pr_err("Failed to process events, error %d", err); + goto out_delete; + } + + sched->nr_events = session->evlist->stats.nr_events[0]; + sched->nr_lost_events = session->evlist->stats.total_lost; + sched->nr_lost_chunks = session->evlist->stats.nr_events[PERF_RECORD_LOST]; + } + + rc = 0; +out_delete: + perf_session__delete(session); + return rc; +} + +static int task_runtime_cmp(struct perf_sched *sched __maybe_unused, + struct task_runtime *a, struct task_runtime *b) +{ + return b->run_time - a->run_time; +} + +static void sort_task_runtime(struct perf_sched *sched, struct task_runtime *tr) +{ + struct rb_root *root = &sched->sorted_atom_root; + struct rb_node **p = &root->rb_node; + struct rb_node *parent = NULL; + + while (*p) { + struct task_runtime *iter; + int cmp; + + parent = *p; + iter = rb_entry(parent, struct task_runtime, node); + + cmp = task_runtime_cmp(sched, iter, tr); + + if (cmp > 0) + p = &parent->rb_left; + else + p = &parent->rb_right; + } + + rb_link_node(&tr->node, parent, p); + rb_insert_color(&tr->node, root); +} + +static void perf_sched__sort_runtime(struct perf_sched *sched) +{ + while (!list_empty(&sched->runtime_list)) { + struct task_runtime *tr; + + tr = list_first_entry(&sched->runtime_list, + struct task_runtime, list); + list_del(&tr->list); + + sort_task_runtime(sched, tr); + } +} + +static void print_task_runtime(struct task_runtime *tr) +{ + struct thread *th = tr->thread; + + /* tid:comm run_time sleep_time wait_time iowait_time switch migrate*/ + printf("%5d:%-16s %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %6d %7d\n", + th->tid, thread__comm_str(th), tr->run_time, tr->sleep_time, + tr->wait_time, tr->iowait_time, tr->num_switch, tr->num_migrate); +} + +static void perf_sched__print_runtime(struct perf_sched *sched) +{ + struct task_runtime *tr; + struct rb_root *root = &sched->sorted_atom_root; + struct rb_node *node = rb_first(root); + + printf("%5s:%-16s %12s %12s %12s %12s %6s %7s\n", + "TID", "COMM", "Run-time", "Sleep-time", "Wait-time", + "IOWait-time", "Switch", "Migrate"); + printf("%.22s %.12s %.12s %.12s %.12s %.6s %.7s\n", + graph_dotted_line, graph_dotted_line, graph_dotted_line, + graph_dotted_line, graph_dotted_line, graph_dotted_line, + graph_dotted_line); + + while (node) { + tr = rb_entry(node, struct task_runtime, node); + print_task_runtime(tr); + + node = rb_next(node); + } + + /* release thread refcnt */ + node = rb_first(root); + while (node) { + struct rb_node *next = rb_next(node); + rb_erase(node, root); + + tr = rb_entry(node, struct task_runtime, node); + thread__set_priv(tr->thread, NULL); + thread__put(tr->thread); + free(tr); + + node = next; + } +} + static void print_bad_events(struct perf_sched *sched) { if (sched->nr_unordered_timestamps && sched->nr_timestamps) { @@ -1720,6 +2031,23 @@ static int perf_sched__replay(struct perf_sched *sched) return 0; } +static int perf_sched__runtime(struct perf_sched *sched) +{ + setup_pager(); + + INIT_LIST_HEAD(&sched->runtime_list); + if (perf_sched__read_runtime_events(sched)) + return -1; + + perf_sched__sort_runtime(sched); + perf_sched__print_runtime(sched); + + print_bad_events(sched); + printf("\n"); + + return 0; +} + static void setup_sorting(struct perf_sched *sched, const struct option *options, const char * const usage_msg[]) { @@ -1821,6 +2149,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"), OPT_END() }; + const struct option runtime_options[] = { + OPT_INCR('v', "verbose", &verbose, + "be more verbose (show symbol address, etc)"), + OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, + "dump raw trace in ASCII"), + OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"), + OPT_END() + }; const struct option sched_options[] = { OPT_STRING('i', "input", &input_name, "file", "input file name"), @@ -1838,8 +2174,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) "perf sched replay [<options>]", NULL }; + const char * const runtime_usage[] = { + "perf sched runtime [<options>]", + NULL + }; const char *const sched_subcommands[] = { "record", "latency", "map", - "replay", "script", NULL }; + "replay", "script", "runtime", + NULL }; const char *sched_usage[] = { NULL, NULL @@ -1858,6 +2199,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) .switch_event = replay_switch_event, .fork_event = replay_fork_event, }; + struct trace_sched_handler runtime_ops = { + .switch_event = runtime_switch_event, + .runtime_event = runtime_runtime_event, + .sleep_event = runtime_sleep_event, + .wait_event = runtime_wait_event, + .iowait_event = runtime_iowait_event, + .migrate_task_event = runtime_migrate_event, + }; unsigned int i; for (i = 0; i < ARRAY_SIZE(sched.curr_pid); i++) @@ -1897,6 +2246,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) usage_with_options(replay_usage, replay_options); } return perf_sched__replay(&sched); + } else if (!strncmp(argv[0], "run", 3)) { + sched.tp_handler = &runtime_ops; + if (argc) { + argc = parse_options(argc, argv, runtime_options, runtime_usage, 0); + if (argc) + usage_with_options(runtime_usage, runtime_options); + } + return perf_sched__runtime(&sched); } else { usage_with_options(sched_usage, sched_options); } -- 2.5.0
| |