* [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts
@ 2021-02-25 1:30 Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 1/2] " Bixuan Cui
` (2 more replies)
0 siblings, 3 replies; 4+ messages in thread
From: Bixuan Cui @ 2021-02-25 1:30 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel
Cc: hagen, john.wanghui, abudankov, yz.yuzhou
When the hardware interrupt processing function is executed, the interrupt and
preemption of current cpu are disabled. As a result, the task is suspended.
The execution of the hardware processing function takes a long time
(for example 5 ms), will affect the task scheduling performance.
This patches provides the 'perf irq' command to trace and calculate the time
consumed of the hardware irq function.
[verse]
'perf irq' [<options>] {record|report}
DESCRIPTION
-----------
There are several variants of 'perf irq':
'perf irq record <command>' to record the irq handler events
of an arbitrary workload.
'perf irq report' to calculate the time consumed by each
hardware interrupt processing function.
Example usage:
perf irq record -- sleep 1
perf irq report
By default it shows the individual irq events, including the irq name,
cpu(execute the hardware interrupt processing function), time consumed,
entry time and exit time for the each hardware irq:
-------------------------------------------------------------------------------------------------------------------------------------------
Irq name | CPU | Time consume us | Handler entry time | Handler exit time
-------------------------------------------------------------------------------------------------------------------------------------------
enp2s0f2-tx-0 | [0006] | 0.000001 s | 6631263.313329 s | 6631263.313330 s
megasas | [0013] | 0.000003 s | 6631263.209564 s | 6631263.209567 s
acpi | [0016] | 0.000018 s | 6631263.085787 s | 6631263.085805 s
And:
perf irq --cpu 78 record -- sleep 1
perf irq --cpu 78 report
-------------------------------------------------------------------------------------------------------------------------------------------
Irq name | CPU | Time consume us | Handler entry time | Handler exit time
-------------------------------------------------------------------------------------------------------------------------------------------
enp134s0f0-TxRx-2 | [0078] | 0.000005 s | 693757.533189 s | 693757.533194 s
Changes from v5:
* Resolve conflicts by the latest commit.
Changes from v4:
* Keep pairs of irq entry/exit per cpu;
* Add NUL-termination to the end of irq->irq_name when strncpy is used;
* Delete some unused declarations and parameters;
Changes from v3:
* Delete 'perf irq script' because its function can be implemented using
'perf script';
* Add --cpu option for 'perf irq';
Changes from v2:
* Delete "-m", "1024" in __cmd_record();
* Change 'perf irq timeconsume <options>' to 'perf irq report <options>';
* Fix a error for tools/perf/Documentation/perf-irq.txt;
Bixuan Cui (2):
perf tools: add 'perf irq' to measure the hardware interrupts
perf tools: Add documentation for 'perf irq' command
tools/perf/Build | 1 +
tools/perf/Documentation/perf-irq.txt | 47 +++++
tools/perf/builtin-irq.c | 260 ++++++++++++++++++++++++++
tools/perf/builtin.h | 1 +
tools/perf/command-list.txt | 1 +
tools/perf/perf.c | 1 +
6 files changed, 311 insertions(+)
create mode 100644 tools/perf/Documentation/perf-irq.txt
create mode 100644 tools/perf/builtin-irq.c
--
2.17.1
^ permalink raw reply [flat|nested] 4+ messages in thread
* [PATCH v5 1/2] perf tools: add 'perf irq' to measure the hardware interrupts
2021-02-25 1:30 [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Bixuan Cui
@ 2021-02-25 1:30 ` Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 2/2] perf tools: Add documentation for 'perf irq' command Bixuan Cui
2021-02-25 16:19 ` [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Jiri Olsa
2 siblings, 0 replies; 4+ messages in thread
From: Bixuan Cui @ 2021-02-25 1:30 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel
Cc: hagen, john.wanghui, abudankov, yz.yuzhou
Add 'perf irq' to trace/measure the hardware interrupts.
Now three functions are provided:
1. 'perf irq record <command>' to record the irq handler events.
2. 'perf irq script' to see a detailed trace of the workload that
was recorded.
3. 'perf irq report' to calculate the time consumed by each
hardware interrupt processing function.
Signed-off-by: Bixuan Cui <cuibixuan@huawei.com>
---
tools/perf/Build | 1 +
tools/perf/builtin-irq.c | 260 +++++++++++++++++++++++++++++++++++++++
tools/perf/builtin.h | 1 +
tools/perf/perf.c | 1 +
4 files changed, 263 insertions(+)
create mode 100644 tools/perf/builtin-irq.c
diff --git a/tools/perf/Build b/tools/perf/Build
index db61dbe2b543..ad8e3c19bb03 100644
--- a/tools/perf/Build
+++ b/tools/perf/Build
@@ -25,6 +25,7 @@ perf-y += builtin-data.o
perf-y += builtin-version.o
perf-y += builtin-c2c.o
perf-y += builtin-daemon.o
+perf-y += builtin-irq.o
perf-$(CONFIG_TRACE) += builtin-trace.o
perf-$(CONFIG_LIBELF) += builtin-probe.o
diff --git a/tools/perf/builtin-irq.c b/tools/perf/builtin-irq.c
new file mode 100644
index 000000000000..bf1e6efd85f8
--- /dev/null
+++ b/tools/perf/builtin-irq.c
@@ -0,0 +1,260 @@
+// SPDX-License-Identifier: GPL-2.0
+#include "builtin.h"
+#include "perf.h"
+#include "perf-sys.h"
+
+#include "util/cpumap.h"
+#include "util/evlist.h"
+#include "util/evsel.h"
+#include "util/evsel_fprintf.h"
+#include "util/symbol.h"
+#include "util/thread.h"
+#include "util/header.h"
+#include "util/session.h"
+#include "util/tool.h"
+#include "util/cloexec.h"
+#include "util/thread_map.h"
+#include "util/color.h"
+#include "util/stat.h"
+#include "util/string2.h"
+#include "util/callchain.h"
+#include "util/time-utils.h"
+
+#include <subcmd/pager.h>
+#include <subcmd/parse-options.h>
+#include "util/trace-event.h"
+
+#include "util/debug.h"
+#include "util/event.h"
+
+#include <linux/kernel.h>
+#include <linux/log2.h>
+#include <linux/zalloc.h>
+#include <sys/prctl.h>
+#include <sys/resource.h>
+#include <inttypes.h>
+
+#include <errno.h>
+#include <semaphore.h>
+#include <pthread.h>
+#include <math.h>
+#include <api/fs/fs.h>
+#include <perf/cpumap.h>
+#include <linux/time64.h>
+#include <linux/err.h>
+
+#include <linux/ctype.h>
+
+#define IRQ_NAME_LEN 24
+#define MAX_CPUS 4096
+
+static const char *cpu_list;
+static DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS);
+
+struct perf_irq {
+ struct perf_tool tool;
+ bool force;
+
+ char irq_name[MAX_CPUS][IRQ_NAME_LEN];
+ u32 irq_num[MAX_CPUS];
+ u64 irq_entry_time[MAX_CPUS];
+ u64 irq_exit_time[MAX_CPUS];
+};
+
+typedef int (*irq_handler)(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample);
+
+static int perf_report_process_sample(struct perf_tool *tool,
+ union perf_event *event __maybe_unused,
+ struct perf_sample *sample,
+ struct evsel *evsel,
+ struct machine *machine __maybe_unused)
+{
+ int err = 0;
+
+ if (evsel->handler != NULL) {
+ irq_handler f = evsel->handler;
+ err = f(tool, evsel, sample);
+ }
+
+ return err;
+}
+
+static void output_report(struct perf_irq *irq, u32 cpu)
+{
+ int ret, i;
+ char irq_entry_time[30], irq_exit_time[30], irq_diff[30];
+
+ timestamp__scnprintf_usec(irq->irq_entry_time[cpu],
+ irq_entry_time, sizeof(irq_entry_time));
+ timestamp__scnprintf_usec(irq->irq_exit_time[cpu],
+ irq_exit_time, sizeof(irq_exit_time));
+ timestamp__scnprintf_usec(irq->irq_exit_time[cpu] - irq->irq_entry_time[cpu],
+ irq_diff, sizeof(irq_diff));
+
+ ret = printf(" %s ", irq->irq_name[cpu]);
+ for (i = 0; i < IRQ_NAME_LEN - ret; i++)
+ printf(" ");
+
+ printf("| [%04d] | %13s s | %16s s | %16s s\n",
+ cpu, irq_diff, irq_entry_time, irq_exit_time);
+}
+
+static int report_irq_handler_entry_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample)
+{
+ int this_cpu = sample->cpu, err = 0;
+ struct perf_irq *irq = container_of(tool, struct perf_irq, tool);
+ const char *name = evsel__strval(evsel, sample, "name");
+
+ irq->irq_entry_time[this_cpu] = sample->time;
+
+ strncpy(irq->irq_name[this_cpu], name, IRQ_NAME_LEN - 1);
+ irq->irq_name[this_cpu][IRQ_NAME_LEN - 1] = '\0';
+
+ return err;
+}
+
+static int report_irq_handler_exit_event(struct perf_tool *tool,
+ struct evsel *evsel __maybe_unused,
+ struct perf_sample *sample)
+{
+ int this_cpu = sample->cpu, err = 0;
+ struct perf_irq *irq = container_of(tool, struct perf_irq, tool);
+
+ irq->irq_exit_time[this_cpu] = sample->time;
+
+ if (cpu_list && !test_bit(this_cpu, cpu_bitmap))
+ return err;
+
+ output_report(irq, this_cpu);
+
+ return err;
+}
+
+static int perf_irq__read_events(struct perf_irq *irq)
+{
+ struct evsel_str_handler handlers[] = {
+ { "irq:irq_handler_entry", report_irq_handler_entry_event, },
+ { "irq:irq_handler_exit", report_irq_handler_exit_event, },
+ };
+ struct perf_session *session;
+ struct perf_data data = {
+ .path = input_name,
+ .mode = PERF_DATA_MODE_READ,
+ .force = irq->force,
+ };
+ int rc = -1;
+
+ irq->tool.sample = perf_report_process_sample;
+
+ session = perf_session__new(&data, false, &irq->tool);
+ if (IS_ERR(session)) {
+ pr_debug("Error creating perf session");
+ return PTR_ERR(session);
+ }
+
+ if (cpu_list) {
+ rc = perf_session__cpu_bitmap(session, cpu_list, cpu_bitmap);
+ if (rc < 0)
+ goto out_delete;
+ }
+
+ if (perf_session__set_tracepoints_handlers(session, handlers))
+ goto out_delete;
+
+ rc = perf_session__process_events(session);
+ if (rc) {
+ pr_err("Failed to process events, error %d", rc);
+ goto out_delete;
+ }
+
+out_delete:
+ perf_session__delete(session);
+ return rc;
+}
+
+static int irq_report(struct perf_irq *irq)
+{
+ printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n");
+ printf(" Irq name | CPU | Time consume us | Handler entry time | Handler exit time \n");
+ printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n");
+
+ if (perf_irq__read_events(irq))
+ return -1;
+
+ return 0;
+}
+
+static int __cmd_record(int argc, const char **argv)
+{
+ unsigned int rec_argc, i, j;
+ const char **rec_argv;
+ const char * const record_args[] = {
+ "record",
+ "-a",
+ "-R",
+ "-c", "1",
+ "-e", "irq:irq_handler_entry",
+ "-e", "irq:irq_handler_exit",
+ };
+
+ rec_argc = ARRAY_SIZE(record_args) + argc - 1;
+ rec_argv = calloc(rec_argc + 1, sizeof(char *));
+ if (rec_argv == NULL)
+ return -ENOMEM;
+
+ for (i = 0; i < ARRAY_SIZE(record_args); i++)
+ rec_argv[i] = strdup(record_args[i]);
+
+ for (j = 1; j < (unsigned int)argc; j++, i++)
+ rec_argv[i] = argv[j];
+
+ BUG_ON(i != rec_argc);
+
+ return cmd_record(i, rec_argv);
+}
+
+int cmd_irq(int argc, const char **argv)
+{
+ struct perf_irq irq = {
+ .force = false,
+ };
+
+ const struct option irq_options[] = {
+ OPT_STRING('C', "cpu", &cpu_list, "cpu", "list of cpus to profile"),
+ OPT_END()
+ };
+ const struct option report_options[] = {
+ OPT_PARENT(irq_options)
+ };
+
+ const char * const report_usage[] = {
+ "perf irq report [<options>]",
+ NULL
+ };
+ const char *const irq_subcommands[] = { "record", "report", NULL };
+ const char *irq_usage[] = {
+ NULL,
+ NULL
+ };
+
+ argc = parse_options_subcommand(argc, argv, irq_options, irq_subcommands,
+ irq_usage, PARSE_OPT_STOP_AT_NON_OPTION);
+ if (!argc)
+ usage_with_options(irq_usage, irq_options);
+
+ if (!strncmp(argv[0], "record", 6)) {
+ return __cmd_record(argc, argv);
+ } else if (!strncmp(argv[0], "report", 6)) {
+ if (argc > 1) {
+ argc = parse_options(argc, argv, report_options, report_usage, 0);
+ if (argc)
+ usage_with_options(report_usage, report_options);
+ }
+ return irq_report(&irq);
+ }
+ return 0;
+}
diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h
index 7303e80a639c..fab1483ad98d 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_irq(int argc, const char **argv);
int find_scripts(char **scripts_array, char **scripts_path_array, int num,
int pathlen);
diff --git a/tools/perf/perf.c b/tools/perf/perf.c
index 20cb91ef06ff..347d2f55e59a 100644
--- a/tools/perf/perf.c
+++ b/tools/perf/perf.c
@@ -89,6 +89,7 @@ static struct cmd_struct commands[] = {
{ "data", cmd_data, 0 },
{ "ftrace", cmd_ftrace, 0 },
{ "daemon", cmd_daemon, 0 },
+ { "irq", cmd_irq, 0 },
};
struct pager_config {
--
2.17.1
^ permalink raw reply related [flat|nested] 4+ messages in thread
* [PATCH v5 2/2] perf tools: Add documentation for 'perf irq' command
2021-02-25 1:30 [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 1/2] " Bixuan Cui
@ 2021-02-25 1:30 ` Bixuan Cui
2021-02-25 16:19 ` [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Jiri Olsa
2 siblings, 0 replies; 4+ messages in thread
From: Bixuan Cui @ 2021-02-25 1:30 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel
Cc: hagen, john.wanghui, abudankov, yz.yuzhou
Add documentation for 'perf irq' command.
Signed-off-by: Bixuan Cui <cuibixuan@huawei.com>
---
tools/perf/Documentation/perf-irq.txt | 47 +++++++++++++++++++++++++++
tools/perf/command-list.txt | 1 +
2 files changed, 48 insertions(+)
create mode 100644 tools/perf/Documentation/perf-irq.txt
diff --git a/tools/perf/Documentation/perf-irq.txt b/tools/perf/Documentation/perf-irq.txt
new file mode 100644
index 000000000000..8f1c466c3d6b
--- /dev/null
+++ b/tools/perf/Documentation/perf-irq.txt
@@ -0,0 +1,47 @@
+perf-irq(1)
+=============
+
+NAME
+----
+perf-irq - Tool to trace/measure hardware interrupts
+
+SYNOPSIS
+--------
+[verse]
+'perf irq' [<options>] {record|report}
+
+DESCRIPTION
+-----------
+There are several variants of 'perf irq':
+
+ 'perf irq record <command>' to record the irq handler events
+ of an arbitrary workload.
+
+ 'perf irq report' to calculate the time consumed by each
+ hardware interrupt processing function.
+
+ Example usage:
+ perf irq record -- sleep 1
+ perf irq report
+
+ By default it shows the individual irq events, including the irq name,
+ cpu(execute the hardware interrupt processing function), time consumed,
+ entry time and exit time for the each hardware irq:
+
+ -------------------------------------------------------------------------------------------------------------------------------------------
+ Irq name | CPU | Time consume us | Handler entry time | Handler exit time
+ -------------------------------------------------------------------------------------------------------------------------------------------
+ enp2s0f2-tx-0 | [0006] | 0.000001 s | 6631263.313329 s | 6631263.313330 s
+ megasas | [0013] | 0.000003 s | 6631263.209564 s | 6631263.209567 s
+ acpi | [0016] | 0.000018 s | 6631263.085787 s | 6631263.085805 s
+
+
+OPTIONS for 'perf irq'
+----------------------------
+
+--cpus::
+ Show just entries with activities for the given CPUs.
+
+SEE ALSO
+--------
+linkperf:perf-record[1]
diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt
index 825a12e8d694..bf56178d2895 100644
--- a/tools/perf/command-list.txt
+++ b/tools/perf/command-list.txt
@@ -26,6 +26,7 @@ perf-report mainporcelain common
perf-sched mainporcelain common
perf-script mainporcelain common
perf-stat mainporcelain common
+perf-irq mainporcelain common
perf-test mainporcelain common
perf-timechart mainporcelain common
perf-top mainporcelain common
--
2.17.1
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts
2021-02-25 1:30 [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 1/2] " Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 2/2] perf tools: Add documentation for 'perf irq' command Bixuan Cui
@ 2021-02-25 16:19 ` Jiri Olsa
2 siblings, 0 replies; 4+ messages in thread
From: Jiri Olsa @ 2021-02-25 16:19 UTC (permalink / raw)
To: Bixuan Cui
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, namhyung,
linux-kernel, hagen, john.wanghui, abudankov, yz.yuzhou
On Thu, Feb 25, 2021 at 09:30:14AM +0800, Bixuan Cui wrote:
> When the hardware interrupt processing function is executed, the interrupt and
> preemption of current cpu are disabled. As a result, the task is suspended.
> The execution of the hardware processing function takes a long time
> (for example 5 ms), will affect the task scheduling performance.
>
> This patches provides the 'perf irq' command to trace and calculate the time
> consumed of the hardware irq function.
>
> [verse]
> 'perf irq' [<options>] {record|report}
>
> DESCRIPTION
> -----------
> There are several variants of 'perf irq':
>
> 'perf irq record <command>' to record the irq handler events
> of an arbitrary workload.
>
> 'perf irq report' to calculate the time consumed by each
> hardware interrupt processing function.
>
> Example usage:
> perf irq record -- sleep 1
> perf irq report
>
> By default it shows the individual irq events, including the irq name,
> cpu(execute the hardware interrupt processing function), time consumed,
> entry time and exit time for the each hardware irq:
>
> -------------------------------------------------------------------------------------------------------------------------------------------
> Irq name | CPU | Time consume us | Handler entry time | Handler exit time
> -------------------------------------------------------------------------------------------------------------------------------------------
> enp2s0f2-tx-0 | [0006] | 0.000001 s | 6631263.313329 s | 6631263.313330 s
> megasas | [0013] | 0.000003 s | 6631263.209564 s | 6631263.209567 s
> acpi | [0016] | 0.000018 s | 6631263.085787 s | 6631263.085805 s
>
> And:
> perf irq --cpu 78 record -- sleep 1
> perf irq --cpu 78 report
> -------------------------------------------------------------------------------------------------------------------------------------------
> Irq name | CPU | Time consume us | Handler entry time | Handler exit time
> -------------------------------------------------------------------------------------------------------------------------------------------
> enp134s0f0-TxRx-2 | [0078] | 0.000005 s | 693757.533189 s | 693757.533194 s
hum, please yell at me if this was discussed before or I'm missing
something else, but wouldn't this be better and easier as a perf's
python script?
jirka
>
> Changes from v5:
> * Resolve conflicts by the latest commit.
>
> Changes from v4:
> * Keep pairs of irq entry/exit per cpu;
> * Add NUL-termination to the end of irq->irq_name when strncpy is used;
> * Delete some unused declarations and parameters;
>
> Changes from v3:
> * Delete 'perf irq script' because its function can be implemented using
> 'perf script';
> * Add --cpu option for 'perf irq';
>
> Changes from v2:
> * Delete "-m", "1024" in __cmd_record();
> * Change 'perf irq timeconsume <options>' to 'perf irq report <options>';
> * Fix a error for tools/perf/Documentation/perf-irq.txt;
>
> Bixuan Cui (2):
> perf tools: add 'perf irq' to measure the hardware interrupts
> perf tools: Add documentation for 'perf irq' command
>
> tools/perf/Build | 1 +
> tools/perf/Documentation/perf-irq.txt | 47 +++++
> tools/perf/builtin-irq.c | 260 ++++++++++++++++++++++++++
> tools/perf/builtin.h | 1 +
> tools/perf/command-list.txt | 1 +
> tools/perf/perf.c | 1 +
> 6 files changed, 311 insertions(+)
> create mode 100644 tools/perf/Documentation/perf-irq.txt
> create mode 100644 tools/perf/builtin-irq.c
>
> --
> 2.17.1
>
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2021-02-25 16:22 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-02-25 1:30 [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 1/2] " Bixuan Cui
2021-02-25 1:30 ` [PATCH v5 2/2] perf tools: Add documentation for 'perf irq' command Bixuan Cui
2021-02-25 16:19 ` [PATCH v5 0/2] perf tools: add 'perf irq' to measure the hardware interrupts Jiri Olsa
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).