From 638433bb926b698b804566ae8f1e55a54ecf891c Mon Sep 17 00:00:00 2001 From: Eelco Chaudron Date: Thu, 19 Dec 2024 15:29:43 +0100 Subject: [PATCH] utilities: Add upcall statistics to the kernel_delay.py script. This patch installs a kernel return probe on ovs_dp_upcall() to record all successful and failed calls per CPU. The statistics are reported when the script exits, providing insights into the upcall behavior. This is an example output: # UPCALL STATISTICS (TOTAL [CPU_ID: N_UPCALLS_PER_CPU, ...]): Total upcalls : 183247 [0: 8937, 2: 14464, 4: 10372, 6: 4254, ...] Successfull upcalls : 120195 [0: 5945, 2: 6379, 4: 5966, 6: 4254, ...] Failed upcalls : 63052 [0: 2992, 2: 8085, 4: 4406, 8: 2275, ...] 11, EAGAIN : 63052 [0: 2992, 2: 8085, 4: 4406, 8: 2275, ...] Tested-by: Adrian Moreno Reviewed-by: Adrian Moreno Signed-off-by: Eelco Chaudron --- utilities/automake.mk | 1 + utilities/usdt-scripts/kernel_delay.py | 136 +++++++++++++++++++++++- utilities/usdt-scripts/kernel_delay.rst | 9 ++ 3 files changed, 145 insertions(+), 1 deletion(-) diff --git a/utilities/automake.mk b/utilities/automake.mk index acc1af4e0b4..22260b2542f 100644 --- a/utilities/automake.mk +++ b/utilities/automake.mk @@ -149,6 +149,7 @@ FLAKE8_PYFILES += utilities/ovs-pcap.in \ utilities/ovs-pipegen.py \ utilities/usdt-scripts/dpif_op_nl_monitor.py \ utilities/usdt-scripts/flow_reval_monitor.py \ + utilities/usdt-scripts/kernel_delay.py \ utilities/usdt-scripts/upcall_monitor.py \ utilities/usdt-scripts/upcall_cost.py diff --git a/utilities/usdt-scripts/kernel_delay.py b/utilities/usdt-scripts/kernel_delay.py index de6b0c9de4d..367d27e34da 100755 --- a/utilities/usdt-scripts/kernel_delay.py +++ b/utilities/usdt-scripts/kernel_delay.py @@ -39,6 +39,7 @@ # import argparse import datetime +import errno import os import pytz import psutil @@ -556,6 +557,36 @@ data->start_ns = 0; return 0; } + + +/* + * For measuring upcall statistics (per CPU). + */ +BPF_PERCPU_HASH(upcall_count); + +#if +int kretprobe__ovs_dp_upcall(struct pt_regs *ctx) +{ + int ret = PT_REGS_RC(ctx); + u64 zero = 0; + u64 *entry; + u64 key; + + if (!capture_enabled__()) + return 0; + + if (ret >= 0) + key = 0; + else + key = -ret; + + entry = upcall_count.lookup_or_try_init(&key, &zero); + if (entry) + *entry += 1; + + return 0; +} +#endif /* For measuring upcall statistics/errors. */ """ @@ -887,6 +918,7 @@ def reset_capture(): bpf["stack_traces"].clear() bpf["stop_start"].clear() bpf["stop_data"].clear() + bpf["upcall_count"].clear() # @@ -900,6 +932,97 @@ def print_timestamp(msg): print(time_string) +# +# Get errno short string +# +def get_errno_short(err): + try: + return errno.errorcode[err] + except KeyError: + return "_unknown_" + + +# +# Format a eBPF per-cpu hash entry (if the count is > 0) +# +def format_per_cpu_hash(cpu_hash, key=None, skip_key=None): + per_cpu = "" + + if key is not None: + total = cpu_hash.sum(key).value + if total > 0: + for cpu, value in enumerate(cpu_hash.getvalue(key)): + if value == 0: + continue + + per_cpu += " {}: {},".format(cpu, value) + else: + total = 0 + total_cpu = None + + for key in cpu_hash.keys(): + if skip_key is not None and skip_key.value == key.value: + continue + + if total_cpu is None: + total_cpu = [0] * len(cpu_hash.getvalue(key)) + + for cpu, value in enumerate(cpu_hash.getvalue(key)): + total_cpu[cpu] += value + total += value + + if total >= 0 and total_cpu: + for cpu, value in enumerate(total_cpu): + if value == 0: + continue + + per_cpu += " {}: {},".format(cpu, value) + + return total, per_cpu.strip(", ") + + +# +# Display kernel upcall statistics +# +def display_upcall_results(): + upcalls = bpf["upcall_count"] + have_upcalls = False + + for k in upcalls: + if upcalls.sum(k).value == 0: + continue + have_upcalls = True + break + + if not have_upcalls: + return + + print("\n\n# UPCALL STATISTICS (TOTAL [CPU_ID: N_UPCALLS_PER_CPU, ...]):\n" + " Total upcalls : {} [{}]".format( + *format_per_cpu_hash(upcalls))) + + for k in sorted(upcalls, key=lambda x: int(x.value)): + error = k.value + total, per_cpu = format_per_cpu_hash(upcalls, key=k) + + if error != 0 and total == 0: + continue + + if error == 0: + total_failed, per_cpu_failed = format_per_cpu_hash(upcalls, + skip_key=k) + if total_failed == 0: + continue + + print(" Successfull upcalls : {} [{}]".format(total, per_cpu)) + print(" Failed upcalls : {} [{}]".format(total_failed, + per_cpu_failed)) + else: + print(" {:3}, {:13}: {} [{}]".format(error, + get_errno_short(error), + total, per_cpu)) + + # # process_results() # @@ -1074,7 +1197,12 @@ def process_results(syscall_events=None, trigger_delta=None): indent, "TOTAL:", "", total_count, total_ns)) # - # Print events + # Print upcall statistics + # + display_upcall_results() + + # + # Print syscall events # lost_stack_traces = 0 if syscall_events: @@ -1194,6 +1322,9 @@ def main(): parser.add_argument("--skip-syscall-poll-events", help="Skip poll() syscalls with --syscall-events", action="store_true") + parser.add_argument("--skip-upcall-stats", + help="Skip the collection of upcall statistics", + action="store_true") parser.add_argument("--stack-trace-size", help="Number of unique stack traces that can be " "recorded, default 4096. 0 to disable", @@ -1298,6 +1429,9 @@ def main(): source = source.replace("", "true" if options.stack_trace_size > 0 else "false") + source = source.replace("", "0" + if options.skip_upcall_stats else "1") + # # Handle start/stop probes # diff --git a/utilities/usdt-scripts/kernel_delay.rst b/utilities/usdt-scripts/kernel_delay.rst index 0f6f916a71e..41620d76059 100644 --- a/utilities/usdt-scripts/kernel_delay.rst +++ b/utilities/usdt-scripts/kernel_delay.rst @@ -109,6 +109,7 @@ followed by resource-specific data. Which are: - ``THREAD STOPPED STATISTICS`` - ``HARD IRQ STATISTICS`` - ``SOFT IRQ STATISTICS`` +- ``UPCALL STATISTICS`` The following sections will describe in detail what statistics they report. @@ -187,6 +188,14 @@ number of interrupts (``COUNT``), the total time spent in the interrupt handler (``TOTAL ns``), and the worst-case duration (``MAX ns``). +``UPCALL STATISTICS`` +~~~~~~~~~~~~~~~~~~~~~ +The ``UPCALL STATISTICS`` section provides information on the number of +upcalls sent by the kernel to userspace. If any upcalls fail to be sent, +the specific return codes are recorded. Statistics are presented both as +a total and on a per-CPU basis. + + The ``--syscall-events`` option ------------------------------- In addition to reporting global syscall statistics in ``SYSCALL_STATISTICS``,