From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 84B70CCA481 for ; Mon, 13 Jun 2022 09:48:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S240110AbiFMJsp (ORCPT ); Mon, 13 Jun 2022 05:48:45 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:44498 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241123AbiFMJsI (ORCPT ); Mon, 13 Jun 2022 05:48:08 -0400 Received: from szxga03-in.huawei.com (szxga03-in.huawei.com [45.249.212.189]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0C5C4193C7; Mon, 13 Jun 2022 02:48:06 -0700 (PDT) Received: from dggemv703-chm.china.huawei.com (unknown [172.30.72.56]) by szxga03-in.huawei.com (SkyGuard) with ESMTP id 4LM6Dr370XzDqtc; Mon, 13 Jun 2022 17:47:40 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv703-chm.china.huawei.com (10.3.19.46) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:04 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:03 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 01/13] perf kwork: New tool Date: Mon, 13 Jun 2022 17:45:53 +0800 Message-ID: <20220613094605.208401-2-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" The perf-kwork tool is used to trace time properties of kernel work (such as irq, softirq, and workqueue), including runtime, latency, and timehist, using the infrastructure in the perf tools to allow tracing extra targets: # perf kwork -h Usage: perf kwork [] {record|report|latency|timehist} -D, --dump-raw-trace dump raw trace in ASCII -f, --force don't complain, do it -k, --kwork list of kwork to profile (irq, softirq, workque= ue etc) -v, --verbose be more verbose (show symbol address, etc) # perf kwork record -- sleep 1 [ perf record: Woken up 0 times to write data ] [ perf record: Captured and wrote 1.696 MB perf.data ] # perf kwork report -h Usage: perf kwork report [] -C, --cpu list of cpus to profile -i, --input input file name -n, --name event name to profile -s, --sort sort by key(s): runtime, max, freq -S, --with-summary Show summary with statistics --time Time span for analysis (start,stop) # perf kwork latency -h Usage: perf kwork latency [] -C, --cpu list of cpus to profile -i, --input input file name -n, --name event name to profile -s, --sort sort by key(s): avg, max, freq --time Time span for analysis (start,stop) # perf kwork timehist -h Usage: perf kwork timehist [] -C, --cpu list of cpus to profile -g, --call-graph Display call chains if present -i, --input input file name -k, --vmlinux vmlinux pathname -n, --name event name to profile --kallsyms kallsyms pathname --max-stack Maximum number of functions to display backtrac= e. --symfs Look for files with symbols relative to this di= rectory --time Time span for analysis (start,stop) Signed-off-by: Yang Jihong --- tools/perf/Build | 1 + tools/perf/Documentation/perf-kwork.txt | 173 ++++++++++++++ tools/perf/builtin-kwork.c | 291 ++++++++++++++++++++++++ tools/perf/builtin.h | 1 + tools/perf/command-list.txt | 1 + tools/perf/perf.c | 1 + 6 files changed, 468 insertions(+) create mode 100644 tools/perf/Documentation/perf-kwork.txt create mode 100644 tools/perf/builtin-kwork.c diff --git a/tools/perf/Build b/tools/perf/Build index db61dbe2b543..496b096153bb 100644 --- a/tools/perf/Build +++ b/tools/perf/Build @@ -25,6 +25,7 @@ perf-y +=3D builtin-data.o perf-y +=3D builtin-version.o perf-y +=3D builtin-c2c.o perf-y +=3D builtin-daemon.o +perf-y +=3D builtin-kwork.o =20 perf-$(CONFIG_TRACE) +=3D builtin-trace.o perf-$(CONFIG_LIBELF) +=3D builtin-probe.o diff --git a/tools/perf/Documentation/perf-kwork.txt b/tools/perf/Documenta= tion/perf-kwork.txt new file mode 100644 index 000000000000..59e0a36c527d --- /dev/null +++ b/tools/perf/Documentation/perf-kwork.txt @@ -0,0 +1,173 @@ +perf-kwork(1) +=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D + +NAME +---- +perf-kwork - Tool to trace/measure kernel work properties (latencies) + +SYNOPSIS +-------- +[verse] +'perf kwork' {record|report|latency|timehist} + +DESCRIPTION +----------- +There are several variants of 'perf kwork': + + 'perf kwork record ' to record the kernel work + of an arbitrary workload. + + 'perf kwork report' to report the per kwork runtime. + + 'perf kwork latency' to report the per kwork latencies. + + 'perf kwork script' to see a detailed trace of the workload that + was recorded (aliased to 'perf script' for now). + + 'perf kwork timehist' provides an analysis of kernel work events. + + Example usage: + perf kwork record -- sleep 1 + perf kwork report + perf kwork latency + perf kwork timehist + + By default it shows the individual work events such as irq, workqeueu, + including the run time and delay (time between raise and actually entry= ): + + Runtime start Runtime end Cpu Kwork name = Runtime Delaytime + (TYPE)NAME:NUM = (msec) (msec) + ----------------- ----------------- ------ -------------------------= ---------- ---------- + 1811186.976062 1811186.976327 [0000] (s)RCU:9 = 0.266 0.114 + 1811186.978452 1811186.978547 [0000] (s)SCHED:7 = 0.095 0.171 + 1811186.980327 1811186.980490 [0000] (s)SCHED:7 = 0.162 0.083 + 1811186.981221 1811186.981271 [0000] (s)SCHED:7 = 0.050 0.077 + 1811186.984267 1811186.984318 [0000] (s)SCHED:7 = 0.051 0.075 + 1811186.987252 1811186.987315 [0000] (s)SCHED:7 = 0.063 0.081 + 1811186.987785 1811186.987843 [0006] (s)RCU:9 = 0.058 0.645 + 1811186.988319 1811186.988383 [0000] (s)SCHED:7 = 0.064 0.143 + 1811186.989404 1811186.989607 [0002] (s)TIMER:1 = 0.203 0.111 + 1811186.989660 1811186.989732 [0002] (s)SCHED:7 = 0.072 0.310 + 1811186.991295 1811186.991407 [0002] eth0:10 = 0.112 + 1811186.991639 1811186.991734 [0002] (s)NET_RX:3 = 0.095 0.277 + 1811186.989860 1811186.991826 [0002] (w)0xffff888102fc14a0 = 1.966 0.345 + ... + + Times are in msec.usec. + +OPTIONS +------- +-D:: +--dump-raw-trace=3D:: + Display verbose dump of the trace data. + +-f:: +--force:: + Don't complain, do it. + +-k:: +--kwork:: + list of kwork to profile (irq, softirq, workqueue etc) + +-v:: +--verbose:: + Be more verbose. (show symbol address, etc) + +OPTIONS for 'perf kwork report' +---------------------------- + +-C:: +--cpu:: + Only show events for the given CPU(s) (comma separated list). + +-i:: +--input:: + Input file name. (default: perf.data unless stdin is a fifo) + +-n:: +--name:: + Only show events for the given name. + +-s:: +--sort:: + sort by key(s): runtime, max, freq + +-S:: +--with-summary:: + Show summary with statistics + +--time:: + Only analyze samples within given time window: ,. Tim= es + have the format seconds.microseconds. If start is not given (i.e.,= time + string is ',x.y') then analysis starts at the beginning of the fil= e. If + stop time is not given (i.e, time string is 'x.y,') then analysis = goes + to end of file. + +OPTIONS for 'perf kwork latency' +---------------------------- + +-C:: +--cpu:: + Only show events for the given CPU(s) (comma separated list). + +-i:: +--input:: + Input file name. (default: perf.data unless stdin is a fifo) + +-n:: +--name:: + Only show events for the given name. + +-s:: +--sort:: + sort by key(s): avg, max, freq + +--time:: + Only analyze samples within given time window: ,. Tim= es + have the format seconds.microseconds. If start is not given (i.e.,= time + string is ',x.y') then analysis starts at the beginning of the fil= e. If + stop time is not given (i.e, time string is 'x.y,') then analysis = goes + to end of file. + +OPTIONS for 'perf kwork timehist' +--------------------------------- + +-C:: +--cpu:: + Only show events for the given CPU(s) (comma separated list). + +-g:: +--call-graph:: + Display call chains if present (default off). + +-i:: +--input:: + Input file name. (default: perf.data unless stdin is a fifo) + +-k:: +--vmlinux=3D:: + vmlinux pathname + +-n:: +--name:: + Only show events for the given name. + +--kallsyms=3D:: + kallsyms pathname + +--max-stack:: + Maximum number of functions to display in backtrace, default 5. + +--symfs=3D:: + Look for files with symbols relative to this directory. + +--time:: + Only analyze samples within given time window: ,. Tim= es + have the format seconds.microseconds. If start is not given (i.e.,= time + string is ',x.y') then analysis starts at the beginning of the fil= e. If + stop time is not given (i.e, time string is 'x.y,') then analysis = goes + to end of file. + +SEE ALSO +-------- +linkperf:perf-record[1] diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c new file mode 100644 index 000000000000..b89e41fcc568 --- /dev/null +++ b/tools/perf/builtin-kwork.c @@ -0,0 +1,291 @@ +// SPDX-License-Identifier: GPL-2.0 +#include "builtin.h" +#include "perf.h" + +#include "util/data.h" +#include "util/tool.h" +#include "util/debug.h" +#include "util/event.h" +#include "util/evlist.h" +#include "util/symbol.h" +#include "util/thread.h" +#include "util/session.h" +#include "util/string2.h" +#include "util/callchain.h" +#include "util/time-utils.h" +#include "util/evsel_fprintf.h" + +#include +#include + +#include +#include +#include +#include +#include + +enum kwork_class_type { + KWORK_CLASS_MAX, +}; + +struct kwork_class { + struct list_head list; + const char *name; + + unsigned int nr_tracepoints; + const struct evsel_str_handler *tp_handlers; +}; + +struct perf_kwork { + /* + * metadata + */ + struct list_head class_list; + + /* + * 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; + + /* + * options for subcommand + */ + bool summary; + bool show_callchain; + unsigned int max_stack; + const char *sort_order; +}; + +static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] =3D= { +}; + +static void setup_event_list(struct perf_kwork *kwork, + const struct option *options, + const char * const usage_msg[]) +{ + int i; + struct kwork_class *class; + char *tmp, *tok, *str; + + if (kwork->event_list_str =3D=3D NULL) + goto null_event_list_str; + + str =3D strdup(kwork->event_list_str); + for (tok =3D strtok_r(str, ", ", &tmp); + tok; tok =3D strtok_r(NULL, ", ", &tmp)) { + for (i =3D 0; i < KWORK_CLASS_MAX; i++) { + class =3D kwork_class_supported_list[i]; + if (strcmp(tok, class->name) =3D=3D 0) { + list_add_tail(&class->list, &kwork->class_list); + break; + } + } + if (i =3D=3D KWORK_CLASS_MAX) + usage_with_options_msg(usage_msg, options, + "Unknown --event key: `%s'", tok); + } + free(str); + +null_event_list_str: + /* + * config all kwork events if not specified + */ + if (list_empty(&kwork->class_list)) + for (i =3D 0; i < KWORK_CLASS_MAX; i++) + list_add_tail(&kwork_class_supported_list[i]->list, + &kwork->class_list); + + pr_debug("Config event list:"); + list_for_each_entry(class, &kwork->class_list, list) + pr_debug(" %s", class->name); + pr_debug("\n"); +} + +static int perf_kwork__record(struct perf_kwork *kwork, + int argc, const char **argv) +{ + const char **rec_argv; + unsigned int rec_argc, i, j; + struct kwork_class *class; + + const char *const record_args[] =3D { + "record", + "-a", + "-R", + "-m", "1024", + "-c", "1", + }; + + rec_argc =3D ARRAY_SIZE(record_args) + argc - 1; + + list_for_each_entry(class, &kwork->class_list, list) + rec_argc +=3D 2 * class->nr_tracepoints; + + rec_argv =3D calloc(rec_argc + 1, sizeof(char *)); + if (rec_argv =3D=3D NULL) + return -ENOMEM; + + for (i =3D 0; i < ARRAY_SIZE(record_args); i++) + rec_argv[i] =3D strdup(record_args[i]); + + list_for_each_entry(class, &kwork->class_list, list) { + for (j =3D 0; j < class->nr_tracepoints; j++) { + rec_argv[i++] =3D strdup("-e"); + rec_argv[i++] =3D strdup(class->tp_handlers[j].name); + } + } + + for (j =3D 1; j < (unsigned int)argc; j++, i++) + rec_argv[i] =3D argv[j]; + + BUG_ON(i !=3D rec_argc); + + pr_debug("record comm: "); + for (j =3D 0; j < rec_argc; j++) + pr_debug("%s ", rec_argv[j]); + pr_debug("\n"); + + return cmd_record(i, rec_argv); +} + +int cmd_kwork(int argc, const char **argv) +{ + static struct perf_kwork kwork =3D { + .class_list =3D LIST_HEAD_INIT(kwork.class_list), + + .profile_name =3D NULL, + .cpu_list =3D NULL, + .time_str =3D NULL, + .force =3D false, + .event_list_str =3D NULL, + .summary =3D false, + .show_callchain =3D false, + .max_stack =3D 5, + .sort_order =3D NULL, + }; + + const struct option kwork_options[] =3D { + 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_STRING('k', "kwork", &kwork.event_list_str, "kwork", + "list of kwork to profile (irq, softirq, workqueue etc)"), + OPT_BOOLEAN('f', "force", &kwork.force, "don't complain, do it"), + OPT_END() + }; + const struct option latency_options[] =3D { + OPT_STRING('s', "sort", &kwork.sort_order, "key[,key2...]", + "sort by key(s): avg, max, freq"), + 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_PARENT(kwork_options) + }; + const struct option report_options[] =3D { + OPT_STRING('s', "sort", &kwork.sort_order, "key[,key2...]", + "sort by key(s): runtime, max, freq"), + 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 struct option timehist_options[] =3D { + OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name, + "file", "vmlinux pathname"), + OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name, + "file", "kallsyms pathname"), + OPT_BOOLEAN('g', "call-graph", &kwork.show_callchain, + "Display call chains if present"), + OPT_UINTEGER(0, "max-stack", &kwork.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_STRING(0, "time", &kwork.time_str, "str", + "Time span for analysis (start,stop)"), + 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('i', "input", &input_name, "file", + "input file name"), + OPT_PARENT(kwork_options) + }; + + const char *kwork_usage[] =3D { + NULL, + NULL + }; + const char * const latency_usage[] =3D { + "perf kwork latency []", + NULL + }; + const char * const report_usage[] =3D { + "perf kwork report []", + NULL + }; + const char * const timehist_usage[] =3D { + "perf kwork timehist []", + NULL + }; + const char *const kwork_subcommands[] =3D { + "record", "report", "latency", "timehist", NULL + }; + + argc =3D parse_options_subcommand(argc, argv, kwork_options, + kwork_subcommands, kwork_usage, + PARSE_OPT_STOP_AT_NON_OPTION); + if (!argc) + usage_with_options(kwork_usage, kwork_options); + + setup_event_list(&kwork, kwork_options, kwork_usage); + + if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) { + return perf_kwork__record(&kwork, argc, argv); + } else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) { + if (argc > 1) { + argc =3D parse_options(argc, argv, report_options, report_usage, 0); + if (argc) + usage_with_options(report_usage, report_options); + } + } else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) { + if (argc > 1) { + argc =3D parse_options(argc, argv, latency_options, latency_usage, 0); + if (argc) + usage_with_options(latency_usage, latency_options); + } + } else if (strlen(argv[0]) > 2 && strstarts("timehist", argv[0])) { + if (argc > 1) { + argc =3D parse_options(argc, argv, timehist_options, timehist_usage, 0); + if (argc) + usage_with_options(timehist_usage, timehist_options); + } + } else + usage_with_options(kwork_usage, kwork_options); + + return 0; +} diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h index 7303e80a639c..d03afea86217 100644 --- a/tools/perf/builtin.h +++ b/tools/perf/builtin.h @@ -38,6 +38,7 @@ int cmd_mem(int argc, const char **argv); int cmd_data(int argc, const char **argv); int cmd_ftrace(int argc, const char **argv); int cmd_daemon(int argc, const char **argv); +int cmd_kwork(int argc, const char **argv); =20 int find_scripts(char **scripts_array, char **scripts_path_array, int num, int pathlen); diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt index 4aa034aefa33..295418840426 100644 --- a/tools/perf/command-list.txt +++ b/tools/perf/command-list.txt @@ -18,6 +18,7 @@ perf-iostat mainporcelain common perf-kallsyms mainporcelain common perf-kmem mainporcelain common perf-kvm mainporcelain common +perf-kwork mainporcelain common perf-list mainporcelain common perf-lock mainporcelain common perf-mem mainporcelain common diff --git a/tools/perf/perf.c b/tools/perf/perf.c index 0170cb0819d6..c21b3973641a 100644 --- a/tools/perf/perf.c +++ b/tools/perf/perf.c @@ -91,6 +91,7 @@ static struct cmd_struct commands[] =3D { { "data", cmd_data, 0 }, { "ftrace", cmd_ftrace, 0 }, { "daemon", cmd_daemon, 0 }, + { "kwork", cmd_kwork, 0 }, }; =20 struct pager_config { --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id CB30FC433EF for ; Mon, 13 Jun 2022 09:49:43 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241216AbiFMJtm (ORCPT ); Mon, 13 Jun 2022 05:49:42 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47300 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241095AbiFMJs1 (ORCPT ); Mon, 13 Jun 2022 05:48:27 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 9AA5418B2E; Mon, 13 Jun 2022 02:48:24 -0700 (PDT) Received: from dggemv711-chm.china.huawei.com (unknown [172.30.72.54]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6Cz09KxzjXf5; Mon, 13 Jun 2022 17:46:55 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv711-chm.china.huawei.com (10.1.198.66) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:04 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:03 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 02/13] perf kwork: Add irq record support Date: Mon, 13 Jun 2022 17:45:54 +0800 Message-ID: <20220613094605.208401-3-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Record interrupt events irq:irq_handler_entry & irq_handler_exit: Record irq events: # perf kwork record -o perf_kwork.date -- sleep 1 [ perf record: Woken up 0 times to write data ] [ perf record: Captured and wrote 0.524 MB perf_kwork.date ] # perf evlist -i perf_kwork.date irq:irq_handler_entry irq:irq_handler_exit dummy:HG Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index b89e41fcc568..822904b2597e 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -25,6 +25,7 @@ #include =20 enum kwork_class_type { + KWORK_CLASS_IRQ, KWORK_CLASS_MAX, }; =20 @@ -68,7 +69,19 @@ struct perf_kwork { const char *sort_order; }; =20 +const struct evsel_str_handler irq_tp_handlers[] =3D { + { "irq:irq_handler_entry", NULL, }, + { "irq:irq_handler_exit", NULL, }, +}; + +static struct kwork_class kwork_irq =3D { + .name =3D "irq", + .nr_tracepoints =3D 2, + .tp_handlers =3D irq_tp_handlers, +}; + static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] =3D= { + [KWORK_CLASS_IRQ] =3D &kwork_irq, }; =20 static void setup_event_list(struct perf_kwork *kwork, --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id AFA2DCCA47B for ; Mon, 13 Jun 2022 09:50:12 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241364AbiFMJuK (ORCPT ); Mon, 13 Jun 2022 05:50:10 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:48212 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241195AbiFMJtk (ORCPT ); Mon, 13 Jun 2022 05:49:40 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 8F9381A83B; Mon, 13 Jun 2022 02:49:21 -0700 (PDT) Received: from dggemv704-chm.china.huawei.com (unknown [172.30.72.56]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6F41lLGzjXf4; Mon, 13 Jun 2022 17:47:52 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv704-chm.china.huawei.com (10.3.19.47) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:05 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:04 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 03/13] perf kwork: Add softirq record support Date: Mon, 13 Jun 2022 17:45:55 +0800 Message-ID: <20220613094605.208401-4-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Record softirq events irq:softirq_raise, irq:softirq_entry & irq:softirq_exit. Record all events: # perf kwork record -o perf_kwork.date -- sleep 1 [ perf record: Woken up 0 times to write data ] [ perf record: Captured and wrote 0.736 MB perf_kwork.date ] # perf evlist -i perf_kwork.date irq:irq_handler_entry irq:irq_handler_exit irq:softirq_raise irq:softirq_entry irq:softirq_exit dummy:HG Record softirq events: # perf kwork -k softirq record -o perf_kwork.date -- sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.165 MB perf_kwork.date ] # perf evlist -i perf_kwork.date irq:softirq_raise irq:softirq_entry irq:softirq_exit dummy:HG Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 822904b2597e..0da554e04f16 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -26,6 +26,7 @@ =20 enum kwork_class_type { KWORK_CLASS_IRQ, + KWORK_CLASS_SOFTIRQ, KWORK_CLASS_MAX, }; =20 @@ -80,8 +81,21 @@ static struct kwork_class kwork_irq =3D { .tp_handlers =3D irq_tp_handlers, }; =20 +const struct evsel_str_handler softirq_tp_handlers[] =3D { + { "irq:softirq_raise", NULL, }, + { "irq:softirq_entry", NULL, }, + { "irq:softirq_exit", NULL, }, +}; + +static struct kwork_class kwork_softirq =3D { + .name =3D "softirq", + .nr_tracepoints =3D 3, + .tp_handlers =3D softirq_tp_handlers, +}; + static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] =3D= { [KWORK_CLASS_IRQ] =3D &kwork_irq, + [KWORK_CLASS_SOFTIRQ] =3D &kwork_softirq, }; =20 static void setup_event_list(struct perf_kwork *kwork, --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id C32A9CCA47B for ; Mon, 13 Jun 2022 09:50:15 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241296AbiFMJuO (ORCPT ); Mon, 13 Jun 2022 05:50:14 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:48554 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241198AbiFMJtk (ORCPT ); Mon, 13 Jun 2022 05:49:40 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 9449C1AD87; Mon, 13 Jun 2022 02:49:21 -0700 (PDT) Received: from dggemv704-chm.china.huawei.com (unknown [172.30.72.56]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6F424gNzjXfK; Mon, 13 Jun 2022 17:47:52 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv704-chm.china.huawei.com (10.3.19.47) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:05 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:04 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 04/13] perf kwork: Add workqueue record support Date: Mon, 13 Jun 2022 17:45:56 +0800 Message-ID: <20220613094605.208401-5-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Record workqueue events workqueue:workqueue_activate_work, workqueue:workqueue_execute_start & workqueue:workqueue_execute_end Record all events: # perf kwork record -o perf_kwork.date -- sleep 1 [ perf record: Woken up 0 times to write data ] [ perf record: Captured and wrote 0.839 MB perf_kwork.date ] # perf evlist -i perf_kwork.date irq:irq_handler_entry irq:irq_handler_exit irq:softirq_raise irq:softirq_entry irq:softirq_exit workqueue:workqueue_activate_work workqueue:workqueue_execute_start workqueue:workqueue_execute_end dummy:HG Record workqueue events: # perf kwork -k workqueue record -o perf_kwork.date -- sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.080 MB perf_kwork.date ] # perf evlist -i perf_kwork.date workqueue:workqueue_activate_work workqueue:workqueue_execute_start workqueue:workqueue_execute_end dummy:HG Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 0da554e04f16..cda6fcbc6e41 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -27,6 +27,7 @@ enum kwork_class_type { KWORK_CLASS_IRQ, KWORK_CLASS_SOFTIRQ, + KWORK_CLASS_WORKQUEUE, KWORK_CLASS_MAX, }; =20 @@ -93,9 +94,22 @@ static struct kwork_class kwork_softirq =3D { .tp_handlers =3D softirq_tp_handlers, }; =20 +const struct evsel_str_handler workqueue_tp_handlers[] =3D { + { "workqueue:workqueue_activate_work", NULL, }, + { "workqueue:workqueue_execute_start", NULL, }, + { "workqueue:workqueue_execute_end", NULL, }, +}; + +static struct kwork_class kwork_workqueue =3D { + .name =3D "workqueue", + .nr_tracepoints =3D 3, + .tp_handlers =3D workqueue_tp_handlers, +}; + static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] =3D= { [KWORK_CLASS_IRQ] =3D &kwork_irq, [KWORK_CLASS_SOFTIRQ] =3D &kwork_softirq, + [KWORK_CLASS_WORKQUEUE] =3D &kwork_workqueue, }; =20 static void setup_event_list(struct perf_kwork *kwork, --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id DD971C43334 for ; Mon, 13 Jun 2022 09:48:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S240687AbiFMJsq (ORCPT ); Mon, 13 Jun 2022 05:48:46 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43690 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S240656AbiFMJsK (ORCPT ); Mon, 13 Jun 2022 05:48:10 -0400 Received: from szxga01-in.huawei.com (szxga01-in.huawei.com [45.249.212.187]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 31B90193F8; Mon, 13 Jun 2022 02:48:08 -0700 (PDT) Received: from dggemv703-chm.china.huawei.com (unknown [172.30.72.56]) by szxga01-in.huawei.com (SkyGuard) with ESMTP id 4LM6D66n53zjXZg; Mon, 13 Jun 2022 17:47:02 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv703-chm.china.huawei.com (10.3.19.46) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:05 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:05 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 05/13] tools lib: Add list_last_entry_or_null Date: Mon, 13 Jun 2022 17:45:57 +0800 Message-ID: <20220613094605.208401-6-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Add list_last_entry_or_null to get the last element from a list, returns NULL if the list is empty. Signed-off-by: Yang Jihong --- tools/include/linux/list.h | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/tools/include/linux/list.h b/tools/include/linux/list.h index b2fc48d5478c..a4dfb6a7cc6a 100644 --- a/tools/include/linux/list.h +++ b/tools/include/linux/list.h @@ -384,6 +384,17 @@ static inline void list_splice_tail_init(struct list_h= ead *list, #define list_first_entry_or_null(ptr, type, member) \ (!list_empty(ptr) ? list_first_entry(ptr, type, member) : NULL) =20 +/** + * list_last_entry_or_null - get the last element from a list + * @ptr: the list head to take the element from. + * @type: the type of the struct this is embedded in. + * @member: the name of the list_head within the struct. + * + * Note that if the list is empty, it returns NULL. + */ +#define list_last_entry_or_null(ptr, type, member) \ + (!list_empty(ptr) ? list_last_entry(ptr, type, member) : NULL) + /** * list_next_entry - get the next element in list * @pos: the type * to cursor --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 6AC6FC433EF for ; Mon, 13 Jun 2022 09:49:40 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241186AbiFMJti (ORCPT ); Mon, 13 Jun 2022 05:49:38 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43636 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241104AbiFMJs2 (ORCPT ); Mon, 13 Jun 2022 05:48:28 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 49E7018B2F; Mon, 13 Jun 2022 02:48:24 -0700 (PDT) Received: from dggemv711-chm.china.huawei.com (unknown [172.30.72.54]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6Cz0VbKzjXdh; Mon, 13 Jun 2022 17:46:55 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv711-chm.china.huawei.com (10.1.198.66) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:06 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:05 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 06/13] perf kwork: Implement perf kwork report Date: Mon, 13 Jun 2022 17:45:58 +0800 Message-ID: <20220613094605.208401-7-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements framework of perf kwork report, which is used to report time properties such as run time and frequency: test case: Kwork Name | Cpu | Avg delay | Frequency | Max delay = | Max delay start | Max delay end | --------------------------------------------------------------------------= ------------------------------------------------- --------------------------------------------------------------------------= ------------------------------------------------- Since there are no report supported events, the output is empty. Briefly describe the data structure: 1. "class" indicates event type. For example, irq and softiq correspond to different types. 2. "cluster" refers to a specific event corresponding to a type. For example, RCU and TIMER in softirq correspond to different clusters, which contains three types of events: raise, entry, and exit. 3. "atom" includes time of each sample and sample of the previous phase. (For example, exit corresponds to entry, which is used for timehist.) Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 937 +++++++++++++++++++++++++++++++++++++ 1 file changed, 937 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index cda6fcbc6e41..ec199942150f 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -31,19 +31,122 @@ enum kwork_class_type { KWORK_CLASS_MAX, }; =20 +enum kwork_trace_type { + KWORK_TRACE_ENTRY, + KWORK_TRACE_EXIT, + KWORK_TRACE_MAX, +}; + +enum kwork_report_type { + KWORK_REPORT_RUNTIME, +}; + +/* + * data structure: + * perf_kwork --> kwork_class (irq) --> kwork_cluster (RCU) --> atom_list = (KWROK_TRACE_RAISE) + * | | |-> atom_list = (KWROK_TRACE_ENTRY) + * | | -> atom_list = (KWROK_TRACE_EXIT) + * | | + * | |-> kwork_cluster (TIMER) --> atom_lis= t (KWROK_TRACE_RAISE) + * | | |-> atom_lis= t (KWROK_TRACE_ENTRY) + * | | -> atom_lis= t (KWROK_TRACE_EXIT) + * | | + * | -> ... + * | + * |-> kwork_class (softirq) --> ... + * | | + * | -> ... + * | + * -> ... + */ + +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_cluster { + /* + * class field + */ + struct rb_node node; + struct kwork_class *class; + + /* + * cluster filed + */ + 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; =20 unsigned int nr_tracepoints; const struct evsel_str_handler *tp_handlers; + + struct rb_root_cached cluster_root; + + int (*class_init)(struct kwork_class *class, + struct perf_session *session); + + void (*cluster_init)(struct kwork_class *class, + struct kwork_cluster *cluster, + struct evsel *evsel, struct perf_sample *sample); + + void (*cluster_name)(struct kwork_cluster *cluster, + 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); }; =20 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_cluster_root; + const struct trace_kwork_handler *tp_handler; =20 /* * profile filters @@ -61,6 +164,7 @@ struct perf_kwork { */ bool force; const char *event_list_str; + enum kwork_report_type report; =20 /* * options for subcommand @@ -69,8 +173,472 @@ struct perf_kwork { bool show_callchain; unsigned int max_stack; 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]; +}; + +/* + * report header elements width + */ +#define PRINT_CPU_WIDTH 4 +#define PRINT_FREQ_WIDTH 9 +#define PRINT_RUNTIME_WIDTH 10 +#define PRINT_TIMESTAMP_WIDTH 17 +#define PRINT_KWORK_NAME_WIDTH 25 +#define RPINT_DECIMAL_WIDTH 3 +#define PRINT_TIME_UNIT_SEC_WIDTH 2 +#define PRINT_TIME_UNIT_MESC_WIDTH 3 +#define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_= MESC_WIDTH) +#define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_U= NIT_SEC_WIDTH) + +struct sort_dimension { + const char *name; + int (*cmp)(struct kwork_cluster *l, struct kwork_cluster *r); + struct list_head list; }; =20 +static int id_cmp(struct kwork_cluster *l, struct kwork_cluster *r) +{ + if (l->cpu > r->cpu) + return 1; + if (l->cpu < r->cpu) + return -1; + + if (l->id > r->id) + return 1; + if (l->id < r->id) + return -1; + + return 0; +} + +static int freq_cmp(struct kwork_cluster *l, struct kwork_cluster *r) +{ + if (l->nr_atoms > r->nr_atoms) + return 1; + if (l->nr_atoms < r->nr_atoms) + return -1; + + return 0; +} + +static int runtime_cmp(struct kwork_cluster *l, struct kwork_cluster *r) +{ + if (l->total_runtime > r->total_runtime) + return 1; + if (l->total_runtime < r->total_runtime) + return -1; + + return 0; +} + +static int max_runtime_cmp(struct kwork_cluster *l, struct kwork_cluster *= r) +{ + if (l->max_runtime > r->max_runtime) + return 1; + if (l->max_runtime < r->max_runtime) + return -1; + + return 0; +} + +static int sort_dimension__add(struct perf_kwork *kwork __maybe_unused, + const char *tok, struct list_head *list) +{ + size_t i; + static struct sort_dimension max_sort_dimension =3D { + .name =3D "max", + .cmp =3D max_runtime_cmp, + }; + static struct sort_dimension id_sort_dimension =3D { + .name =3D "id", + .cmp =3D id_cmp, + }; + static struct sort_dimension runtime_sort_dimension =3D { + .name =3D "runtime", + .cmp =3D runtime_cmp, + }; + static struct sort_dimension freq_sort_dimension =3D { + .name =3D "freq", + .cmp =3D freq_cmp, + }; + struct sort_dimension *available_sorts[] =3D { + &id_sort_dimension, + &max_sort_dimension, + &freq_sort_dimension, + &runtime_sort_dimension, + }; + + for (i =3D 0; i < ARRAY_SIZE(available_sorts); i++) { + if (!strcmp(available_sorts[i]->name, tok)) { + list_add_tail(&available_sorts[i]->list, list); + return 0; + } + } + + return -1; +} + +static void setup_sorting(struct perf_kwork *kwork, + const struct option *options, + const char * const usage_msg[]) +{ + char *tmp, *tok, *str =3D strdup(kwork->sort_order); + + for (tok =3D strtok_r(str, ", ", &tmp); + tok; tok =3D strtok_r(NULL, ", ", &tmp)) { + if (sort_dimension__add(kwork, tok, &kwork->sort_list) < 0) + usage_with_options_msg(usage_msg, options, + "Unknown --sort key: `%s'", tok); + } + + pr_debug("Sort order: %s\n", kwork->sort_order); + free(str); +} + +static struct kwork_atom *atom_new(struct perf_kwork *kwork, + struct perf_sample *sample) +{ + unsigned long i; + struct kwork_atom_page *page; + struct kwork_atom *atom =3D NULL; + + list_for_each_entry(page, &kwork->atom_page_list, list) { + if (!bitmap_full(page->bitmap, NR_ATOM_PER_PAGE)) { + i =3D find_first_zero_bit(page->bitmap, NR_ATOM_PER_PAGE); + BUG_ON(i >=3D NR_ATOM_PER_PAGE); + atom =3D &page->atoms[i]; + goto found_atom; + } + } + + /* + * new page + */ + page =3D zalloc(sizeof(*page)); + if (page =3D=3D NULL) { + pr_debug("Failed to zalloc kwork atom page\n"); + return NULL; + } + + i =3D 0; + atom =3D &page->atoms[0]; + list_add_tail(&page->list, &kwork->atom_page_list); + +found_atom: + set_bit(i, page->bitmap); + atom->time =3D sample->time; + atom->prev =3D NULL; + atom->page_addr =3D page; + atom->bit_inpage =3D i; + return atom; +} + +static void atom_free(struct kwork_atom *atom) +{ + if (atom->prev !=3D NULL) + atom_free(atom->prev); + + clear_bit(atom->bit_inpage, + ((struct kwork_atom_page *)atom->page_addr)->bitmap); +} + +static void atom_del(struct kwork_atom *atom) +{ + list_del(&atom->list); + atom_free(atom); +} + +static int cluster_cmp(struct list_head *list, + struct kwork_cluster *l, struct kwork_cluster *r) +{ + int ret =3D 0; + struct sort_dimension *sort; + + BUG_ON(list_empty(list)); + + list_for_each_entry(sort, list, list) { + ret =3D sort->cmp(l, r); + if (ret) + return ret; + } + + return ret; +} + +static struct kwork_cluster *cluster_search(struct rb_root_cached *root, + struct kwork_cluster *key, + struct list_head *sort_list) +{ + int cmp; + struct kwork_cluster *cluster; + struct rb_node *node =3D root->rb_root.rb_node; + + while (node) { + cluster =3D container_of(node, struct kwork_cluster, node); + cmp =3D cluster_cmp(sort_list, key, cluster); + if (cmp > 0) + node =3D node->rb_left; + else if (cmp < 0) + node =3D node->rb_right; + else { + if (cluster->name =3D=3D NULL) + cluster->name =3D key->name; + return cluster; + } + } + return NULL; +} + +static void cluster_insert(struct rb_root_cached *root, + struct kwork_cluster *key, struct list_head *sort_list) +{ + int cmp; + bool leftmost =3D true; + struct kwork_cluster *cur; + struct rb_node **new =3D &(root->rb_root.rb_node), *parent =3D NULL; + + while (*new) { + cur =3D container_of(*new, struct kwork_cluster, node); + parent =3D *new; + cmp =3D cluster_cmp(sort_list, key, cur); + + if (cmp > 0) + new =3D &((*new)->rb_left); + else { + new =3D &((*new)->rb_right); + leftmost =3D false; + } + } + + rb_link_node(&key->node, parent, new); + rb_insert_color_cached(&key->node, root, leftmost); +} + +static struct kwork_cluster *cluster_new(struct kwork_cluster *key) +{ + int i; + struct kwork_cluster *cluster =3D zalloc(sizeof(*cluster)); + + if (cluster =3D=3D NULL) { + pr_debug("Failed to zalloc kwork cluster\n"); + return NULL; + } + + for (i =3D 0; i < KWORK_TRACE_MAX; i++) + INIT_LIST_HEAD(&cluster->atom_list[i]); + + cluster->id =3D key->id; + cluster->cpu =3D key->cpu; + cluster->name =3D key->name; + cluster->class =3D key->class; + return cluster; +} + +static struct kwork_cluster *cluster_findnew(struct rb_root_cached *root, + struct kwork_cluster *key, + struct list_head *sort_list) +{ + struct kwork_cluster *cluster =3D NULL; + + cluster =3D cluster_search(root, key, sort_list); + if (cluster !=3D NULL) + return cluster; + + cluster =3D cluster_new(key); + if (cluster =3D=3D NULL) + return NULL; + + cluster_insert(root, cluster, sort_list); + return cluster; +} + +static void profile_update_timespan(struct perf_kwork *kwork, + struct perf_sample *sample) +{ + if (!kwork->summary) + return; + + if ((kwork->timestart =3D=3D 0) || (kwork->timestart > sample->time)) + kwork->timestart =3D sample->time; + + if (kwork->timeend < sample->time) + kwork->timeend =3D sample->time; +} + +static bool profile_event_match(struct perf_kwork *kwork, + struct kwork_cluster *cluster, + struct perf_sample *sample) +{ + int cpu =3D cluster->cpu; + u64 time =3D sample->time; + struct perf_time_interval *ptime =3D &kwork->ptime; + + if ((kwork->cpu_list !=3D NULL) && !test_bit(cpu, kwork->cpu_bitmap)) + return false; + + if (((ptime->start !=3D 0) && (ptime->start > time)) || + ((ptime->end !=3D 0) && (ptime->end < time))) + return false; + + if ((kwork->profile_name !=3D NULL) && + ((cluster->name =3D=3D NULL) || + (strcmp(cluster->name, kwork->profile_name) !=3D 0))) + return false; + + profile_update_timespan(kwork, sample); + return true; +} + +static int cluster_push_atom(struct perf_kwork *kwork, + struct kwork_class *class, + enum kwork_trace_type src_type, + enum kwork_trace_type dst_type, + struct evsel *evsel, + struct perf_sample *sample, + struct kwork_cluster **ret_cluster) +{ + struct kwork_atom *atom, *dst_atom; + struct kwork_cluster *cluster, key; + + BUG_ON(class->cluster_init =3D=3D NULL); + class->cluster_init(class, &key, evsel, sample); + + atom =3D atom_new(kwork, sample); + if (atom =3D=3D NULL) + return -1; + + cluster =3D cluster_findnew(&class->cluster_root, &key, &kwork->cmp_id); + if (cluster =3D=3D NULL) { + free(atom); + return -1; + } + + if (!profile_event_match(kwork, cluster, sample)) + return 0; + + if ((dst_type >=3D 0) && (dst_type < KWORK_TRACE_MAX)) { + dst_atom =3D list_last_entry_or_null(&cluster->atom_list[dst_type], + struct kwork_atom, list); + if (dst_atom !=3D NULL) { + atom->prev =3D dst_atom; + list_del(&dst_atom->list); + } + } + + if (ret_cluster !=3D NULL) + *ret_cluster =3D cluster; + + list_add_tail(&atom->list, &cluster->atom_list[src_type]); + + return 0; +} + +static struct kwork_atom *cluster_pop_atom(struct perf_kwork *kwork, + struct kwork_class *class, + enum kwork_trace_type src_type, + enum kwork_trace_type dst_type, + struct evsel *evsel, + struct perf_sample *sample, + struct kwork_cluster **ret_cluster) +{ + struct kwork_atom *atom, *src_atom; + struct kwork_cluster *cluster, key; + + BUG_ON(class->cluster_init =3D=3D NULL); + class->cluster_init(class, &key, evsel, sample); + + cluster =3D cluster_findnew(&class->cluster_root, &key, &kwork->cmp_id); + if (ret_cluster !=3D NULL) + *ret_cluster =3D cluster; + + if (cluster =3D=3D NULL) + return NULL; + + if (!profile_event_match(kwork, cluster, sample)) + return NULL; + + atom =3D list_last_entry_or_null(&cluster->atom_list[dst_type], + struct kwork_atom, list); + if (atom !=3D NULL) + return atom; + + src_atom =3D atom_new(kwork, sample); + if (src_atom !=3D NULL) + list_add_tail(&src_atom->list, &cluster->atom_list[src_type]); + else { + if (ret_cluster !=3D NULL) + *ret_cluster =3D NULL; + } + + return NULL; +} + +static void report_update_exit_event(struct kwork_cluster *cluster, + struct kwork_atom *atom, + struct perf_sample *sample) +{ + u64 delta; + u64 exit_time =3D sample->time; + u64 entry_time =3D atom->time; + + if ((entry_time !=3D 0) && (exit_time >=3D entry_time)) { + delta =3D exit_time - entry_time; + if ((delta > cluster->max_runtime) || + (cluster->max_runtime =3D=3D 0)) { + cluster->max_runtime =3D delta; + cluster->max_runtime_start =3D entry_time; + cluster->max_runtime_end =3D exit_time; + } + cluster->total_runtime +=3D delta; + cluster->nr_atoms++; + } +} + +static int report_entry_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine __maybe_unused) +{ + return cluster_push_atom(kwork, class, KWORK_TRACE_ENTRY, + KWORK_TRACE_MAX, evsel, sample, NULL); +} + +static int report_exit_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine __maybe_unused) +{ + struct kwork_atom *atom =3D NULL; + struct kwork_cluster *cluster =3D NULL; + + atom =3D cluster_pop_atom(kwork, class, KWORK_TRACE_EXIT, + KWORK_TRACE_ENTRY, evsel, sample, &cluster); + if (cluster =3D=3D NULL) + return -1; + + if (atom !=3D NULL) { + report_update_exit_event(cluster, atom, sample); + atom_del(atom); + } + + return 0; +} + const struct evsel_str_handler irq_tp_handlers[] =3D { { "irq:irq_handler_entry", NULL, }, { "irq:irq_handler_exit", NULL, }, @@ -112,6 +680,182 @@ static struct kwork_class *kwork_class_supported_list= [KWORK_CLASS_MAX] =3D { [KWORK_CLASS_WORKQUEUE] =3D &kwork_workqueue, }; =20 +static void print_separator(int len) +{ + printf(" %.*s\n", len, graph_dotted_line); +} + +static void report_print_cluster(struct perf_kwork *kwork, + struct kwork_cluster *cluster) +{ + int ret =3D 0; + char kwork_name[PRINT_KWORK_NAME_WIDTH]; + char max_runtime_start[32], max_runtime_end[32]; + + printf(" "); + + /* + * kwork name + */ + if (cluster->class && cluster->class->cluster_name) { + cluster->class->cluster_name(cluster, kwork_name, + PRINT_KWORK_NAME_WIDTH); + ret +=3D printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, kwork_name); + } else + ret +=3D printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, ""); + + /* + * cpu + */ + ret +=3D printf(" %0*d |", PRINT_CPU_WIDTH, cluster->cpu); + + /* + * total runtime + */ + if (kwork->report =3D=3D KWORK_REPORT_RUNTIME) + ret +=3D printf(" %*.*f ms |", + PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, + (double)cluster->total_runtime / NSEC_PER_MSEC); + + /* + * frequency + */ + ret +=3D printf(" %*" PRIu64 " |", PRINT_FREQ_WIDTH, cluster->nr_atoms); + + /* + * max runtime, max runtime start, max runtime end + */ + if (kwork->report =3D=3D KWORK_REPORT_RUNTIME) { + + timestamp__scnprintf_usec(cluster->max_runtime_start, + max_runtime_start, + sizeof(max_runtime_start)); + timestamp__scnprintf_usec(cluster->max_runtime_end, + max_runtime_end, + sizeof(max_runtime_end)); + ret +=3D printf(" %*.*f ms | %*s s | %*s s |", + PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, + (double)cluster->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 =3D printf(" %-*s | %-*s |", + PRINT_KWORK_NAME_WIDTH, "Kwork Name", + PRINT_CPU_WIDTH, "Cpu"); + + if (kwork->report =3D=3D KWORK_REPORT_RUNTIME) + ret +=3D printf(" %-*s |", + PRINT_RUNTIME_HEADER_WIDTH, "Total Runtime"); + + ret +=3D printf(" %-*s |", PRINT_FREQ_WIDTH, "Frequency"); + + if (kwork->report =3D=3D KWORK_REPORT_RUNTIME) + ret +=3D 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 =3D 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, + (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 =3D 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[] =3D { + [KWORK_TRACE_ENTRY] =3D "entry", + [KWORK_TRACE_EXIT] =3D "exit", + }; + + if ((kwork->nr_skipped_events[KWORK_TRACE_MAX] !=3D 0) && + (kwork->nr_events !=3D 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 =3D 0; i < KWORK_TRACE_MAX; i++) + printf("%" PRIu64 " %s%s", + kwork->nr_skipped_events[i], + kwork_event_str[i], + (i =3D=3D 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 !=3D 0) && (kwork->nr_events !=3D 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 cluster_sort(struct perf_kwork *kwork, struct kwork_class *cla= ss) +{ + struct rb_node *node; + struct kwork_cluster *data; + struct rb_root_cached *root =3D &class->cluster_root; + + pr_debug("Sorting %s ...\n", class->name); + for (;;) { + node =3D rb_first_cached(root); + if (!node) + break; + + rb_erase_cached(node, root); + data =3D rb_entry(node, struct kwork_cluster, node); + cluster_insert(&kwork->sorted_cluster_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) + cluster_sort(kwork, class); +} + static void setup_event_list(struct perf_kwork *kwork, const struct option *options, const char * const usage_msg[]) @@ -154,6 +898,176 @@ static void setup_event_list(struct perf_kwork *kwork, pr_debug("\n"); } =20 +static int perf_kwork__check_config(struct perf_kwork *kwork, + struct perf_session *session) +{ + int ret; + struct evsel *evsel; + struct kwork_class *class; + + static struct trace_kwork_handler report_ops =3D { + .entry_event =3D report_entry_event, + .exit_event =3D report_exit_event, + }; + + switch (kwork->report) { + case KWORK_REPORT_RUNTIME: + kwork->tp_handler =3D &report_ops; + break; + default: + pr_debug("Invalid report type %d\n", kwork->report); + break; + } + + list_for_each_entry(class, &kwork->class_list, list) + if ((class->class_init !=3D NULL) && + (class->class_init(class, session) !=3D 0)) + return -1; + + if (kwork->cpu_list !=3D NULL) { + ret =3D perf_session__cpu_bitmap(session, + kwork->cpu_list, + kwork->cpu_bitmap); + if (ret < 0) { + pr_debug("Invalid cpu bitmap\n"); + return -1; + } + } + + if (kwork->time_str !=3D NULL) { + ret =3D perf_time__parse_str(&kwork->ptime, kwork->time_str); + if (ret !=3D 0) { + pr_debug("Invalid time span\n"); + return -1; + } + } + + list_for_each_entry(evsel, &session->evlist->core.entries, core.node) { + if (kwork->show_callchain && !evsel__has_callchain(evsel)) { + pr_debug("Samples do not have callchains\n"); + kwork->show_callchain =3D 0; + symbol_conf.use_callchain =3D 0; + } + } + + sort_dimension__add(kwork, "id", &kwork->cmp_id); + return 0; +} + +static int perf_kwork__read_events(struct perf_kwork *kwork) +{ + int ret =3D -1; + struct perf_session *session =3D NULL; + + struct perf_data data =3D { + .path =3D input_name, + .mode =3D PERF_DATA_MODE_READ, + .force =3D kwork->force, + }; + + session =3D 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) !=3D 0) + goto out_delete; + + ret =3D perf_session__process_events(session); + if (ret) { + pr_debug("Failed to process events, error %d\n", ret); + goto out_delete; + } + + kwork->nr_events =3D session->evlist->stats.nr_events[0]; + kwork->nr_lost_events =3D session->evlist->stats.total_lost; + kwork->nr_lost_chunks =3D session->evlist->stats.nr_events[PERF_RECORD_LO= ST]; + +out_delete: + perf_session__delete(session); + return ret; +} + +static void process_skipped_events(struct perf_kwork *kwork, + struct kwork_cluster *cluster) +{ + int i; + unsigned long long count; + + for (i =3D 0; i < KWORK_TRACE_MAX; i++) { + count =3D nr_list_entry(&cluster->atom_list[i]); + kwork->nr_skipped_events[i] +=3D count; + kwork->nr_skipped_events[KWORK_TRACE_MAX] +=3D count; + } +} + +static int perf_kwork__report(struct perf_kwork *kwork) +{ + int ret; + struct rb_node *next; + struct kwork_cluster *cluster; + + setup_pager(); + + if (perf_kwork__read_events(kwork) !=3D 0) + return -1; + + perf_kwork__sort(kwork); + + ret =3D report_print_header(kwork); + next =3D rb_first_cached(&kwork->sorted_cluster_root); + while (next) { + cluster =3D rb_entry(next, struct kwork_cluster, node); + process_skipped_events(kwork, cluster); + + if (cluster->nr_atoms !=3D 0) { + report_print_cluster(kwork, cluster); + if (kwork->summary) { + kwork->all_runtime +=3D cluster->total_runtime; + kwork->all_count +=3D cluster->nr_atoms; + } + } + next =3D 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 =3D 0; + + if (evsel->handler !=3D NULL) { + tracepoint_handler f =3D evsel->handler; + + err =3D f(tool, evsel, sample, machine); + } + + return err; +} + static int perf_kwork__record(struct perf_kwork *kwork, int argc, const char **argv) { @@ -203,8 +1117,18 @@ static int perf_kwork__record(struct perf_kwork *kwor= k, =20 int cmd_kwork(int argc, const char **argv) { + static const char default_report_sort_order[] =3D "runtime, max, freq"; static struct perf_kwork kwork =3D { + .tool =3D { + .sample =3D perf_kwork__process_tracepoint_sample, + }, + .class_list =3D LIST_HEAD_INIT(kwork.class_list), + .atom_page_list =3D LIST_HEAD_INIT(kwork.atom_page_list), + .sort_list =3D LIST_HEAD_INIT(kwork.sort_list), + .cmp_id =3D LIST_HEAD_INIT(kwork.cmp_id), + .sorted_cluster_root =3D RB_ROOT_CACHED, + .tp_handler =3D NULL, =20 .profile_name =3D NULL, .cpu_list =3D NULL, @@ -215,6 +1139,15 @@ int cmd_kwork(int argc, const char **argv) .show_callchain =3D false, .max_stack =3D 5, .sort_order =3D NULL, + + .timestart =3D 0, + .timeend =3D 0, + .nr_events =3D 0, + .nr_lost_chunks =3D 0, + .nr_lost_events =3D 0, + .all_runtime =3D 0, + .all_count =3D 0, + .nr_skipped_events =3D { 0 }, }; =20 const struct option kwork_options[] =3D { @@ -308,11 +1241,15 @@ int cmd_kwork(int argc, const char **argv) if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) { return perf_kwork__record(&kwork, argc, argv); } else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) { + kwork.sort_order =3D default_report_sort_order; if (argc > 1) { argc =3D parse_options(argc, argv, report_options, report_usage, 0); if (argc) usage_with_options(report_usage, report_options); } + kwork.report =3D KWORK_REPORT_RUNTIME; + setup_sorting(&kwork, report_options, report_usage); + return perf_kwork__report(&kwork); } else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) { if (argc > 1) { argc =3D parse_options(argc, argv, latency_options, latency_usage, 0); --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 2FEA5C433EF for ; Mon, 13 Jun 2022 09:50:22 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241397AbiFMJuV (ORCPT ); Mon, 13 Jun 2022 05:50:21 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47834 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241088AbiFMJtx (ORCPT ); Mon, 13 Jun 2022 05:49:53 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0F10E1AD92; Mon, 13 Jun 2022 02:49:22 -0700 (PDT) Received: from dggemv704-chm.china.huawei.com (unknown [172.30.72.56]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6F44VbNzjXfd; Mon, 13 Jun 2022 17:47:52 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv704-chm.china.huawei.com (10.3.19.47) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:06 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:06 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 07/13] perf kwork: Add irq report support Date: Mon, 13 Jun 2022 17:45:59 +0800 Message-ID: <20220613094605.208401-8-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements irq kwork report function. test case: # perf kwork rep Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- virtio0-requests:25 | 0000 | 429.202 ms | 7155 | 0.9= 37 ms | 1906657.581035 s | 1906657.581973 s | eth0:10 | 0002 | 0.136 ms | 5 | 0.0= 45 ms | 1906656.302257 s | 1906656.302301 s | ------------------------------------------------------------------------= --------------------------------------------------- # # perf kwork rep -C 2 Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- eth0:10 | 0002 | 0.136 ms | 5 | 0.0= 45 ms | 1906656.302257 s | 1906656.302301 s | ------------------------------------------------------------------------= --------------------------------------------------- # perf kwork rep -C 1,2 Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- eth0:10 | 0002 | 0.136 ms | 5 | 0.0= 45 ms | 1906656.302257 s | 1906656.302301 s | ------------------------------------------------------------------------= --------------------------------------------------- # perf kwork rep -n eth0 Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- eth0:10 | 0002 | 0.136 ms | 5 | 0.0= 45 ms | 1906656.302257 s | 1906656.302301 s | ------------------------------------------------------------------------= --------------------------------------------------- # perf kwork rep -S Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- virtio0-requests:25 | 0000 | 429.202 ms | 7155 | 0.9= 37 ms | 1906657.581035 s | 1906657.581973 s | eth0:10 | 0002 | 0.136 ms | 5 | 0.0= 45 ms | 1906656.302257 s | 1906656.302301 s | ------------------------------------------------------------------------= --------------------------------------------------- Total count : 7160 Total runtime (msec) : 429.338 (0.142% load average) Total time span (msec) : 3013.347 ------------------------------------------------------------------------= --------------------------------------------------- # perf kwork rep --time 1906657, Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- virtio0-requests:25 | 0000 | 228.631 ms | 3855 | 0.9= 37 ms | 1906657.581035 s | 1906657.581973 s | eth0:10 | 0002 | 0.092 ms | 4 | 0.0= 34 ms | 1906658.614010 s | 1906658.614043 s | ------------------------------------------------------------------------= --------------------------------------------------- Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 62 ++++++++++++++++++++++++++++++++++++-- 1 file changed, 60 insertions(+), 2 deletions(-) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index ec199942150f..5741a8ac3e41 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -639,15 +639,73 @@ static int report_exit_event(struct perf_kwork *kwork, return 0; } =20 +static struct kwork_class kwork_irq; +static int process_irq_handler_entry_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->entry_event) + return kwork->tp_handler->entry_event(kwork, &kwork_irq, + evsel, sample, machine); + return 0; +} + +static int process_irq_handler_exit_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->exit_event) + return kwork->tp_handler->exit_event(kwork, &kwork_irq, + evsel, sample, machine); + return 0; +} + const struct evsel_str_handler irq_tp_handlers[] =3D { - { "irq:irq_handler_entry", NULL, }, - { "irq:irq_handler_exit", NULL, }, + { "irq:irq_handler_entry", process_irq_handler_entry_event, }, + { "irq:irq_handler_exit", process_irq_handler_exit_event, }, }; =20 +static int irq_class_init(struct kwork_class *class, + struct perf_session *session) +{ + if (perf_session__set_tracepoints_handlers(session, irq_tp_handlers)) { + pr_debug("Failed to set irq tracepoints handlers\n"); + return -1; + } + + class->cluster_root =3D RB_ROOT_CACHED; + return 0; +} + +static void irq_cluster_init(struct kwork_class *class, + struct kwork_cluster *cluster, + struct evsel *evsel, + struct perf_sample *sample) +{ + cluster->class =3D class; + cluster->cpu =3D sample->cpu; + cluster->id =3D evsel__intval(evsel, sample, "irq"); + cluster->name =3D evsel__strval(evsel, sample, "name"); +} + +static void irq_cluster_name(struct kwork_cluster *cluster, char *buf, int= len) +{ + snprintf(buf, len, "%s:%" PRIu64 "", cluster->name, cluster->id); +} + static struct kwork_class kwork_irq =3D { .name =3D "irq", .nr_tracepoints =3D 2, .tp_handlers =3D irq_tp_handlers, + .class_init =3D irq_class_init, + .cluster_init =3D irq_cluster_init, + .cluster_name =3D irq_cluster_name, }; =20 const struct evsel_str_handler softirq_tp_handlers[] =3D { --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 69479CCA47B for ; Mon, 13 Jun 2022 09:49:35 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241120AbiFMJt3 (ORCPT ); Mon, 13 Jun 2022 05:49:29 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:44512 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S240560AbiFMJsL (ORCPT ); Mon, 13 Jun 2022 05:48:11 -0400 Received: from szxga01-in.huawei.com (szxga01-in.huawei.com [45.249.212.187]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0111919C2D; Mon, 13 Jun 2022 02:48:09 -0700 (PDT) Received: from dggemv703-chm.china.huawei.com (unknown [172.30.72.54]) by szxga01-in.huawei.com (SkyGuard) with ESMTP id 4LM6C74m1KzgYqT; Mon, 13 Jun 2022 17:46:11 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv703-chm.china.huawei.com (10.3.19.46) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:07 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:06 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 08/13] perf kwork: Add softirq report support Date: Mon, 13 Jun 2022 17:46:00 +0800 Message-ID: <20220613094605.208401-9-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements softirq kwork report function. test case: # perf kwork rep Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- virtio0-requests:25 | 0000 | 1073.208 ms | 19333 | 1.3= 31 ms | 2059360.096926 s | 2059360.098257 s | (s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.4= 35 ms | 2059361.588639 s | 2059361.590074 s | (s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.1= 25 ms | 2059359.989698 s | 2059359.989823 s | (s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.9= 78 ms | 2059362.073209 s | 2059362.074187 s | (s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.1= 20 ms | 2059358.259073 s | 2059358.260193 s | (s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.0= 90 ms | 2059364.592682 s | 2059364.592772 s | (s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.0= 87 ms | 2059358.201654 s | 2059358.201742 s | (s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.1= 16 ms | 2059358.207263 s | 2059358.207379 s | (s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.4= 90 ms | 2059361.310045 s | 2059361.311535 s | (s)RCU:9 | 0004 | 10.983 ms | 94 | 0.9= 81 ms | 2059358.241061 s | 2059358.242042 s | (s)RCU:9 | 0000 | 3.102 ms | 66 | 1.5= 68 ms | 2059360.853075 s | 2059360.854643 s | (s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.1= 08 ms | 2059363.117923 s | 2059363.118031 s | (s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.9= 03 ms | 2059359.985888 s | 2059359.986792 s | (s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.1= 92 ms | 2059368.237655 s | 2059368.237847 s | (s)RCU:9 | 0005 | 0.715 ms | 18 | 0.0= 98 ms | 2059360.002711 s | 2059360.002810 s | (s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.1= 30 ms | 2059360.850686 s | 2059360.850816 s | (s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.1= 31 ms | 2059368.237258 s | 2059368.237389 s | (s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.1= 77 ms | 2059362.689653 s | 2059362.689830 s | (s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.1= 74 ms | 2059362.620644 s | 2059362.620818 s | (s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.4= 14 ms | 2059361.265364 s | 2059361.265778 s | (s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.0= 78 ms | 2059361.265799 s | 2059361.265878 s | (s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.0= 84 ms | 2059368.376924 s | 2059368.377008 s | ata_piix:14 | 0002 | 0.221 ms | 4 | 0.0= 96 ms | 2059362.610172 s | 2059362.610267 s | (s)RCU:9 | 0002 | 0.208 ms | 9 | 0.0= 30 ms | 2059359.279854 s | 2059359.279884 s | (s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.1= 99 ms | 2059362.605271 s | 2059362.605471 s | (s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.1= 08 ms | 2059358.207823 s | 2059358.207931 s | (s)RCU:9 | 0006 | 0.150 ms | 4 | 0.0= 77 ms | 2059358.209321 s | 2059358.209398 s | eth0:10 | 0002 | 0.124 ms | 6 | 0.0= 24 ms | 2059359.985835 s | 2059359.985859 s | (s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.0= 46 ms | 2059360.046630 s | 2059360.046676 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.003% skipped events (3 including 0 entry, 3 exit) # perf kwork -k softirq rep Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.4= 35 ms | 2059361.588639 s | 2059361.590074 s | (s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.1= 25 ms | 2059359.989698 s | 2059359.989823 s | (s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.9= 78 ms | 2059362.073209 s | 2059362.074187 s | (s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.1= 20 ms | 2059358.259073 s | 2059358.260193 s | (s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.0= 90 ms | 2059364.592682 s | 2059364.592772 s | (s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.0= 87 ms | 2059358.201654 s | 2059358.201742 s | (s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.1= 16 ms | 2059358.207263 s | 2059358.207379 s | (s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.4= 90 ms | 2059361.310045 s | 2059361.311535 s | (s)RCU:9 | 0004 | 10.983 ms | 94 | 0.9= 81 ms | 2059358.241061 s | 2059358.242042 s | (s)RCU:9 | 0000 | 3.102 ms | 66 | 1.5= 68 ms | 2059360.853075 s | 2059360.854643 s | (s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.1= 08 ms | 2059363.117923 s | 2059363.118031 s | (s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.9= 03 ms | 2059359.985888 s | 2059359.986792 s | (s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.1= 92 ms | 2059368.237655 s | 2059368.237847 s | (s)RCU:9 | 0005 | 0.715 ms | 18 | 0.0= 98 ms | 2059360.002711 s | 2059360.002810 s | (s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.1= 30 ms | 2059360.850686 s | 2059360.850816 s | (s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.1= 31 ms | 2059368.237258 s | 2059368.237389 s | (s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.1= 77 ms | 2059362.689653 s | 2059362.689830 s | (s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.1= 74 ms | 2059362.620644 s | 2059362.620818 s | (s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.4= 14 ms | 2059361.265364 s | 2059361.265778 s | (s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.0= 78 ms | 2059361.265799 s | 2059361.265878 s | (s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.0= 84 ms | 2059368.376924 s | 2059368.377008 s | (s)RCU:9 | 0002 | 0.208 ms | 9 | 0.0= 30 ms | 2059359.279854 s | 2059359.279884 s | (s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.1= 99 ms | 2059362.605271 s | 2059362.605471 s | (s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.1= 08 ms | 2059358.207823 s | 2059358.207931 s | (s)RCU:9 | 0006 | 0.150 ms | 4 | 0.0= 77 ms | 2059358.209321 s | 2059358.209398 s | (s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.0= 46 ms | 2059360.046630 s | 2059360.046676 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.003% skipped events (3 including 0 entry, 3 exit) # perf kwork -k softirq rep -C 0,2 Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.4= 90 ms | 2059361.310045 s | 2059361.311535 s | (s)RCU:9 | 0000 | 3.102 ms | 66 | 1.5= 68 ms | 2059360.853075 s | 2059360.854643 s | (s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.9= 03 ms | 2059359.985888 s | 2059359.986792 s | (s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.1= 30 ms | 2059360.850686 s | 2059360.850816 s | (s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.1= 31 ms | 2059368.237258 s | 2059368.237389 s | (s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.1= 77 ms | 2059362.689653 s | 2059362.689830 s | (s)RCU:9 | 0002 | 0.208 ms | 9 | 0.0= 30 ms | 2059359.279854 s | 2059359.279884 s | ------------------------------------------------------------------------= --------------------------------------------------- # perf kwork -k softirq rep -n RCU Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.4= 35 ms | 2059361.588639 s | 2059361.590074 s | (s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.9= 78 ms | 2059362.073209 s | 2059362.074187 s | (s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.0= 87 ms | 2059358.201654 s | 2059358.201742 s | (s)RCU:9 | 0004 | 10.983 ms | 94 | 0.9= 81 ms | 2059358.241061 s | 2059358.242042 s | (s)RCU:9 | 0000 | 3.102 ms | 66 | 1.5= 68 ms | 2059360.853075 s | 2059360.854643 s | (s)RCU:9 | 0005 | 0.715 ms | 18 | 0.0= 98 ms | 2059360.002711 s | 2059360.002810 s | (s)RCU:9 | 0002 | 0.208 ms | 9 | 0.0= 30 ms | 2059359.279854 s | 2059359.279884 s | (s)RCU:9 | 0006 | 0.150 ms | 4 | 0.0= 77 ms | 2059358.209321 s | 2059358.209398 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.001% skipped events (1 including 0 entry, 1 exit) # perf kwork -k softirq rep -s max,freq Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0000 | 3.102 ms | 66 | 1.5= 68 ms | 2059360.853075 s | 2059360.854643 s | (s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.4= 90 ms | 2059361.310045 s | 2059361.311535 s | (s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.4= 35 ms | 2059361.588639 s | 2059361.590074 s | (s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.1= 20 ms | 2059358.259073 s | 2059358.260193 s | (s)RCU:9 | 0004 | 10.983 ms | 94 | 0.9= 81 ms | 2059358.241061 s | 2059358.242042 s | (s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.9= 78 ms | 2059362.073209 s | 2059362.074187 s | (s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.9= 03 ms | 2059359.985888 s | 2059359.986792 s | (s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.4= 14 ms | 2059361.265364 s | 2059361.265778 s | (s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.1= 99 ms | 2059362.605271 s | 2059362.605471 s | (s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.1= 92 ms | 2059368.237655 s | 2059368.237847 s | (s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.1= 77 ms | 2059362.689653 s | 2059362.689830 s | (s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.1= 74 ms | 2059362.620644 s | 2059362.620818 s | (s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.1= 31 ms | 2059368.237258 s | 2059368.237389 s | (s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.1= 30 ms | 2059360.850686 s | 2059360.850816 s | (s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.1= 25 ms | 2059359.989698 s | 2059359.989823 s | (s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.1= 16 ms | 2059358.207263 s | 2059358.207379 s | (s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.1= 08 ms | 2059363.117923 s | 2059363.118031 s | (s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.1= 08 ms | 2059358.207823 s | 2059358.207931 s | (s)RCU:9 | 0005 | 0.715 ms | 18 | 0.0= 98 ms | 2059360.002711 s | 2059360.002810 s | (s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.0= 90 ms | 2059364.592682 s | 2059364.592772 s | (s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.0= 87 ms | 2059358.201654 s | 2059358.201742 s | (s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.0= 84 ms | 2059368.376924 s | 2059368.377008 s | (s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.0= 78 ms | 2059361.265799 s | 2059361.265878 s | (s)RCU:9 | 0006 | 0.150 ms | 4 | 0.0= 77 ms | 2059358.209321 s | 2059358.209398 s | (s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.0= 46 ms | 2059360.046630 s | 2059360.046676 s | (s)RCU:9 | 0002 | 0.208 ms | 9 | 0.0= 30 ms | 2059359.279854 s | 2059359.279884 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.003% skipped events (3 including 0 entry, 3 exit) # perf kwork -k softirq rep --time 2059361, Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0001 | 148.655 ms | 2838 | 1.4= 35 ms | 2059361.588639 s | 2059361.590074 s | (s)TIMER:1 | 0003 | 109.877 ms | 1811 | 0.1= 21 ms | 2059361.071163 s | 2059361.071284 s | (s)SCHED:7 | 0001 | 48.681 ms | 1140 | 0.0= 90 ms | 2059364.592682 s | 2059364.592772 s | (s)SCHED:7 | 0007 | 32.373 ms | 796 | 0.8= 08 ms | 2059361.088583 s | 2059361.089391 s | (s)RCU:9 | 0003 | 30.198 ms | 1327 | 0.0= 45 ms | 2059363.891611 s | 2059363.891655 s | (s)RCU:9 | 0007 | 28.735 ms | 524 | 0.9= 78 ms | 2059362.073209 s | 2059362.074187 s | (s)SCHED:7 | 0003 | 19.399 ms | 457 | 0.0= 55 ms | 2059367.528239 s | 2059367.528295 s | (s)SCHED:7 | 0000 | 14.284 ms | 143 | 1.4= 90 ms | 2059361.310045 s | 2059361.311535 s | (s)TIMER:1 | 0001 | 1.716 ms | 21 | 0.1= 08 ms | 2059363.117923 s | 2059363.118031 s | (s)RCU:9 | 0004 | 1.061 ms | 10 | 0.7= 66 ms | 2059368.385058 s | 2059368.385824 s | (s)RCU:9 | 0000 | 1.001 ms | 43 | 0.0= 43 ms | 2059364.147987 s | 2059364.148031 s | (s)SCHED:7 | 0002 | 0.591 ms | 8 | 0.1= 77 ms | 2059362.689653 s | 2059362.689830 s | (s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.1= 74 ms | 2059362.620644 s | 2059362.620818 s | (s)TIMER:1 | 0002 | 0.578 ms | 6 | 0.1= 31 ms | 2059368.237258 s | 2059368.237389 s | (s)TIMER:1 | 0007 | 0.491 ms | 4 | 0.1= 92 ms | 2059368.237655 s | 2059368.237847 s | (s)TIMER:1 | 0000 | 0.485 ms | 5 | 0.1= 22 ms | 2059366.586542 s | 2059366.586665 s | (s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.4= 14 ms | 2059361.265364 s | 2059361.265778 s | (s)SCHED:7 | 0004 | 0.199 ms | 3 | 0.0= 84 ms | 2059368.376924 s | 2059368.377008 s | (s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.1= 99 ms | 2059362.605271 s | 2059362.605471 s | (s)SCHED:7 | 0005 | 0.185 ms | 3 | 0.0= 78 ms | 2059361.265799 s | 2059361.265878 s | (s)RCU:9 | 0002 | 0.132 ms | 6 | 0.0= 23 ms | 2059367.469375 s | 2059367.469398 s | (s)RCU:9 | 0005 | 0.128 ms | 4 | 0.0= 36 ms | 2059361.267615 s | 2059361.267652 s | (s)NET_RX:3 | 0002 | 0.125 ms | 4 | 0.0= 35 ms | 2059365.423649 s | 2059365.423684 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.003% skipped events (3 including 0 entry, 3 exit) Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 97 +++++++++++++++++++++++++++++++++++++- 1 file changed, 95 insertions(+), 2 deletions(-) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 5741a8ac3e41..1eb416faf8ef 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -708,16 +708,109 @@ static struct kwork_class kwork_irq =3D { .cluster_name =3D irq_cluster_name, }; =20 +static struct kwork_class kwork_softirq; +static int process_softirq_entry_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->entry_event) + return kwork->tp_handler->entry_event(kwork, &kwork_softirq, + evsel, sample, machine); + + return 0; +} + +static int process_softirq_exit_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->exit_event) + return kwork->tp_handler->exit_event(kwork, &kwork_softirq, + evsel, sample, machine); + + return 0; +} + const struct evsel_str_handler softirq_tp_handlers[] =3D { { "irq:softirq_raise", NULL, }, - { "irq:softirq_entry", NULL, }, - { "irq:softirq_exit", NULL, }, + { "irq:softirq_entry", process_softirq_entry_event, }, + { "irq:softirq_exit", process_softirq_exit_event, }, }; =20 +static int softirq_class_init(struct kwork_class *class, + struct perf_session *session) +{ + if (perf_session__set_tracepoints_handlers(session, + softirq_tp_handlers)) { + pr_debug("Failed to set softirq tracepoints handlers\n"); + return -1; + } + + class->cluster_root =3D RB_ROOT_CACHED; + return 0; +} + +static char *evsel__softirq_name(struct evsel *evsel, u64 num) +{ + char *name =3D NULL; + bool found =3D false; + struct tep_print_flag_sym *sym =3D NULL; + struct tep_print_arg *args =3D evsel->tp_format->print_fmt.args; + + if ((args =3D=3D NULL) || (args->next =3D=3D NULL)) + return NULL; + + /* skip softirq field: "REC->vec" */ + for (sym =3D args->next->symbol.symbols; sym !=3D NULL; sym =3D sym->next= ) { + if ((eval_flag(sym->value) =3D=3D (unsigned long long)num) && + (strlen(sym->str) !=3D 0)) { + found =3D true; + break; + } + } + + if (!found) + return NULL; + + name =3D strdup(sym->str); + if (name =3D=3D NULL) { + pr_debug("Failed to copy symbol name\n"); + return NULL; + } + return name; +} + +static void softirq_cluster_init(struct kwork_class *class, + struct kwork_cluster *cluster, + struct evsel *evsel, + struct perf_sample *sample) +{ + u64 num =3D evsel__intval(evsel, sample, "vec"); + + cluster->id =3D num; + cluster->class =3D class; + cluster->cpu =3D sample->cpu; + cluster->name =3D evsel__softirq_name(evsel, num); +} + +static void softirq_cluster_name(struct kwork_cluster *cluster, char *buf,= int len) +{ + snprintf(buf, len, "(s)%s:%" PRIu64 "", cluster->name, cluster->id); +} + static struct kwork_class kwork_softirq =3D { .name =3D "softirq", .nr_tracepoints =3D 3, .tp_handlers =3D softirq_tp_handlers, + .class_init =3D softirq_class_init, + .cluster_init =3D softirq_cluster_init, + .cluster_name =3D softirq_cluster_name, }; =20 const struct evsel_str_handler workqueue_tp_handlers[] =3D { --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id EEF37C43334 for ; Mon, 13 Jun 2022 09:49:44 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241238AbiFMJto (ORCPT ); Mon, 13 Jun 2022 05:49:44 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:44498 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241091AbiFMJs1 (ORCPT ); Mon, 13 Jun 2022 05:48:27 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 870AD18B29; Mon, 13 Jun 2022 02:48:24 -0700 (PDT) Received: from dggemv711-chm.china.huawei.com (unknown [172.30.72.54]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6Cz11yNzjXf8; Mon, 13 Jun 2022 17:46:55 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv711-chm.china.huawei.com (10.1.198.66) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:07 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:07 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 09/13] perf kwork: Add workqueue report support Date: Mon, 13 Jun 2022 17:46:01 +0800 Message-ID: <20220613094605.208401-10-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements workqueue report function. test case: # perf kwork -k workqueue rep Kwork Name | Cpu | Total Runtime | Frequency | Max runt= ime | Max runtime start | Max runtime end | ------------------------------------------------------------------------= --------------------------------------------------- (w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.3= 76 ms | 2059361.546621 s | 2059361.558997 s | (w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.0= 18 ms | 2059358.441070 s | 2059358.442089 s | (w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.2= 12 ms | 2059362.614643 s | 2059362.617855 s | (w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.9= 62 ms | 2059365.421753 s | 2059365.423714 s | (w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.7= 78 ms | 2059360.851063 s | 2059360.854841 s | (w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.7= 96 ms | 2059360.046818 s | 2059360.048613 s | (w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.6= 19 ms | 2059361.266051 s | 2059361.267670 s | (w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.7= 83 ms | 2059368.238059 s | 2059368.238842 s | (w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.9= 11 ms | 2059359.604075 s | 2059359.604986 s | (w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.0= 46 ms | 2059362.689277 s | 2059362.689323 s | (w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.1= 37 ms | 2059363.117537 s | 2059363.117674 s | (w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.0= 49 ms | 2059365.423784 s | 2059365.423833 s | (w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.0= 47 ms | 2059358.208033 s | 2059358.208080 s | (w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.0= 41 ms | 2059361.071371 s | 2059361.071412 s | (w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.0= 62 ms | 2059362.605723 s | 2059362.605785 s | (w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.0= 56 ms | 2059363.118231 s | 2059363.118287 s | (w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.0= 26 ms | 2059358.573397 s | 2059358.573423 s | (w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.0= 23 ms | 2059368.398864 s | 2059368.398888 s | (w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.0= 00 ms | 2059359.986792 s | 2059359.986792 s | ------------------------------------------------------------------------= --------------------------------------------------- Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 65 ++++++++++++++++++++++++++++++++++++-- 1 file changed, 63 insertions(+), 2 deletions(-) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 1eb416faf8ef..f27ffad223a3 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -813,16 +813,77 @@ static struct kwork_class kwork_softirq =3D { .cluster_name =3D softirq_cluster_name, }; =20 +static struct kwork_class kwork_workqueue; +static int process_workqueue_execute_start_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->entry_event) + return kwork->tp_handler->entry_event(kwork, &kwork_workqueue, + evsel, sample, machine); + + return 0; +} + +static int process_workqueue_execute_end_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->exit_event) + return kwork->tp_handler->exit_event(kwork, &kwork_workqueue, + evsel, sample, machine); + + return 0; +} + const struct evsel_str_handler workqueue_tp_handlers[] =3D { { "workqueue:workqueue_activate_work", NULL, }, - { "workqueue:workqueue_execute_start", NULL, }, - { "workqueue:workqueue_execute_end", NULL, }, + { "workqueue:workqueue_execute_start", process_workqueue_execute_start_ev= ent, }, + { "workqueue:workqueue_execute_end", process_workqueue_execute_end_even= t, }, }; =20 +static int workqueue_class_init(struct kwork_class *class, + struct perf_session *session) +{ + if (perf_session__set_tracepoints_handlers(session, + workqueue_tp_handlers)) { + pr_debug("Failed to set workqueue tracepoints handlers\n"); + return -1; + } + + class->cluster_root =3D RB_ROOT_CACHED; + return 0; +} + +static void workqueue_cluster_init(struct kwork_class *class, + struct kwork_cluster *cluster, + struct evsel *evsel, + struct perf_sample *sample) +{ + cluster->name =3D NULL; + cluster->class =3D class; + cluster->cpu =3D sample->cpu; + cluster->id =3D evsel__intval(evsel, sample, "work"); +} + +static void workqueue_cluster_name(struct kwork_cluster *cluster, char *bu= f, int len) +{ + snprintf(buf, len, "(w)0x%" PRIx64, cluster->id); +} + static struct kwork_class kwork_workqueue =3D { .name =3D "workqueue", .nr_tracepoints =3D 3, .tp_handlers =3D workqueue_tp_handlers, + .class_init =3D workqueue_class_init, + .cluster_init =3D workqueue_cluster_init, + .cluster_name =3D workqueue_cluster_name, }; =20 static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] =3D= { --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id AD402C433EF for ; Mon, 13 Jun 2022 09:50:25 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241319AbiFMJuX (ORCPT ); Mon, 13 Jun 2022 05:50:23 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47974 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241331AbiFMJty (ORCPT ); Mon, 13 Jun 2022 05:49:54 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 55E311ADAA; Mon, 13 Jun 2022 02:49:22 -0700 (PDT) Received: from dggemv704-chm.china.huawei.com (unknown [172.30.72.56]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6F46fh4zjXfm; Mon, 13 Jun 2022 17:47:52 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv704-chm.china.huawei.com (10.3.19.47) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:08 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:07 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 10/13] perf kwork: Implement perf kwork latency Date: Mon, 13 Jun 2022 17:46:02 +0800 Message-ID: <20220613094605.208401-11-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements framework of perf kwork latency, which is used to report time properties such as delay time and frequency. test case: Kwork Name | Cpu | Avg delay | Frequency | Max delay = | Max delay start | Max delay end | --------------------------------------------------------------------------= ------------------------------------------------- --------------------------------------------------------------------------= ------------------------------------------------- INFO: 37.324% skipped events (33174 including 0 raise, 33174 entry, 0 exi= t) Since there are no latency-enabled events, the output is empty. Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 153 +++++++++++++++++++++++++++++++++++++ 1 file changed, 153 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index f27ffad223a3..84e318eea832 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -32,6 +32,7 @@ enum kwork_class_type { }; =20 enum kwork_trace_type { + KWORK_TRACE_RAISE, KWORK_TRACE_ENTRY, KWORK_TRACE_EXIT, KWORK_TRACE_MAX, @@ -39,6 +40,7 @@ enum kwork_trace_type { =20 enum kwork_report_type { KWORK_REPORT_RUNTIME, + KWORK_REPORT_LATENCY, }; =20 /* @@ -104,6 +106,14 @@ struct kwork_cluster { u64 max_runtime_start; u64 max_runtime_end; u64 total_runtime; + + /* + * latency report + */ + u64 max_latency; + u64 max_latency_start; + u64 max_latency_end; + u64 total_latency; }; =20 struct kwork_class { @@ -128,6 +138,10 @@ struct kwork_class { =20 struct perf_kwork; struct trace_kwork_handler { + int (*raise_event)(struct perf_kwork *kwork, + struct kwork_class *class, struct evsel *evsel, + struct perf_sample *sample, struct machine *machine); + int (*entry_event)(struct perf_kwork *kwork, struct kwork_class *class, struct evsel *evsel, struct perf_sample *sample, struct machine *machine); @@ -195,12 +209,14 @@ struct perf_kwork { #define PRINT_CPU_WIDTH 4 #define PRINT_FREQ_WIDTH 9 #define PRINT_RUNTIME_WIDTH 10 +#define PRINT_LATENCY_WIDTH 10 #define PRINT_TIMESTAMP_WIDTH 17 #define PRINT_KWORK_NAME_WIDTH 25 #define RPINT_DECIMAL_WIDTH 3 #define PRINT_TIME_UNIT_SEC_WIDTH 2 #define PRINT_TIME_UNIT_MESC_WIDTH 3 #define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_= MESC_WIDTH) +#define PRINT_LATENCY_HEADER_WIDTH (PRINT_LATENCY_WIDTH + PRINT_TIME_UNIT_= MESC_WIDTH) #define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_U= NIT_SEC_WIDTH) =20 struct sort_dimension { @@ -254,6 +270,36 @@ static int max_runtime_cmp(struct kwork_cluster *l, st= ruct kwork_cluster *r) return 0; } =20 +static int avg_latency_cmp(struct kwork_cluster *l, struct kwork_cluster *= r) +{ + u64 avgl, avgr; + + if (!r->nr_atoms) + return 1; + if (!l->nr_atoms) + return -1; + + avgl =3D l->total_latency / l->nr_atoms; + avgr =3D r->total_latency / r->nr_atoms; + + if (avgl > avgr) + return 1; + if (avgl < avgr) + return -1; + + return 0; +} + +static int max_latency_cmp(struct kwork_cluster *l, struct kwork_cluster *= r) +{ + if (l->max_latency > r->max_latency) + return 1; + if (l->max_latency < r->max_latency) + return -1; + + return 0; +} + static int sort_dimension__add(struct perf_kwork *kwork __maybe_unused, const char *tok, struct list_head *list) { @@ -274,13 +320,21 @@ static int sort_dimension__add(struct perf_kwork *kwo= rk __maybe_unused, .name =3D "freq", .cmp =3D freq_cmp, }; + static struct sort_dimension avg_sort_dimension =3D { + .name =3D "avg", + .cmp =3D avg_latency_cmp, + }; struct sort_dimension *available_sorts[] =3D { &id_sort_dimension, &max_sort_dimension, &freq_sort_dimension, &runtime_sort_dimension, + &avg_sort_dimension, }; =20 + if (kwork->report =3D=3D KWORK_REPORT_LATENCY) + max_sort_dimension.cmp =3D max_latency_cmp; + for (i =3D 0; i < ARRAY_SIZE(available_sorts); i++) { if (!strcmp(available_sorts[i]->name, tok)) { list_add_tail(&available_sorts[i]->list, list); @@ -639,6 +693,59 @@ static int report_exit_event(struct perf_kwork *kwork, return 0; } =20 +static void latency_update_entry_event(struct kwork_cluster *cluster, + struct kwork_atom *atom, + struct perf_sample *sample) +{ + u64 delta; + u64 entry_time =3D sample->time; + u64 raise_time =3D atom->time; + + if ((raise_time !=3D 0) && (entry_time >=3D raise_time)) { + delta =3D entry_time - raise_time; + if ((delta > cluster->max_latency) || + (cluster->max_latency =3D=3D 0)) { + cluster->max_latency =3D delta; + cluster->max_latency_start =3D raise_time; + cluster->max_latency_end =3D entry_time; + } + cluster->total_latency +=3D delta; + cluster->nr_atoms++; + } +} + +static int latency_raise_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine __maybe_unused) +{ + return cluster_push_atom(kwork, class, KWORK_TRACE_RAISE, + KWORK_TRACE_MAX, evsel, sample, NULL); +} + +static int latency_entry_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine __maybe_unused) +{ + struct kwork_atom *atom =3D NULL; + struct kwork_cluster *cluster =3D NULL; + + atom =3D cluster_pop_atom(kwork, class, KWORK_TRACE_ENTRY, + KWORK_TRACE_RAISE, evsel, sample, &cluster); + if (cluster =3D=3D NULL) + return -1; + + if (atom !=3D NULL) { + latency_update_entry_event(cluster, atom, sample); + atom_del(atom); + } + + return 0; +} + static struct kwork_class kwork_irq; static int process_irq_handler_entry_event(struct perf_tool *tool, struct evsel *evsel, @@ -903,6 +1010,7 @@ static void report_print_cluster(struct perf_kwork *kw= ork, int ret =3D 0; char kwork_name[PRINT_KWORK_NAME_WIDTH]; char max_runtime_start[32], max_runtime_end[32]; + char max_latency_start[32], max_latency_end[32]; =20 printf(" "); =20 @@ -928,6 +1036,14 @@ static void report_print_cluster(struct perf_kwork *k= work, ret +=3D printf(" %*.*f ms |", PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, (double)cluster->total_runtime / NSEC_PER_MSEC); + /* + * avg delay + */ + else if (kwork->report =3D=3D KWORK_REPORT_LATENCY) + ret +=3D printf(" %*.*f ms |", + PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH, + (double)cluster->total_latency / + cluster->nr_atoms / NSEC_PER_MSEC); =20 /* * frequency @@ -951,6 +1067,22 @@ static void report_print_cluster(struct perf_kwork *k= work, PRINT_TIMESTAMP_WIDTH, max_runtime_start, PRINT_TIMESTAMP_WIDTH, max_runtime_end); } + /* + * max delay, max delay start, max delay end + */ + else if (kwork->report =3D=3D KWORK_REPORT_LATENCY) { + timestamp__scnprintf_usec(cluster->max_latency_start, + max_latency_start, + sizeof(max_latency_start)); + timestamp__scnprintf_usec(cluster->max_latency_end, + max_latency_end, + sizeof(max_latency_end)); + ret +=3D printf(" %*.*f ms | %*s s | %*s s |", + PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH, + (double)cluster->max_latency / NSEC_PER_MSEC, + PRINT_TIMESTAMP_WIDTH, max_latency_start, + PRINT_TIMESTAMP_WIDTH, max_latency_end); + } =20 printf("\n"); } @@ -967,6 +1099,9 @@ static int report_print_header(struct perf_kwork *kwor= k) if (kwork->report =3D=3D KWORK_REPORT_RUNTIME) ret +=3D printf(" %-*s |", PRINT_RUNTIME_HEADER_WIDTH, "Total Runtime"); + else if (kwork->report =3D=3D KWORK_REPORT_LATENCY) + ret +=3D printf(" %-*s |", + PRINT_LATENCY_HEADER_WIDTH, "Avg delay"); =20 ret +=3D printf(" %-*s |", PRINT_FREQ_WIDTH, "Frequency"); =20 @@ -975,6 +1110,11 @@ static int report_print_header(struct perf_kwork *kwo= rk) PRINT_RUNTIME_HEADER_WIDTH, "Max runtime", PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime start", PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime end"); + else if (kwork->report =3D=3D KWORK_REPORT_LATENCY) + ret +=3D printf(" %-*s | %-*s | %-*s |", + PRINT_LATENCY_HEADER_WIDTH, "Max delay", + PRINT_TIMESTAMP_HEADER_WIDTH, "Max delay start", + PRINT_TIMESTAMP_HEADER_WIDTH, "Max delay end"); =20 printf("\n"); print_separator(ret); @@ -1008,6 +1148,7 @@ static void print_skipped_events(struct perf_kwork *k= work) { int i; const char *const kwork_event_str[] =3D { + [KWORK_TRACE_RAISE] =3D "raise", [KWORK_TRACE_ENTRY] =3D "entry", [KWORK_TRACE_EXIT] =3D "exit", }; @@ -1121,11 +1262,18 @@ static int perf_kwork__check_config(struct perf_kwo= rk *kwork, .entry_event =3D report_entry_event, .exit_event =3D report_exit_event, }; + static struct trace_kwork_handler latency_ops =3D { + .raise_event =3D latency_raise_event, + .entry_event =3D latency_entry_event, + }; =20 switch (kwork->report) { case KWORK_REPORT_RUNTIME: kwork->tp_handler =3D &report_ops; break; + case KWORK_REPORT_LATENCY: + kwork->tp_handler =3D &latency_ops; + break; default: pr_debug("Invalid report type %d\n", kwork->report); break; @@ -1330,6 +1478,7 @@ static int perf_kwork__record(struct perf_kwork *kwor= k, int cmd_kwork(int argc, const char **argv) { static const char default_report_sort_order[] =3D "runtime, max, freq"; + static const char default_latency_sort_order[] =3D "avg, max, freq"; static struct perf_kwork kwork =3D { .tool =3D { .sample =3D perf_kwork__process_tracepoint_sample, @@ -1463,11 +1612,15 @@ int cmd_kwork(int argc, const char **argv) setup_sorting(&kwork, report_options, report_usage); return perf_kwork__report(&kwork); } else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) { + kwork.sort_order =3D default_latency_sort_order; if (argc > 1) { argc =3D parse_options(argc, argv, latency_options, latency_usage, 0); if (argc) usage_with_options(latency_usage, latency_options); } + kwork.report =3D KWORK_REPORT_LATENCY; + setup_sorting(&kwork, latency_options, latency_usage); + return perf_kwork__report(&kwork); } else if (strlen(argv[0]) > 2 && strstarts("timehist", argv[0])) { if (argc > 1) { argc =3D parse_options(argc, argv, timehist_options, timehist_usage, 0); --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 856B9C433EF for ; Mon, 13 Jun 2022 09:48:56 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S234429AbiFMJsz (ORCPT ); Mon, 13 Jun 2022 05:48:55 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42884 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S240506AbiFMJsM (ORCPT ); Mon, 13 Jun 2022 05:48:12 -0400 Received: from szxga01-in.huawei.com (szxga01-in.huawei.com [45.249.212.187]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 4BDB113F05; Mon, 13 Jun 2022 02:48:10 -0700 (PDT) Received: from dggemv703-chm.china.huawei.com (unknown [172.30.72.56]) by szxga01-in.huawei.com (SkyGuard) with ESMTP id 4LM6C90FjHzgYrW; Mon, 13 Jun 2022 17:46:13 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv703-chm.china.huawei.com (10.3.19.46) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:08 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:07 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 11/13] perf kwork: Add softirq latency support Date: Mon, 13 Jun 2022 17:46:03 +0800 Message-ID: <20220613094605.208401-12-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements softirq latency function. test case: # perf kwork lat Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0006 | 1.338 ms | 1 | 1.3= 38 ms | 2072616.369122 s | 2072616.370461 s | (s)RCU:9 | 0005 | 0.945 ms | 2 | 1.7= 57 ms | 2072616.368262 s | 2072616.370020 s | (s)RCU:9 | 0002 | 0.575 ms | 73 | 1.8= 84 ms | 2072616.423139 s | 2072616.425023 s | (s)RCU:9 | 0000 | 0.327 ms | 105 | 1.3= 65 ms | 2072620.344392 s | 2072620.345757 s | (s)RCU:9 | 0001 | 0.233 ms | 711 | 2.8= 62 ms | 2072620.639022 s | 2072620.641885 s | (s)NET_RX:3 | 0002 | 0.219 ms | 5 | 0.7= 62 ms | 2072624.174209 s | 2072624.174971 s | (s)RCU:9 | 0004 | 0.176 ms | 4 | 0.2= 65 ms | 2072620.333206 s | 2072620.333472 s | (s)RCU:9 | 0007 | 0.172 ms | 3165 | 2.8= 90 ms | 2072616.385706 s | 2072616.388595 s | (s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.3= 07 ms | 2072620.638399 s | 2072620.638706 s | (s)RCU:9 | 0003 | 0.149 ms | 194 | 1.1= 27 ms | 2072620.617286 s | 2072620.618413 s | (s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.3= 84 ms | 2072617.261300 s | 2072617.261684 s | (s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.7= 34 ms | 2072620.639022 s | 2072620.641756 s | (s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.9= 89 ms | 2072616.386068 s | 2072616.387057 s | (s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.2= 09 ms | 2072620.354356 s | 2072620.354564 s | (s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.1= 72 ms | 2072620.333236 s | 2072620.333408 s | (s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.2= 26 ms | 2072618.917223 s | 2072618.917449 s | (s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.9= 86 ms | 2072620.392020 s | 2072620.393007 s | (s)TIMER:1 | 0007 | 0.095 ms | 1550 | 1.2= 74 ms | 2072625.965379 s | 2072625.966653 s | (s)TIMER:1 | 0004 | 0.081 ms | 2 | 0.0= 82 ms | 2072620.333187 s | 2072620.333269 s | (s)TIMER:1 | 0002 | 0.076 ms | 10 | 0.1= 04 ms | 2072617.261239 s | 2072617.261344 s | (s)TIMER:1 | 0003 | 0.065 ms | 245 | 1.0= 23 ms | 2072620.617286 s | 2072620.618309 s | (s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.0= 81 ms | 2072616.370310 s | 2072616.370391 s | (s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.4= 73 ms | 2072621.357987 s | 2072621.358460 s | (s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.3= 96 ms | 2072617.523145 s | 2072617.523540 s | (s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.0= 42 ms | 2072616.369895 s | 2072616.369937 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 28.605% skipped events (25424 including 2617 raise, 22807 entry, = 0 exit) # perf kwork lat -C 0,1 Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0000 | 0.327 ms | 105 | 1.3= 65 ms | 2072620.344392 s | 2072620.345757 s | (s)RCU:9 | 0001 | 0.233 ms | 711 | 2.8= 62 ms | 2072620.639022 s | 2072620.641885 s | (s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.3= 07 ms | 2072620.638399 s | 2072620.638706 s | (s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.7= 34 ms | 2072620.639022 s | 2072620.641756 s | (s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.9= 89 ms | 2072616.386068 s | 2072616.387057 s | (s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.2= 09 ms | 2072620.354356 s | 2072620.354564 s | (s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.9= 86 ms | 2072620.392020 s | 2072620.393007 s | (s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.3= 96 ms | 2072617.523145 s | 2072617.523540 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 26.410% skipped events (23473 including 795 raise, 22678 entry, 0= exit) # perf kwork lat -n SCHED Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.3= 84 ms | 2072617.261300 s | 2072617.261684 s | (s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.9= 89 ms | 2072616.386068 s | 2072616.387057 s | (s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.1= 72 ms | 2072620.333236 s | 2072620.333408 s | (s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.2= 26 ms | 2072618.917223 s | 2072618.917449 s | (s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.9= 86 ms | 2072620.392020 s | 2072620.393007 s | (s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.0= 81 ms | 2072616.370310 s | 2072616.370391 s | (s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.4= 73 ms | 2072621.357987 s | 2072621.358460 s | (s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.0= 42 ms | 2072616.369895 s | 2072616.369937 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.006% skipped events (5 including 5 raise, 0 entry, 0 exit) # perf kwork lat -s freq,max Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0007 | 0.172 ms | 3165 | 2.8= 90 ms | 2072616.385706 s | 2072616.388595 s | (s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.4= 73 ms | 2072621.357987 s | 2072621.358460 s | (s)TIMER:1 | 0007 | 0.095 ms | 1550 | 1.2= 74 ms | 2072625.965379 s | 2072625.966653 s | (s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.3= 96 ms | 2072617.523145 s | 2072617.523540 s | (s)RCU:9 | 0001 | 0.233 ms | 711 | 2.8= 62 ms | 2072620.639022 s | 2072620.641885 s | (s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.9= 89 ms | 2072616.386068 s | 2072616.387057 s | (s)TIMER:1 | 0003 | 0.065 ms | 245 | 1.0= 23 ms | 2072620.617286 s | 2072620.618309 s | (s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.9= 86 ms | 2072620.392020 s | 2072620.393007 s | (s)RCU:9 | 0003 | 0.149 ms | 194 | 1.1= 27 ms | 2072620.617286 s | 2072620.618413 s | (s)RCU:9 | 0000 | 0.327 ms | 105 | 1.3= 65 ms | 2072620.344392 s | 2072620.345757 s | (s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.2= 26 ms | 2072618.917223 s | 2072618.917449 s | (s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.7= 34 ms | 2072620.639022 s | 2072620.641756 s | (s)RCU:9 | 0002 | 0.575 ms | 73 | 1.8= 84 ms | 2072616.423139 s | 2072616.425023 s | (s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.2= 09 ms | 2072620.354356 s | 2072620.354564 s | (s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.3= 84 ms | 2072617.261300 s | 2072617.261684 s | (s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.3= 07 ms | 2072620.638399 s | 2072620.638706 s | (s)TIMER:1 | 0002 | 0.076 ms | 10 | 0.1= 04 ms | 2072617.261239 s | 2072617.261344 s | (s)NET_RX:3 | 0002 | 0.219 ms | 5 | 0.7= 62 ms | 2072624.174209 s | 2072624.174971 s | (s)RCU:9 | 0004 | 0.176 ms | 4 | 0.2= 65 ms | 2072620.333206 s | 2072620.333472 s | (s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.1= 72 ms | 2072620.333236 s | 2072620.333408 s | (s)RCU:9 | 0005 | 0.945 ms | 2 | 1.7= 57 ms | 2072616.368262 s | 2072616.370020 s | (s)TIMER:1 | 0004 | 0.081 ms | 2 | 0.0= 82 ms | 2072620.333187 s | 2072620.333269 s | (s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.0= 81 ms | 2072616.370310 s | 2072616.370391 s | (s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.0= 42 ms | 2072616.369895 s | 2072616.369937 s | (s)RCU:9 | 0006 | 1.338 ms | 1 | 1.3= 38 ms | 2072616.369122 s | 2072616.370461 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 28.605% skipped events (25424 including 2617 raise, 22807 entry, = 0 exit) # perf kwork lat --time 2072620.333236, Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (s)RCU:9 | 0001 | 0.699 ms | 130 | 2.8= 62 ms | 2072620.639022 s | 2072620.641885 s | (s)RCU:9 | 0000 | 0.320 ms | 70 | 1.3= 65 ms | 2072620.344392 s | 2072620.345757 s | (s)NET_RX:3 | 0002 | 0.298 ms | 3 | 0.7= 62 ms | 2072624.174209 s | 2072624.174971 s | (s)RCU:9 | 0002 | 0.297 ms | 13 | 0.6= 87 ms | 2072622.126201 s | 2072622.126888 s | (s)RCU:9 | 0003 | 0.271 ms | 17 | 1.1= 27 ms | 2072620.617286 s | 2072620.618413 s | (s)TIMER:1 | 0000 | 0.166 ms | 8 | 0.3= 07 ms | 2072620.638399 s | 2072620.638706 s | (s)RCU:9 | 0004 | 0.146 ms | 3 | 0.2= 53 ms | 2072621.357331 s | 2072621.357584 s | (s)SCHED:7 | 0003 | 0.143 ms | 15 | 0.1= 97 ms | 2072625.973321 s | 2072625.973519 s | (s)TIMER:1 | 0003 | 0.137 ms | 16 | 1.0= 23 ms | 2072620.617286 s | 2072620.618309 s | (s)RCU:9 | 0005 | 0.133 ms | 1 | 0.1= 33 ms | 2072626.530482 s | 2072626.530615 s | (s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.7= 34 ms | 2072620.639022 s | 2072620.641756 s | (s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.2= 09 ms | 2072620.354356 s | 2072620.354564 s | (s)SCHED:7 | 0001 | 0.121 ms | 15 | 0.9= 86 ms | 2072620.392020 s | 2072620.393007 s | (s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.1= 72 ms | 2072620.333236 s | 2072620.333408 s | (s)SCHED:7 | 0000 | 0.115 ms | 269 | 0.9= 87 ms | 2072624.176905 s | 2072624.177892 s | (s)SCHED:7 | 0002 | 0.109 ms | 7 | 0.1= 40 ms | 2072625.966227 s | 2072625.966368 s | (s)RCU:9 | 0007 | 0.095 ms | 1526 | 1.3= 33 ms | 2072620.616224 s | 2072620.617557 s | (s)TIMER:1 | 0007 | 0.094 ms | 1546 | 1.2= 74 ms | 2072625.965379 s | 2072625.966653 s | (s)TIMER:1 | 0004 | 0.079 ms | 1 | 0.0= 79 ms | 2072621.357313 s | 2072621.357393 s | (s)TIMER:1 | 0002 | 0.072 ms | 7 | 0.0= 82 ms | 2072620.845190 s | 2072620.845272 s | (s)TIMER:1 | 0001 | 0.070 ms | 9 | 0.1= 49 ms | 2072620.360584 s | 2072620.360734 s | (s)SCHED:7 | 0007 | 0.068 ms | 1959 | 0.4= 73 ms | 2072621.357987 s | 2072621.358460 s | (s)SCHED:7 | 0005 | 0.038 ms | 1 | 0.0= 38 ms | 2072626.530536 s | 2072626.530573 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 17.800% skipped events (15821 including 1602 raise, 14219 entry, = 0 exit) Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 84e318eea832..e0ffd3291b3a 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -816,6 +816,20 @@ static struct kwork_class kwork_irq =3D { }; =20 static struct kwork_class kwork_softirq; +static int process_softirq_raise_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->raise_event) + return kwork->tp_handler->raise_event(kwork, &kwork_softirq, + evsel, sample, machine); + + return 0; +} + static int process_softirq_entry_event(struct perf_tool *tool, struct evsel *evsel, struct perf_sample *sample, @@ -845,7 +859,7 @@ static int process_softirq_exit_event(struct perf_tool = *tool, } =20 const struct evsel_str_handler softirq_tp_handlers[] =3D { - { "irq:softirq_raise", NULL, }, + { "irq:softirq_raise", process_softirq_raise_event, }, { "irq:softirq_entry", process_softirq_entry_event, }, { "irq:softirq_exit", process_softirq_exit_event, }, }; --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 00958C433EF for ; Mon, 13 Jun 2022 09:49:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241265AbiFMJtp (ORCPT ); Mon, 13 Jun 2022 05:49:45 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:46510 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241089AbiFMJs1 (ORCPT ); Mon, 13 Jun 2022 05:48:27 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 8799618B2C; Mon, 13 Jun 2022 02:48:24 -0700 (PDT) Received: from dggemv711-chm.china.huawei.com (unknown [172.30.72.54]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6Cz1M2dzjXfR; Mon, 13 Jun 2022 17:46:55 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv711-chm.china.huawei.com (10.1.198.66) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:08 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:08 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 12/13] perf kwork: Add workqueue latency support Date: Mon, 13 Jun 2022 17:46:04 +0800 Message-ID: <20220613094605.208401-13-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements workqueue latency function. test case: # perf kwork -k workqueue lat Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.3= 87 ms | 2072619.309237 s | 2072624.429624 s | (w)0xffff8883333e9040 | 0002 | 2.331 ms | 1 | 2.3= 31 ms | 2072618.029512 s | 2072618.031844 s | (w)0xffff888332fe9040 | 0000 | 0.724 ms | 5 | 1.6= 28 ms | 2072620.638985 s | 2072620.640613 s | (w)0xffff8883333ea180 | 0002 | 0.675 ms | 6 | 2.0= 07 ms | 2072624.174209 s | 2072624.176216 s | (w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.4= 00 ms | 2072625.965284 s | 2072625.965684 s | (w)0xffffffff82f7da00 | 0000 | 0.392 ms | 7 | 0.8= 22 ms | 2072621.627843 s | 2072621.628665 s | (w)0xffff8881035a83d8 | 0000 | 0.352 ms | 3 | 0.8= 27 ms | 2072620.650451 s | 2072620.651278 s | (w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.2= 28 ms | 2072620.504051 s | 2072620.505279 s | (w)0xffff8881035a81e8 | 0004 | 0.285 ms | 1 | 0.2= 85 ms | 2072621.357437 s | 2072621.357722 s | (w)0xffff888102fc14a0 | 0002 | 0.279 ms | 5 | 0.3= 19 ms | 2072618.029425 s | 2072618.029744 s | (w)0xffff8883335e9040 | 0003 | 0.271 ms | 2 | 0.2= 93 ms | 2072618.917354 s | 2072618.917647 s | (w)0xffffffff8305ca48 | 0003 | 0.268 ms | 2 | 0.2= 92 ms | 2072618.917407 s | 2072618.917699 s | (w)0xffffffff8305c990 | 0003 | 0.256 ms | 1 | 0.2= 56 ms | 2072625.973445 s | 2072625.973701 s | (w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.2= 54 ms | 2072626.173289 s | 2072626.173542 s | (w)0xffff888332fea180 | 0000 | 0.252 ms | 346 | 2.2= 37 ms | 2072620.339623 s | 2072620.341860 s | (w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.2= 34 ms | 2072625.965354 s | 2072625.965588 s | (w)0xffff888100e65c80 | 0000 | 0.217 ms | 10 | 0.7= 05 ms | 2072620.339040 s | 2072620.339745 s | (w)0xffff888333de9040 | 0007 | 0.179 ms | 8 | 0.3= 74 ms | 2072619.565271 s | 2072619.565645 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.024% skipped events (21 including 11 raise, 10 entry, 0 exit) # perf kwork -k workqueue lat -s freq,avg Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (w)0xffff888332fea180 | 0000 | 0.252 ms | 346 | 2.2= 37 ms | 2072620.339623 s | 2072620.341860 s | (w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.2= 28 ms | 2072620.504051 s | 2072620.505279 s | (w)0xffff888100e65c80 | 0000 | 0.217 ms | 10 | 0.7= 05 ms | 2072620.339040 s | 2072620.339745 s | (w)0xffff888333de9040 | 0007 | 0.179 ms | 8 | 0.3= 74 ms | 2072619.565271 s | 2072619.565645 s | (w)0xffffffff82f7da00 | 0000 | 0.392 ms | 7 | 0.8= 22 ms | 2072621.627843 s | 2072621.628665 s | (w)0xffff8883333ea180 | 0002 | 0.675 ms | 6 | 2.0= 07 ms | 2072624.174209 s | 2072624.176216 s | (w)0xffff888332fe9040 | 0000 | 0.724 ms | 5 | 1.6= 28 ms | 2072620.638985 s | 2072620.640613 s | (w)0xffff888102fc14a0 | 0002 | 0.279 ms | 5 | 0.3= 19 ms | 2072618.029425 s | 2072618.029744 s | (w)0xffff8881035a83d8 | 0000 | 0.352 ms | 3 | 0.8= 27 ms | 2072620.650451 s | 2072620.651278 s | (w)0xffff8883335e9040 | 0003 | 0.271 ms | 2 | 0.2= 93 ms | 2072618.917354 s | 2072618.917647 s | (w)0xffffffff8305ca48 | 0003 | 0.268 ms | 2 | 0.2= 92 ms | 2072618.917407 s | 2072618.917699 s | (w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.2= 34 ms | 2072625.965354 s | 2072625.965588 s | (w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.3= 87 ms | 2072619.309237 s | 2072624.429624 s | (w)0xffff8883333e9040 | 0002 | 2.331 ms | 1 | 2.3= 31 ms | 2072618.029512 s | 2072618.031844 s | (w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.4= 00 ms | 2072625.965284 s | 2072625.965684 s | (w)0xffff8881035a81e8 | 0004 | 0.285 ms | 1 | 0.2= 85 ms | 2072621.357437 s | 2072621.357722 s | (w)0xffffffff8305c990 | 0003 | 0.256 ms | 1 | 0.2= 56 ms | 2072625.973445 s | 2072625.973701 s | (w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.2= 54 ms | 2072626.173289 s | 2072626.173542 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.024% skipped events (21 including 11 raise, 10 entry, 0 exit) # perf kwork -k workqueue lat -C 1 Kwork Name | Cpu | Avg delay | Frequency | Max dela= y | Max delay start | Max delay end | ------------------------------------------------------------------------= --------------------------------------------------- (w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.3= 87 ms | 2072619.309237 s | 2072624.429624 s | (w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.4= 00 ms | 2072625.965284 s | 2072625.965684 s | (w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.2= 28 ms | 2072620.504051 s | 2072620.505279 s | (w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.2= 54 ms | 2072626.173289 s | 2072626.173542 s | (w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.2= 34 ms | 2072625.965354 s | 2072625.965588 s | ------------------------------------------------------------------------= --------------------------------------------------- INFO: 0.006% skipped events (5 including 3 raise, 2 entry, 0 exit) Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index e0ffd3291b3a..7e3da243ccd8 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -935,6 +935,20 @@ static struct kwork_class kwork_softirq =3D { }; =20 static struct kwork_class kwork_workqueue; +static int process_workqueue_activate_work_event(struct perf_tool *tool, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct perf_kwork *kwork =3D container_of(tool, struct perf_kwork, tool); + + if (kwork->tp_handler->raise_event) + return kwork->tp_handler->raise_event(kwork, &kwork_workqueue, + evsel, sample, machine); + + return 0; +} + static int process_workqueue_execute_start_event(struct perf_tool *tool, struct evsel *evsel, struct perf_sample *sample, @@ -964,7 +978,7 @@ static int process_workqueue_execute_end_event(struct p= erf_tool *tool, } =20 const struct evsel_str_handler workqueue_tp_handlers[] =3D { - { "workqueue:workqueue_activate_work", NULL, }, + { "workqueue:workqueue_activate_work", process_workqueue_activate_work_ev= ent, }, { "workqueue:workqueue_execute_start", process_workqueue_execute_start_ev= ent, }, { "workqueue:workqueue_execute_end", process_workqueue_execute_end_even= t, }, }; --=20 2.30.GIT From nobody Wed Apr 29 09:34:37 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id B1A59C433EF for ; Mon, 13 Jun 2022 09:50:18 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241390AbiFMJuR (ORCPT ); Mon, 13 Jun 2022 05:50:17 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47992 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241148AbiFMJtx (ORCPT ); Mon, 13 Jun 2022 05:49:53 -0400 Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [45.249.212.188]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5895D1ADAC; Mon, 13 Jun 2022 02:49:22 -0700 (PDT) Received: from dggemv704-chm.china.huawei.com (unknown [172.30.72.56]) by szxga02-in.huawei.com (SkyGuard) with ESMTP id 4LM6F471YdzjXg7; Mon, 13 Jun 2022 17:47:52 +0800 (CST) Received: from kwepemm600003.china.huawei.com (7.193.23.202) by dggemv704-chm.china.huawei.com (10.3.19.47) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:09 +0800 Received: from ubuntu1804.huawei.com (10.67.174.61) by kwepemm600003.china.huawei.com (7.193.23.202) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.24; Mon, 13 Jun 2022 17:48:08 +0800 From: Yang Jihong To: , , , , , , , , CC: Subject: [RFC 13/13] perf kwork: Implement perf kwork timehist Date: Mon, 13 Jun 2022 17:46:05 +0800 Message-ID: <20220613094605.208401-14-yangjihong1@huawei.com> X-Mailer: git-send-email 2.30.GIT In-Reply-To: <20220613094605.208401-1-yangjihong1@huawei.com> References: <20220613094605.208401-1-yangjihong1@huawei.com> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-Originating-IP: [10.67.174.61] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To kwepemm600003.china.huawei.com (7.193.23.202) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" Implements framework of perf kwork timehist, to provide an analysis of kern= el work events. test case: # perf kwork tim Runtime start Runtime end Cpu Kwork name = Runtime Delaytime (TYPE)NAME:NUM = (msec) (msec) ----------------- ----------------- ------ ------------------------- = ---------- ---------- 2072616.355256 2072616.355295 [0000] (s)SCHED:7 = 0.040 0.062 2072616.356794 2072616.356865 [0001] (s)RCU:9 = 0.071 0.083 2072616.358362 2072616.358406 [0002] (s)RCU:9 = 0.044 0.108 2072616.360179 2072616.360211 [0000] (s)SCHED:7 = 0.032 0.032 2072616.360608 2072616.360729 [0003] (s)TIMER:1 = 0.120 0.311 2072616.360753 2072616.360803 [0003] (s)SCHED:7 = 0.050 0.199 2072616.362232 2072616.362295 [0001] (s)RCU:9 = 0.063 0.071 2072616.363177 2072616.363229 [0000] (s)SCHED:7 = 0.052 0.030 2072616.365407 2072616.365502 [0003] (s)TIMER:1 = 0.096 0.106 2072616.365527 2072616.365595 [0003] (s)SCHED:7 = 0.068 0.162 2072616.365616 2072616.365670 [0003] (s)RCU:9 = 0.053 0.290 2072616.366171 2072616.366211 [0000] (s)SCHED:7 = 0.040 0.029 2072616.366372 2072616.366435 [0001] (s)SCHED:7 = 0.063 0.053 2072616.369351 2072616.369434 [0003] (s)TIMER:1 = 0.083 0.060 2072616.369937 2072616.369998 [0005] (s)SCHED:7 = 0.061 0.042 2072616.370391 2072616.370440 [0006] (s)SCHED:7 = 0.049 0.081 2072616.370461 2072616.370510 [0006] (s)RCU:9 = 0.049 1.338 2072616.370020 2072616.372415 [0005] (s)RCU:9 = 2.395 1.757 2072616.372624 2072616.372689 [0006] (s)SCHED:7 = 0.065 0.047 2072616.373171 2072616.373226 [0000] (s)SCHED:7 = 0.055 0.029 2072616.373589 2072616.373621 [0003] (s)TIMER:1 = 0.032 0.375 2072616.375176 2072616.375353 [0000] (s)SCHED:7 = 0.177 0.031 2072616.375539 2072616.375587 [0001] (s)RCU:9 = 0.048 0.082 2072616.377183 2072616.377215 [0000] (s)SCHED:7 = 0.032 0.032 2072616.379190 2072616.379222 [0000] (s)SCHED:7 = 0.033 0.032 2072616.379475 2072616.379579 [0007] (s)RCU:9 = 0.105 0.288 2072616.379832 2072616.379923 [0000] virtio0-requests:25 = 0.090 2072616.380339 2072616.380392 [0007] (s)SCHED:7 = 0.054 0.064 2072616.382425 2072616.382486 [0007] (s)RCU:9 = 0.061 1.181 2072616.383339 2072616.383387 [0002] (s)RCU:9 = 0.047 1.222 2072616.384265 2072616.384314 [0003] (s)SCHED:7 = 0.050 0.082 2072616.384824 2072616.384875 [0007] (s)RCU:9 = 0.051 1.506 2072616.385319 2072616.385361 [0002] (s)RCU:9 = 0.042 1.088 2072616.386321 2072616.386413 [0003] (s)TIMER:1 = 0.091 0.107 2072616.386438 2072616.386515 [0003] (s)SCHED:7 = 0.078 0.159 2072616.386537 2072616.386575 [0003] (s)RCU:9 = 0.038 0.298 2072616.386068 2072616.387057 [0000] virtio0-requests:25 = 0.989 2072616.387057 2072616.387057 [0000] (s)SCHED:7 = 0.000 0.989 2072616.387057 2072616.387057 [0000] (s)SCHED:7 = 0.000 0.989 2072616.387726 2072616.387781 [0002] (s)RCU:9 = 0.055 1.512 2072616.387025 2072616.388331 [0007] (s)SCHED:7 = 1.306 0.052 2072616.388358 2072616.388404 [0007] (s)RCU:9 = 0.046 0.409 2072616.388527 2072616.388573 [0007] (s)SCHED:7 = 0.046 0.264 2072616.388595 2072616.388619 [0007] (s)RCU:9 = 0.024 2.890 2072616.390267 2072616.390353 [0003] (s)TIMER:1 = 0.086 0.066 2072616.390949 2072616.391060 [0007] (s)RCU:9 = 0.111 1.711 2072616.391290 2072616.391340 [0002] (s)RCU:9 = 0.050 1.125 2072616.392304 2072616.392353 [0007] (s)RCU:9 = 0.049 0.456 ... Signed-off-by: Yang Jihong --- tools/perf/builtin-kwork.c | 253 +++++++++++++++++++++++++++++++++++++ 1 file changed, 253 insertions(+) diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c index 7e3da243ccd8..0ab34e3480fe 100644 --- a/tools/perf/builtin-kwork.c +++ b/tools/perf/builtin-kwork.c @@ -41,6 +41,7 @@ enum kwork_trace_type { enum kwork_report_type { KWORK_REPORT_RUNTIME, KWORK_REPORT_LATENCY, + KWORK_REPORT_TIMEHIST, }; =20 /* @@ -213,10 +214,12 @@ struct perf_kwork { #define PRINT_TIMESTAMP_WIDTH 17 #define PRINT_KWORK_NAME_WIDTH 25 #define RPINT_DECIMAL_WIDTH 3 +#define PRINT_BRACKETPAIR_WIDTH 2 #define PRINT_TIME_UNIT_SEC_WIDTH 2 #define PRINT_TIME_UNIT_MESC_WIDTH 3 #define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_= MESC_WIDTH) #define PRINT_LATENCY_HEADER_WIDTH (PRINT_LATENCY_WIDTH + PRINT_TIME_UNIT_= MESC_WIDTH) +#define PRINT_TIMEHIST_CPU_WIDTH (PRINT_CPU_WIDTH + PRINT_BRACKETPAIR_WIDT= H) #define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_U= NIT_SEC_WIDTH) =20 struct sort_dimension { @@ -746,6 +749,181 @@ static int latency_entry_event(struct perf_kwork *kwo= rk, return 0; } =20 +static void timehist_save_callchain(struct perf_kwork *kwork, + struct perf_sample *sample, + struct evsel *evsel, + struct machine *machine) +{ + struct symbol *sym; + struct thread *thread; + struct callchain_cursor_node *node; + struct callchain_cursor *cursor =3D &callchain_cursor; + + if (!kwork->show_callchain || sample->callchain =3D=3D NULL) + return; + + /* want main thread for process - has maps */ + thread =3D machine__findnew_thread(machine, sample->pid, sample->pid); + if (thread =3D=3D NULL) { + pr_debug("Failed to get thread for pid %d\n", sample->pid); + return; + } + + if (thread__resolve_callchain(thread, cursor, evsel, sample, + NULL, NULL, kwork->max_stack + 2) !=3D 0) { + pr_debug("Failed to resolve callchain, skipping\n"); + goto out_put; + } + + callchain_cursor_commit(cursor); + + while (true) { + node =3D callchain_cursor_current(cursor); + if (node =3D=3D NULL) + break; + + sym =3D node->ms.sym; + if (sym) { + if (!strcmp(sym->name, "__softirqentry_text_start")) + sym->ignore =3D 1; + } + + callchain_cursor_advance(cursor); + } + +out_put: + thread__put(thread); +} + +static void timehist_print_event(struct perf_kwork *kwork, + struct kwork_cluster *cluster, + struct kwork_atom *atom, + struct perf_sample *sample, + struct addr_location *al) +{ + char entrytime[32], exittime[32]; + char kwork_name[PRINT_KWORK_NAME_WIDTH]; + + /* + * runtime start + */ + timestamp__scnprintf_usec(atom->time, + entrytime, sizeof(entrytime)); + printf(" %*s ", PRINT_TIMESTAMP_WIDTH, entrytime); + + /* + * runtime end + */ + timestamp__scnprintf_usec(sample->time, + exittime, sizeof(exittime)); + printf(" %*s ", PRINT_TIMESTAMP_WIDTH, exittime); + + /* + * cpu + */ + printf(" [%0*d] ", PRINT_CPU_WIDTH, cluster->cpu); + + /* + * kwork name + */ + if (cluster->class && cluster->class->cluster_name) { + cluster->class->cluster_name(cluster, kwork_name, + PRINT_KWORK_NAME_WIDTH); + printf(" %-*s ", PRINT_KWORK_NAME_WIDTH, kwork_name); + } else + printf(" %-*s ", PRINT_KWORK_NAME_WIDTH, ""); + + /* + *runtime + */ + printf(" %*.*f ", + PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH, + (double)(sample->time - atom->time) / NSEC_PER_MSEC); + + /* + * delaytime + */ + if (atom->prev !=3D NULL) + printf(" %*.*f ", PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH, + (double)(atom->time - atom->prev->time) / NSEC_PER_MSEC); + else + printf(" %*s ", PRINT_LATENCY_WIDTH, " "); + + /* + * callchain + */ + if (kwork->show_callchain) { + printf(" "); + sample__fprintf_sym(sample, al, 0, + EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE | + EVSEL__PRINT_CALLCHAIN_ARROW | + EVSEL__PRINT_SKIP_IGNORED, + &callchain_cursor, symbol_conf.bt_stop_list, + stdout); + } + + printf("\n"); +} + +static int timehist_raise_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine __maybe_unused) +{ + return cluster_push_atom(kwork, class, KWORK_TRACE_RAISE, + KWORK_TRACE_MAX, evsel, sample, NULL); +} + +static int timehist_entry_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + int ret; + struct kwork_cluster *cluster =3D NULL; + + ret =3D cluster_push_atom(kwork, class, KWORK_TRACE_ENTRY, + KWORK_TRACE_RAISE, evsel, sample, &cluster); + if (ret) + return ret; + + if (cluster !=3D NULL) + timehist_save_callchain(kwork, sample, evsel, machine); + + return 0; +} + +static int timehist_exit_event(struct perf_kwork *kwork, + struct kwork_class *class, + struct evsel *evsel, + struct perf_sample *sample, + struct machine *machine) +{ + struct kwork_atom *atom =3D NULL; + struct kwork_cluster *cluster =3D NULL; + struct addr_location al; + + if (machine__resolve(machine, &al, sample) < 0) { + pr_debug("Problem processing event, skipping it\n"); + return -1; + } + + atom =3D cluster_pop_atom(kwork, class, KWORK_TRACE_EXIT, + KWORK_TRACE_ENTRY, evsel, sample, &cluster); + if (cluster =3D=3D NULL) + return -1; + + if (atom !=3D NULL) { + cluster->nr_atoms++; + timehist_print_event(kwork, cluster, atom, sample, &al); + atom_del(atom); + } + + return 0; +} + static struct kwork_class kwork_irq; static int process_irq_handler_entry_event(struct perf_tool *tool, struct evsel *evsel, @@ -1149,6 +1327,42 @@ static int report_print_header(struct perf_kwork *kw= ork) return ret; } =20 +static void timehist_print_header(void) +{ + /* + * header row + */ + printf(" %-*s %-*s %-*s %-*s %-*s %-*s\n", + PRINT_TIMESTAMP_WIDTH, "Runtime start", + PRINT_TIMESTAMP_WIDTH, "Runtime end", + PRINT_TIMEHIST_CPU_WIDTH, "Cpu", + PRINT_KWORK_NAME_WIDTH, "Kwork name", + PRINT_RUNTIME_WIDTH, "Runtime", + PRINT_RUNTIME_WIDTH, "Delaytime"); + + /* + * units row + */ + printf(" %-*s %-*s %-*s %-*s %-*s %-*s\n", + PRINT_TIMESTAMP_WIDTH, "", + PRINT_TIMESTAMP_WIDTH, "", + PRINT_TIMEHIST_CPU_WIDTH, "", + PRINT_KWORK_NAME_WIDTH, "(TYPE)NAME:NUM", + PRINT_RUNTIME_WIDTH, "(msec)", + PRINT_RUNTIME_WIDTH, "(msec)"); + + /* + * separator + */ + printf(" %.*s %.*s %.*s %.*s %.*s %.*s\n", + PRINT_TIMESTAMP_WIDTH, graph_dotted_line, + PRINT_TIMESTAMP_WIDTH, graph_dotted_line, + PRINT_TIMEHIST_CPU_WIDTH, graph_dotted_line, + PRINT_KWORK_NAME_WIDTH, graph_dotted_line, + PRINT_RUNTIME_WIDTH, graph_dotted_line, + PRINT_RUNTIME_WIDTH, graph_dotted_line); +} + static void print_summary(struct perf_kwork *kwork) { u64 time =3D kwork->timeend - kwork->timestart; @@ -1294,6 +1508,11 @@ static int perf_kwork__check_config(struct perf_kwor= k *kwork, .raise_event =3D latency_raise_event, .entry_event =3D latency_entry_event, }; + static struct trace_kwork_handler timehist_ops =3D { + .raise_event =3D timehist_raise_event, + .entry_event =3D timehist_entry_event, + .exit_event =3D timehist_exit_event, + }; =20 switch (kwork->report) { case KWORK_REPORT_RUNTIME: @@ -1302,6 +1521,9 @@ static int perf_kwork__check_config(struct perf_kwork= *kwork, case KWORK_REPORT_LATENCY: kwork->tp_handler =3D &latency_ops; break; + case KWORK_REPORT_TIMEHIST: + kwork->tp_handler =3D &timehist_ops; + break; default: pr_debug("Invalid report type %d\n", kwork->report); break; @@ -1364,6 +1586,9 @@ static int perf_kwork__read_events(struct perf_kwork = *kwork) if (perf_kwork__check_config(kwork, session) !=3D 0) goto out_delete; =20 + if (kwork->report =3D=3D KWORK_REPORT_TIMEHIST) + timehist_print_header(); + ret =3D perf_session__process_events(session); if (ret) { pr_debug("Failed to process events, error %d\n", ret); @@ -1379,6 +1604,28 @@ static int perf_kwork__read_events(struct perf_kwork= *kwork) return ret; } =20 +static int perf_kwork__timehist(struct perf_kwork *kwork) +{ + /* + * event handlers for timehist option + */ + kwork->tool.mmap =3D perf_event__process_mmap; + kwork->tool.mmap2 =3D perf_event__process_mmap2; + kwork->tool.comm =3D perf_event__process_comm; + kwork->tool.exit =3D perf_event__process_exit; + kwork->tool.fork =3D perf_event__process_fork; + kwork->tool.attr =3D perf_event__process_attr; + kwork->tool.tracing_data =3D perf_event__process_tracing_data; + kwork->tool.build_id =3D perf_event__process_build_id; + kwork->tool.ordered_events =3D true; + kwork->tool.ordering_requires_timestamps =3D true; + symbol_conf.use_callchain =3D kwork->show_callchain; + + setup_pager(); + + return perf_kwork__read_events(kwork); +} + static void process_skipped_events(struct perf_kwork *kwork, struct kwork_cluster *cluster) { @@ -1505,6 +1752,7 @@ static int perf_kwork__record(struct perf_kwork *kwor= k, =20 int cmd_kwork(int argc, const char **argv) { + int ret; static const char default_report_sort_order[] =3D "runtime, max, freq"; static const char default_latency_sort_order[] =3D "avg, max, freq"; static struct perf_kwork kwork =3D { @@ -1655,6 +1903,11 @@ int cmd_kwork(int argc, const char **argv) if (argc) usage_with_options(timehist_usage, timehist_options); } + ret =3D symbol__validate_sym_arguments(); + if (ret) + return ret; + kwork.report =3D KWORK_REPORT_TIMEHIST; + return perf_kwork__timehist(&kwork); } else usage_with_options(kwork_usage, kwork_options); =20 --=20 2.30.GIT