Messages in this thread Patch in this message | | | Date | Tue, 26 Jul 2022 14:40:32 -0300 | From | Arnaldo Carvalho de Melo <> | Subject | Re: [RFC v3 06/17] perf kwork: Implement perf kwork report |
| |
Em Sat, Jul 09, 2022 at 09:50:22AM +0800, Yang Jihong escreveu: > + > +static void report_print_work(struct perf_kwork *kwork, > + struct kwork_work *work) > +{ > + int ret = 0; > + char kwork_name[PRINT_KWORK_NAME_WIDTH]; > + char max_runtime_start[32], max_runtime_end[32];
Committer notes:
- Add some {} for multiline for/if blocks
- Return the calculated number of printed bytes in report_print_work, otherwise soem compilers will complain that variable isn't used, e.g.:
2 92.64 almalinux:9 : FAIL clang version 13.0.1 (Red Hat 13.0.1-1.el9) builtin-kwork.c:1061:6: error: variable 'ret' set but not used [-Werror,-Wunused-but-set-variable] int ret = 0;
> + > + printf(" "); > + > + /* > + * kwork name > + */ > + if (work->class && work->class->work_name) { > + work->class->work_name(work, kwork_name, > + PRINT_KWORK_NAME_WIDTH); > + ret += printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, kwork_name); > + } else > + ret += printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, ""); > + > + /* > + * cpu > + */ > + ret += printf(" %0*d |", PRINT_CPU_WIDTH, work->cpu); > + > + /* > + * total runtime > + */ > + if (kwork->report == KWORK_REPORT_RUNTIME) > + ret += printf(" %*.*f ms |", > + PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, > + (double)work->total_runtime / NSEC_PER_MSEC); > + > + /* > + * count > + */ > + ret += printf(" %*" PRIu64 " |", PRINT_COUNT_WIDTH, work->nr_atoms); > + > + /* > + * max runtime, max runtime start, max runtime end > + */ > + if (kwork->report == KWORK_REPORT_RUNTIME) { > + > + timestamp__scnprintf_usec(work->max_runtime_start, > + max_runtime_start, > + sizeof(max_runtime_start)); > + timestamp__scnprintf_usec(work->max_runtime_end, > + max_runtime_end, > + sizeof(max_runtime_end)); > + ret += printf(" %*.*f ms | %*s s | %*s s |", > + PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, > + (double)work->max_runtime / NSEC_PER_MSEC, > + PRINT_TIMESTAMP_WIDTH, max_runtime_start, > + PRINT_TIMESTAMP_WIDTH, max_runtime_end); > + } > + > + printf("\n"); > +} > + > +static int report_print_header(struct perf_kwork *kwork) > +{ > + int ret; > + > + printf("\n "); > + ret = printf(" %-*s | %-*s |", > + PRINT_KWORK_NAME_WIDTH, "Kwork Name", > + PRINT_CPU_WIDTH, "Cpu"); > + > + if (kwork->report == KWORK_REPORT_RUNTIME) > + ret += printf(" %-*s |", > + PRINT_RUNTIME_HEADER_WIDTH, "Total Runtime"); > + > + ret += printf(" %-*s |", PRINT_COUNT_WIDTH, "Count"); > + > + if (kwork->report == KWORK_REPORT_RUNTIME) > + ret += printf(" %-*s | %-*s | %-*s |", > + PRINT_RUNTIME_HEADER_WIDTH, "Max runtime", > + PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime start", > + PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime end"); > + > + printf("\n"); > + print_separator(ret); > + return ret; > +} > + > +static void print_summary(struct perf_kwork *kwork) > +{ > + u64 time = kwork->timeend - kwork->timestart; > + > + printf(" Total count : %9" PRIu64 "\n", kwork->all_count); > + printf(" Total runtime (msec) : %9.3f (%.3f%% load average)\n", > + (double)kwork->all_runtime / NSEC_PER_MSEC, > + time == 0 ? 0 : (double)kwork->all_runtime / time); > + printf(" Total time span (msec) : %9.3f\n", > + (double)time / NSEC_PER_MSEC); > +} > + > +static unsigned long long nr_list_entry(struct list_head *head) > +{ > + struct list_head *pos; > + unsigned long long n = 0; > + > + list_for_each(pos, head) > + n++; > + > + return n; > +} > + > +static void print_skipped_events(struct perf_kwork *kwork) > +{ > + int i; > + const char *const kwork_event_str[] = { > + [KWORK_TRACE_ENTRY] = "entry", > + [KWORK_TRACE_EXIT] = "exit", > + }; > + > + if ((kwork->nr_skipped_events[KWORK_TRACE_MAX] != 0) && > + (kwork->nr_events != 0)) { > + printf(" INFO: %.3f%% skipped events (%" PRIu64 " including ", > + (double)kwork->nr_skipped_events[KWORK_TRACE_MAX] / > + (double)kwork->nr_events * 100.0, > + kwork->nr_skipped_events[KWORK_TRACE_MAX]); > + > + for (i = 0; i < KWORK_TRACE_MAX; i++) > + printf("%" PRIu64 " %s%s", > + kwork->nr_skipped_events[i], > + kwork_event_str[i], > + (i == KWORK_TRACE_MAX - 1) ? ")\n" : ", "); > + } > + > + if (verbose > 0) > + printf(" INFO: use %lld atom pages\n", > + nr_list_entry(&kwork->atom_page_list)); > +} > + > +static void print_bad_events(struct perf_kwork *kwork) > +{ > + if ((kwork->nr_lost_events != 0) && (kwork->nr_events != 0)) > + printf(" INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n", > + (double)kwork->nr_lost_events / > + (double)kwork->nr_events * 100.0, > + kwork->nr_lost_events, kwork->nr_events, > + kwork->nr_lost_chunks); > +} > + > +static void work_sort(struct perf_kwork *kwork, struct kwork_class *class) > +{ > + struct rb_node *node; > + struct kwork_work *data; > + struct rb_root_cached *root = &class->work_root; > + > + pr_debug("Sorting %s ...\n", class->name); > + for (;;) { > + node = rb_first_cached(root); > + if (!node) > + break; > + > + rb_erase_cached(node, root); > + data = rb_entry(node, struct kwork_work, node); > + work_insert(&kwork->sorted_work_root, > + data, &kwork->sort_list); > + } > +} > + > +static void perf_kwork__sort(struct perf_kwork *kwork) > +{ > + struct kwork_class *class; > + > + list_for_each_entry(class, &kwork->class_list, list) > + work_sort(kwork, class); > +} > + > +static int perf_kwork__check_config(struct perf_kwork *kwork, > + struct perf_session *session) > +{ > + int ret; > + struct kwork_class *class; > + > + static struct trace_kwork_handler report_ops = { > + .entry_event = report_entry_event, > + .exit_event = report_exit_event, > + }; > + > + switch (kwork->report) { > + case KWORK_REPORT_RUNTIME: > + kwork->tp_handler = &report_ops; > + break; > + default: > + pr_debug("Invalid report type %d\n", kwork->report); > + return -1; > + } > + > + list_for_each_entry(class, &kwork->class_list, list) > + if ((class->class_init != NULL) && > + (class->class_init(class, session) != 0)) > + return -1; > + > + if (kwork->cpu_list != NULL) { > + ret = perf_session__cpu_bitmap(session, > + kwork->cpu_list, > + kwork->cpu_bitmap); > + if (ret < 0) { > + pr_err("Invalid cpu bitmap\n"); > + return -1; > + } > + } > + > + if (kwork->time_str != NULL) { > + ret = perf_time__parse_str(&kwork->ptime, kwork->time_str); > + if (ret != 0) { > + pr_err("Invalid time span\n"); > + return -1; > + } > + } > + > + return 0; > +} > + > +static int perf_kwork__read_events(struct perf_kwork *kwork) > +{ > + int ret = -1; > + struct perf_session *session = NULL; > + > + struct perf_data data = { > + .path = input_name, > + .mode = PERF_DATA_MODE_READ, > + .force = kwork->force, > + }; > + > + session = perf_session__new(&data, &kwork->tool); > + if (IS_ERR(session)) { > + pr_debug("Error creating perf session\n"); > + return PTR_ERR(session); > + } > + > + symbol__init(&session->header.env); > + > + if (perf_kwork__check_config(kwork, session) != 0) > + goto out_delete; > + > + if (session->tevent.pevent && > + tep_set_function_resolver(session->tevent.pevent, > + machine__resolve_kernel_addr, > + &session->machines.host) < 0) { > + pr_err("Failed to set libtraceevent function resolver\n"); > + goto out_delete; > + } > + > + ret = perf_session__process_events(session); > + if (ret) { > + pr_debug("Failed to process events, error %d\n", ret); > + goto out_delete; > + } > + > + kwork->nr_events = session->evlist->stats.nr_events[0]; > + kwork->nr_lost_events = session->evlist->stats.total_lost; > + kwork->nr_lost_chunks = session->evlist->stats.nr_events[PERF_RECORD_LOST]; > + > +out_delete: > + perf_session__delete(session); > + return ret; > +} > + > +static void process_skipped_events(struct perf_kwork *kwork, > + struct kwork_work *work) > +{ > + int i; > + unsigned long long count; > + > + for (i = 0; i < KWORK_TRACE_MAX; i++) { > + count = nr_list_entry(&work->atom_list[i]); > + kwork->nr_skipped_events[i] += count; > + kwork->nr_skipped_events[KWORK_TRACE_MAX] += count; > + } > +} > + > +static int perf_kwork__report(struct perf_kwork *kwork) > +{ > + int ret; > + struct rb_node *next; > + struct kwork_work *work; > + > + ret = perf_kwork__read_events(kwork); > + if (ret != 0) > + return -1; > + > + perf_kwork__sort(kwork); > + > + setup_pager(); > + > + ret = report_print_header(kwork); > + next = rb_first_cached(&kwork->sorted_work_root); > + while (next) { > + work = rb_entry(next, struct kwork_work, node); > + process_skipped_events(kwork, work); > + > + if (work->nr_atoms != 0) { > + report_print_work(kwork, work); > + if (kwork->summary) { > + kwork->all_runtime += work->total_runtime; > + kwork->all_count += work->nr_atoms; > + } > + } > + next = rb_next(next); > + } > + print_separator(ret); > + > + if (kwork->summary) { > + print_summary(kwork); > + print_separator(ret); > + } > + > + print_bad_events(kwork); > + print_skipped_events(kwork); > + printf("\n"); > + > + return 0; > +} > + > +typedef int (*tracepoint_handler)(struct perf_tool *tool, > + struct evsel *evsel, > + struct perf_sample *sample, > + struct machine *machine); > + > +static int perf_kwork__process_tracepoint_sample(struct perf_tool *tool, > + union perf_event *event __maybe_unused, > + struct perf_sample *sample, > + struct evsel *evsel, > + struct machine *machine) > +{ > + int err = 0; > + > + if (evsel->handler != NULL) { > + tracepoint_handler f = evsel->handler; > + > + err = f(tool, evsel, sample, machine); > + } > + > + return err; > +} > + > static void setup_event_list(struct perf_kwork *kwork, > const struct option *options, > const char * const usage_msg[]) > @@ -161,11 +960,37 @@ static int perf_kwork__record(struct perf_kwork *kwork, > int cmd_kwork(int argc, const char **argv) > { > static struct perf_kwork kwork = { > + .tool = { > + .mmap = perf_event__process_mmap, > + .mmap2 = perf_event__process_mmap2, > + .sample = perf_kwork__process_tracepoint_sample, > + }, > + > .class_list = LIST_HEAD_INIT(kwork.class_list), > + .atom_page_list = LIST_HEAD_INIT(kwork.atom_page_list), > + .sort_list = LIST_HEAD_INIT(kwork.sort_list), > + .cmp_id = LIST_HEAD_INIT(kwork.cmp_id), > + .sorted_work_root = RB_ROOT_CACHED, > + .tp_handler = NULL, > > + .profile_name = NULL, > + .cpu_list = NULL, > + .time_str = NULL, > .force = false, > .event_list_str = NULL, > + .summary = false, > + .sort_order = NULL, > + > + .timestart = 0, > + .timeend = 0, > + .nr_events = 0, > + .nr_lost_chunks = 0, > + .nr_lost_events = 0, > + .all_runtime = 0, > + .all_count = 0, > + .nr_skipped_events = { 0 }, > }; > + static const char default_report_sort_order[] = "runtime, max, count"; > > const struct option kwork_options[] = { > OPT_INCR('v', "verbose", &verbose, > @@ -177,13 +1002,32 @@ int cmd_kwork(int argc, const char **argv) > OPT_BOOLEAN('f', "force", &kwork.force, "don't complain, do it"), > OPT_END() > }; > + const struct option report_options[] = { > + OPT_STRING('s', "sort", &kwork.sort_order, "key[,key2...]", > + "sort by key(s): runtime, max, count"), > + OPT_STRING('C', "cpu", &kwork.cpu_list, "cpu", > + "list of cpus to profile"), > + OPT_STRING('n', "name", &kwork.profile_name, "name", > + "event name to profile"), > + OPT_STRING(0, "time", &kwork.time_str, "str", > + "Time span for analysis (start,stop)"), > + OPT_STRING('i', "input", &input_name, "file", > + "input file name"), > + OPT_BOOLEAN('S', "with-summary", &kwork.summary, > + "Show summary with statistics"), > + OPT_PARENT(kwork_options) > + }; > > const char *kwork_usage[] = { > NULL, > NULL > }; > + const char * const report_usage[] = { > + "perf kwork report [<options>]", > + NULL > + }; > const char *const kwork_subcommands[] = { > - "record", NULL > + "record", "report", NULL > }; > > argc = parse_options_subcommand(argc, argv, kwork_options, > @@ -193,10 +1037,21 @@ int cmd_kwork(int argc, const char **argv) > usage_with_options(kwork_usage, kwork_options); > > setup_event_list(&kwork, kwork_options, kwork_usage); > + sort_dimension__add(&kwork, "id", &kwork.cmp_id); > > if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) > return perf_kwork__record(&kwork, argc, argv); > - else > + else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) { > + kwork.sort_order = default_report_sort_order; > + if (argc > 1) { > + argc = parse_options(argc, argv, report_options, report_usage, 0); > + if (argc) > + usage_with_options(report_usage, report_options); > + } > + kwork.report = KWORK_REPORT_RUNTIME; > + setup_sorting(&kwork, report_options, report_usage); > + return perf_kwork__report(&kwork); > + } else > usage_with_options(kwork_usage, kwork_options); > > return 0; > diff --git a/tools/perf/util/kwork.h b/tools/perf/util/kwork.h > index 03203c4deb34..0a86bf47c74d 100644 > --- a/tools/perf/util/kwork.h > +++ b/tools/perf/util/kwork.h > @@ -19,6 +19,105 @@ enum kwork_class_type { > KWORK_CLASS_MAX, > }; > > +enum kwork_report_type { > + KWORK_REPORT_RUNTIME, > +}; > + > +enum kwork_trace_type { > + KWORK_TRACE_ENTRY, > + KWORK_TRACE_EXIT, > + KWORK_TRACE_MAX, > +}; > + > +/* > + * data structure: > + * > + * +==================+ +============+ +======================+ > + * | class | | work | | atom | > + * +==================+ +============+ +======================+ > + * +------------+ | +-----+ | | +------+ | | +-------+ +-----+ | > + * | perf_kwork | +-> | irq | --------|+-> | eth0 | --+-> | raise | - | ... | --+ +-----------+ > + * +-----+------+ || +-----+ ||| +------+ ||| +-------+ +-----+ | | | | > + * | || ||| ||| | +-> | atom_page | > + * | || ||| ||| +-------+ +-----+ | | | > + * | class_list ||| |+-> | entry | - | ... | ----> | | > + * | || ||| ||| +-------+ +-----+ | | | > + * | || ||| ||| | +-> | | > + * | || ||| ||| +-------+ +-----+ | | | | > + * | || ||| |+-> | exit | - | ... | --+ +-----+-----+ > + * | || ||| | | +-------+ +-----+ | | > + * | || ||| | | | | > + * | || ||| +-----+ | | | | > + * | || |+-> | ... | | | | | > + * | || | | +-----+ | | | | > + * | || | | | | | | > + * | || +---------+ | | +-----+ | | +-------+ +-----+ | | > + * | +-> | softirq | -------> | RCU | ---+-> | raise | - | ... | --+ +-----+-----+ > + * | || +---------+ | | +-----+ ||| +-------+ +-----+ | | | | > + * | || | | ||| | +-> | atom_page | > + * | || | | ||| +-------+ +-----+ | | | > + * | || | | |+-> | entry | - | ... | ----> | | > + * | || | | ||| +-------+ +-----+ | | | > + * | || | | ||| | +-> | | > + * | || | | ||| +-------+ +-----+ | | | | > + * | || | | |+-> | exit | - | ... | --+ +-----+-----+ > + * | || | | | | +-------+ +-----+ | | > + * | || | | | | | | > + * | || +-----------+ | | +-----+ | | | | > + * | +-> | workqueue | -----> | ... | | | | | > + * | | +-----------+ | | +-----+ | | | | > + * | +==================+ +============+ +======================+ | > + * | | > + * +----> atom_page_list ---------------------------------------------------------+ > + * > + */ > + > +struct kwork_atom { > + struct list_head list; > + u64 time; > + struct kwork_atom *prev; > + > + void *page_addr; > + unsigned long bit_inpage; > +}; > + > +#define NR_ATOM_PER_PAGE 128 > +struct kwork_atom_page { > + struct list_head list; > + struct kwork_atom atoms[NR_ATOM_PER_PAGE]; > + DECLARE_BITMAP(bitmap, NR_ATOM_PER_PAGE); > +}; > + > +struct kwork_class; > +struct kwork_work { > + /* > + * class field > + */ > + struct rb_node node; > + struct kwork_class *class; > + > + /* > + * work field > + */ > + u64 id; > + int cpu; > + char *name; > + > + /* > + * atom field > + */ > + u64 nr_atoms; > + struct list_head atom_list[KWORK_TRACE_MAX]; > + > + /* > + * runtime report > + */ > + u64 max_runtime; > + u64 max_runtime_start; > + u64 max_runtime_end; > + u64 total_runtime; > +}; > + > struct kwork_class { > struct list_head list; > const char *name; > @@ -26,19 +125,81 @@ struct kwork_class { > > unsigned int nr_tracepoints; > const struct evsel_str_handler *tp_handlers; > + > + struct rb_root_cached work_root; > + > + int (*class_init)(struct kwork_class *class, > + struct perf_session *session); > + > + void (*work_init)(struct kwork_class *class, > + struct kwork_work *work, > + struct evsel *evsel, > + struct perf_sample *sample, > + struct machine *machine); > + > + void (*work_name)(struct kwork_work *work, > + char *buf, int len); > +}; > + > +struct perf_kwork; > +struct trace_kwork_handler { > + int (*entry_event)(struct perf_kwork *kwork, > + struct kwork_class *class, struct evsel *evsel, > + struct perf_sample *sample, struct machine *machine); > + > + int (*exit_event)(struct perf_kwork *kwork, > + struct kwork_class *class, struct evsel *evsel, > + struct perf_sample *sample, struct machine *machine); > }; > > struct perf_kwork { > /* > * metadata > */ > + struct perf_tool tool; > struct list_head class_list; > + struct list_head atom_page_list; > + struct list_head sort_list, cmp_id; > + struct rb_root_cached sorted_work_root; > + const struct trace_kwork_handler *tp_handler; > + > + /* > + * profile filters > + */ > + const char *profile_name; > + > + const char *cpu_list; > + DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS); > + > + const char *time_str; > + struct perf_time_interval ptime; > > /* > * options for command > */ > bool force; > const char *event_list_str; > + enum kwork_report_type report; > + > + /* > + * options for subcommand > + */ > + bool summary; > + const char *sort_order; > + > + /* > + * statistics > + */ > + u64 timestart; > + u64 timeend; > + > + unsigned long nr_events; > + unsigned long nr_lost_chunks; > + unsigned long nr_lost_events; > + > + u64 all_runtime; > + u64 all_count; > + u64 nr_skipped_events[KWORK_TRACE_MAX + 1]; > }; > > #endif /* PERF_UTIL_KWORK_H */ > -- > 2.30.GIT
--
- Arnaldo
| |