From patchwork Mon Mar 24 08:06:54 2025 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Eelco Chaudron X-Patchwork-Id: 2064359 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=NCo7rb0O; dkim-atps=neutral Authentication-Results: legolas.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org (client-ip=140.211.166.137; helo=smtp4.osuosl.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=patchwork.ozlabs.org) Received: from smtp4.osuosl.org (smtp4.osuosl.org [140.211.166.137]) (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 4ZLlyT44Dmz1yG0 for ; Mon, 24 Mar 2025 19:07:13 +1100 (AEDT) Received: from localhost (localhost [127.0.0.1]) by smtp4.osuosl.org (Postfix) with ESMTP id 9DEC6408C8; Mon, 24 Mar 2025 08:07:14 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp4.osuosl.org ([127.0.0.1]) by localhost (smtp4.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id OYJoZ-Mwf6zM; Mon, 24 Mar 2025 08:07:13 +0000 (UTC) X-Comment: SPF check N/A for local connections - client-ip=2605:bc80:3010:104::8cd3:938; helo=lists.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver= DKIM-Filter: OpenDKIM Filter v2.11.0 smtp4.osuosl.org 8043440842 Authentication-Results: smtp4.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=NCo7rb0O Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [IPv6:2605:bc80:3010:104::8cd3:938]) by smtp4.osuosl.org (Postfix) with ESMTPS id 8043440842; Mon, 24 Mar 2025 08:07:13 +0000 (UTC) Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 66E8DC007B; Mon, 24 Mar 2025 08:07:13 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp3.osuosl.org (smtp3.osuosl.org [IPv6:2605:bc80:3010::136]) by lists.linuxfoundation.org (Postfix) with ESMTP id 65324C0009 for ; Mon, 24 Mar 2025 08:07:12 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp3.osuosl.org (Postfix) with ESMTP id 4C8B160B8A for ; Mon, 24 Mar 2025 08:07:10 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp3.osuosl.org ([127.0.0.1]) by localhost (smtp3.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id YjRuexFWZgUj for ; Mon, 24 Mar 2025 08:07:09 +0000 (UTC) Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=170.10.133.124; helo=us-smtp-delivery-124.mimecast.com; envelope-from=echaudro@redhat.com; receiver= DMARC-Filter: OpenDMARC Filter v1.4.2 smtp3.osuosl.org 5F38560B8F Authentication-Results: smtp3.osuosl.org; dmarc=pass (p=quarantine dis=none) header.from=redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 smtp3.osuosl.org 5F38560B8F Authentication-Results: smtp3.osuosl.org; dkim=pass (1024-bit key) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=NCo7rb0O Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by smtp3.osuosl.org (Postfix) with ESMTPS id 5F38560B8F for ; Mon, 24 Mar 2025 08:07:09 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1742803628; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=J9VeNrruP9+w+5WBmFtRXhQV/XwBYIvkIBM9dcUFFsA=; b=NCo7rb0Owrk6sWA4b3FfBIg3oq7LavSJzZUTSVpcDeWz1Z0R/pwhSlPX8eDCrBYhVW7a6K 8OhnKjnksVPpC9CQhhzsdgTWKlijtU1rKWwKJQrEZbndORKif5SqU0d1erjtgZ5pSiJaD4 Nsp/FI0c89jeP+iyfJsMBQ91ZgICBQM= Received: from mx-prod-mc-06.mail-002.prod.us-west-2.aws.redhat.com (ec2-35-165-154-97.us-west-2.compute.amazonaws.com [35.165.154.97]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-516-l0OtNE82NhW32SoQ_rXTTA-1; Mon, 24 Mar 2025 04:07:06 -0400 X-MC-Unique: l0OtNE82NhW32SoQ_rXTTA-1 X-Mimecast-MFC-AGG-ID: l0OtNE82NhW32SoQ_rXTTA_1742803625 Received: from mx-prod-int-01.mail-002.prod.us-west-2.aws.redhat.com (mx-prod-int-01.mail-002.prod.us-west-2.aws.redhat.com [10.30.177.4]) (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-06.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTPS id BB014180025E for ; Mon, 24 Mar 2025 08:07:05 +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-01.mail-002.prod.us-west-2.aws.redhat.com (Postfix) with ESMTP id 415E630001A1; Mon, 24 Mar 2025 08:07:05 +0000 (UTC) To: dev@openvswitch.org Date: Mon, 24 Mar 2025 09:06:54 +0100 Message-ID: MIME-Version: 1.0 X-Scanned-By: MIMEDefang 3.4.1 on 10.30.177.4 X-Mimecast-Spam-Score: 0 X-Mimecast-MFC-PROC-ID: cxng_x-zno1trWYaSf44ytZzvxdBtXUaux4hESRZKNY_1742803625 X-Mimecast-Originator: redhat.com Subject: [ovs-dev] [PATCH v3] utilities: Add long poll 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: , X-Patchwork-Original-From: Eelco Chaudron via dev From: Eelco Chaudron Reply-To: Eelco Chaudron Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" This addition uses the existing syscall probes to record statistics related to the OVS 'Unreasonably long ... ms poll interval' message. Basically, it records the min/max/average time between system poll calls. This can be used to determine if a long poll event has occurred during the capture. Signed-off-by: Eelco Chaudron --- The long line warning can be ignored. I'm keeping the original output in the documentation. v3: - Fixed else if problem for min delay case. - Fixed theoretical divide by 0. v2: - Calculate the average on display, not per sample. - Enhanced the documentation with additional log details. --- utilities/usdt-scripts/kernel_delay.py | 70 ++++++++++++++++++++++++- utilities/usdt-scripts/kernel_delay.rst | 17 +++++- 2 files changed, 83 insertions(+), 4 deletions(-) diff --git a/utilities/usdt-scripts/kernel_delay.py b/utilities/usdt-scripts/kernel_delay.py index 367d27e34..2372ca917 100755 --- a/utilities/usdt-scripts/kernel_delay.py +++ b/utilities/usdt-scripts/kernel_delay.py @@ -182,11 +182,27 @@ struct syscall_data_key_t { u32 syscall; }; +struct long_poll_data_key_t { + u32 pid; + u32 tid; +}; + +struct long_poll_data_t { + u64 count; + u64 total_ns; + u64 min_ns; + u64 max_ns; +}; + BPF_HASH(syscall_start, u64, u64); BPF_HASH(syscall_data, struct syscall_data_key_t, struct syscall_data_t); +BPF_HASH(long_poll_start, u64, u64); +BPF_HASH(long_poll_data, struct long_poll_data_key_t, struct long_poll_data_t); TRACEPOINT_PROBE(raw_syscalls, sys_enter) { u64 pid_tgid = bpf_get_current_pid_tgid(); + struct long_poll_data_t *val, init_val = {.min_ns = U64_MAX}; + struct long_poll_data_key_t key; if (!capture_enabled(pid_tgid)) return 0; @@ -194,6 +210,29 @@ TRACEPOINT_PROBE(raw_syscalls, sys_enter) { u64 t = bpf_ktime_get_ns(); syscall_start.update(&pid_tgid, &t); + /* Do long poll handling from here on. */ + if (args->id != ) + return 0; + + u64 *start_ns = long_poll_start.lookup(&pid_tgid); + + if (!start_ns || *start_ns == 0) + return 0; + + key.pid = pid_tgid >> 32; + key.tid = (u32)pid_tgid; + + val = long_poll_data.lookup_or_try_init(&key, &init_val); + if (val) { + u64 delta = t - *start_ns; + val->count++; + val->total_ns += delta; + if (delta > val->max_ns) + val->max_ns = delta; + if (delta < val->min_ns) + val->min_ns = delta; + } + return 0; } @@ -206,6 +245,12 @@ TRACEPOINT_PROBE(raw_syscalls, sys_exit) { if (!capture_enabled(pid_tgid)) return 0; + u64 t = bpf_ktime_get_ns(); + + if (args->id == ) { + long_poll_start.update(&pid_tgid, &t); + } + key.pid = pid_tgid >> 32; key.tid = (u32)pid_tgid; key.syscall = args->id; @@ -217,7 +262,7 @@ TRACEPOINT_PROBE(raw_syscalls, sys_exit) { val = syscall_data.lookup_or_try_init(&key, &zero); if (val) { - u64 delta = bpf_ktime_get_ns() - *start_ns; + u64 delta = t - *start_ns; val->count++; val->total_ns += delta; if (delta > val->worst_ns) @@ -1039,6 +1084,9 @@ def process_results(syscall_events=None, trigger_delta=None): threads_syscall = {k.tid for k, _ in bpf["syscall_data"].items() if k.syscall != 0xffffffff} + threads_long_poll = {k.tid for k, _ in bpf["long_poll_data"].items() + if k.pid != 0xffffffff} + threads_run = {k.tid for k, _ in bpf["run_data"].items() if k.pid != 0xffffffff} @@ -1055,7 +1103,8 @@ def process_results(syscall_events=None, trigger_delta=None): if k.pid != 0xffffffff} threads = sorted(threads_syscall | threads_run | threads_ready | - threads_stopped | threads_hardirq | threads_softirq, + threads_stopped | threads_hardirq | threads_softirq | + threads_long_poll, key=lambda x: get_thread_name(options.pid, x)) # @@ -1099,6 +1148,21 @@ def process_results(syscall_events=None, trigger_delta=None): print("{}{:20.20} {:6} {:10} {:16,}".format( indent, "TOTAL( - poll):", "", total_count, total_ns)) + # + # LONG POLL STATISTICS + # + for k, v in filter(lambda t: t[0].tid == thread, + bpf["long_poll_data"].items()): + + print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16} {:>16}".format( + "", "", "[LONG POLL STATISTICS]", indent, + "COUNT", "AVERAGE ns", "MIN ns", "MAX ns")) + + print("{}{:10} {:16,} {:16,} {:16,}".format( + indent, v.count, int(v.total_ns / max(v.count, 1)), + v.min_ns, v.max_ns)) + break + # # THREAD RUN STATISTICS # @@ -1429,6 +1493,8 @@ def main(): source = source.replace("", "true" if options.stack_trace_size > 0 else "false") + source = source.replace("", str(poll_id)) + source = source.replace("", "0" if options.skip_upcall_stats else "1") diff --git a/utilities/usdt-scripts/kernel_delay.rst b/utilities/usdt-scripts/kernel_delay.rst index 41620d760..0a2a430a5 100644 --- a/utilities/usdt-scripts/kernel_delay.rst +++ b/utilities/usdt-scripts/kernel_delay.rst @@ -67,13 +67,17 @@ with the ``--pid`` option. read 0 1 1,292 1,292 TOTAL( - poll): 519 144,405,334 + [LONG POLL STATISTICS] + COUNT AVERAGE ns MIN ns MAX ns + 58 76,773 7,388 234,129 + [THREAD RUN STATISTICS] SCHED_CNT TOTAL ns MIN ns MAX ns - 6 136,764,071 1,480 115,146,424 + 6 136,764,071 1,480 115,146,424 [THREAD READY STATISTICS] SCHED_CNT TOTAL ns MAX ns - 7 11,334 6,636 + 7 11,334 6,636 [THREAD STOPPED STATISTICS] STOP_CNT TOTAL ns MAX ns @@ -104,6 +108,7 @@ For this, it displays the thread's id (``TID``) and name (``THREAD``), followed by resource-specific data. Which are: - ``SYSCALL STATISTICS`` +- ``LONG POLL STATISTICS`` - ``THREAD RUN STATISTICS`` - ``THREAD READY STATISTICS`` - ``THREAD STOPPED STATISTICS`` @@ -129,6 +134,14 @@ Note that it only counts calls that started and stopped during the measurement interval! +``LONG POLL STATISTICS`` +~~~~~~~~~~~~~~~~~~~~~~ +``LONG POLL STATISTICS`` tell you how long the thread was running between two +poll system calls. This relates to the 'Unreasonably long ... ms poll interval' +message reported by ovs-vswitchd. More details about this message can be found +in the example section. + + ``THREAD RUN STATISTICS`` ~~~~~~~~~~~~~~~~~~~~~~~~~ ``THREAD RUN STATISTICS`` tell you how long the thread was running on a CPU