From patchwork Mon Nov 25 14:14:20 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Eelco Chaudron X-Patchwork-Id: 2014957 X-Patchwork-Delegate: aconole@redhat.com Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@legolas.ozlabs.org Authentication-Results: legolas.ozlabs.org; dkim=fail reason="signature verification failed" (1024-bit key; unprotected) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=JsP7BNzx; dkim-atps=neutral Authentication-Results: legolas.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org (client-ip=2605:bc80:3010::138; helo=smtp1.osuosl.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=patchwork.ozlabs.org) Received: from smtp1.osuosl.org (smtp1.osuosl.org [IPv6:2605:bc80:3010::138]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature ECDSA (secp384r1) server-digest SHA384) (No client certificate requested) by legolas.ozlabs.org (Postfix) with ESMTPS id 4XxnlN1YnKz1yCv for ; Tue, 26 Nov 2024 01:14:40 +1100 (AEDT) Received: from localhost (localhost [127.0.0.1]) by smtp1.osuosl.org (Postfix) with ESMTP id 4011A8143A; Mon, 25 Nov 2024 14:14:38 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp1.osuosl.org ([127.0.0.1]) by localhost (smtp1.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id oXn-Kuo6s3s3; Mon, 25 Nov 2024 14:14:31 +0000 (UTC) X-Comment: SPF check N/A for local connections - client-ip=140.211.9.56; helo=lists.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver= DKIM-Filter: OpenDKIM Filter v2.11.0 smtp1.osuosl.org 90A9280517 Authentication-Results: smtp1.osuosl.org; dkim=fail reason="signature verification failed" (1024-bit key) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=JsP7BNzx Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [140.211.9.56]) by smtp1.osuosl.org (Postfix) with ESMTPS id 90A9280517; Mon, 25 Nov 2024 14:14:31 +0000 (UTC) Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 2F061C08A9; Mon, 25 Nov 2024 14:14:31 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp2.osuosl.org (smtp2.osuosl.org [140.211.166.133]) by lists.linuxfoundation.org (Postfix) with ESMTP id 82C8BC08A8 for ; Mon, 25 Nov 2024 14:14:29 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp2.osuosl.org (Postfix) with ESMTP id 5BB19433BE for ; Mon, 25 Nov 2024 14:14:29 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp2.osuosl.org ([127.0.0.1]) by localhost (smtp2.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id EVUAkK4stERT for ; Mon, 25 Nov 2024 14:14:28 +0000 (UTC) Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=170.10.129.124; helo=us-smtp-delivery-124.mimecast.com; envelope-from=echaudro@redhat.com; receiver= DMARC-Filter: OpenDMARC Filter v1.4.2 smtp2.osuosl.org EAFB4433B8 Authentication-Results: smtp2.osuosl.org; dmarc=pass (p=none dis=none) header.from=redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 smtp2.osuosl.org EAFB4433B8 Authentication-Results: smtp2.osuosl.org; dkim=pass (1024-bit key) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=JsP7BNzx Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.129.124]) by smtp2.osuosl.org (Postfix) with ESMTPS id EAFB4433B8 for ; Mon, 25 Nov 2024 14:14:27 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1732544066; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=n3aLeq23jhmXrWGP1OHkbnrxfObsjoP3FHjcE0k7G2E=; b=JsP7BNzxGIl99ZiVXvS4nTIDr4S4L7/KeWzbfiOrmTZzqQTgs+sjetU0ziCzXk6E3dbscx 81mrNhx+724Uq2jeaCUrvriEAFSKhASYNU1dvTWhqS/KcosfIwS72vHLnMZqSQ4T+69sdG HTcvZQePNQnbohnqKWJ2y7TxMUrnzwM= Received: from mx-prod-mc-05.mail-002.prod.us-west-2.aws.redhat.com (ec2-54-186-198-63.us-west-2.compute.amazonaws.com [54.186.198.63]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-275-syS9XYrCNaCBVx1HoDtsOg-1; Mon, 25 Nov 2024 09:14:24 -0500 X-MC-Unique: syS9XYrCNaCBVx1HoDtsOg-1 X-Mimecast-MFC-AGG-ID: syS9XYrCNaCBVx1HoDtsOg Received: from mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com (mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com [10.30.177.17]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by mx-prod-mc-05.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTPS id C5586195608D for ; Mon, 25 Nov 2024 14:14:23 +0000 (UTC) Received: from wsfd-advnetlab224.anl.eng.rdu2.dc.redhat.com (wsfd-advnetlab224.anl.eng.rdu2.dc.redhat.com [10.6.42.15]) by mx-prod-int-05.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTP id 6C3FE1956052 for ; Mon, 25 Nov 2024 14:14:23 +0000 (UTC) From: Eelco Chaudron To: dev@openvswitch.org Date: Mon, 25 Nov 2024 15:14:20 +0100 Message-ID: <173254404327.545539.5146903122430077833.stgit@wsfd-advnetlab224.anl.eng.rdu2.dc.redhat.com> User-Agent: StGit/1.5 MIME-Version: 1.0 X-Scanned-By: MIMEDefang 3.0 on 10.30.177.17 X-Mimecast-Spam-Score: 0 X-Mimecast-MFC-PROC-ID: mpQL12kzN1swn6yd9OG6ZkuDJFDwxbMhaG5tvF_dWRI_1732544064 X-Mimecast-Originator: redhat.com Subject: [ovs-dev] [PATCH] utilities: Add upcall statistics to the kernel_delay.py script. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.30 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" 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 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, ...] Signed-off-by: Eelco Chaudron --- utilities/automake.mk | 1 utilities/usdt-scripts/kernel_delay.py | 127 +++++++++++++++++++++++++++++++ utilities/usdt-scripts/kernel_delay.rst | 9 ++ 3 files changed, 136 insertions(+), 1 deletion(-) diff --git a/utilities/automake.mk b/utilities/automake.mk index acc1af4e0..22260b254 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 de6b0c9de..a5aa1a3d4 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,30 @@ TRACEPOINT_PROBE(irq, softirq_exit) data->start_ns = 0; return 0; } + + +/* + * For measuring upcall statistics (per CPU). + */ +#define MAX_ERROR 255 +BPF_TABLE("percpu_array", uint32_t, uint64_t, upcall_count, MAX_ERROR + 1); + +#if +int kretprobe__ovs_dp_upcall(struct pt_regs *ctx) +{ + int ret = PT_REGS_RC(ctx); + + if (ret > 0) + ret = 0; + + ret = -ret; + if (ret > MAX_ERROR) + ret = MAX_ERROR; + + upcall_count.increment(ret); + return 0; +} +#endif /* For measuring upcall statistics/errors. */ """ @@ -900,6 +925,95 @@ 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 bfd per cpu array entry per cpu (if the count is > 0) +# +def format_per_cpu_array(cpu_array, key=None, skip_key=None): + per_cpu = "" + + if key is not None: + total = cpu_array.sum(key).value + if total > 0: + for cpu, value in enumerate(cpu_array.getvalue(key)): + if value == 0: + continue + + per_cpu += " {}: {},".format(cpu, value) + else: + total = 0 + total_cpu = None + + for key in cpu_array.keys(): + # I've seen extrem odd hight values, to avoid those, exclude any + # index higher thant 1024 for now. + if (not (0 <= key.value <= 1024)) or (skip_key is not None and + skip_key.value == key.value): + continue + + if total_cpu is None: + total_cpu = [0] * len(cpu_array.getvalue(key)) + + for cpu, value in enumerate(cpu_array.getvalue(key)): + total_cpu[cpu] += value + total += value + + if total >= 0: + for cpu, value in enumerate(total_cpu): + if value == 0: + continue + + per_cpu += " {}: {},".format(cpu, value) + + return str(total), per_cpu.strip(", ") + + +# +# Display kernel upcall statistics +# +def display_upcall_results(): + upcalls = bpf.get_table("upcall_count") + have_upcalls = False + + for k in upcalls.keys(): + if not (0 <= k.value <= 255) or upcalls.sum(k).value == 0: + continue + have_upcalls = True + break + + if not have_upcalls: + return + + print("\n\n# UPCALL STATISTICS:\n Total upcalls : {} [{}]".format( + *format_per_cpu_array(upcalls))) + + for k in upcalls.keys(): + error = k.value + total, per_cpu = format_per_cpu_array(upcalls, key=k) + + if error != 0 and total == "0": + continue + + if error == 0: + print(" Successfull upcalls : {} [{}]".format(total, per_cpu)) + + total, per_cpu = format_per_cpu_array(upcalls, skip_key=k) + print(" Failed upcalls : {} [{}]".format(total, per_cpu)) + else: + print(" {:3}, {:13}: {} [{}]".format(error, + get_errno_short(error), + total, per_cpu)) + + # # process_results() # @@ -1074,7 +1188,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 +1313,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 +1420,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 0f6f916a7..41620d760 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``,