From patchwork Mon Jan 29 12:51:42 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Eelco Chaudron X-Patchwork-Id: 1892223 X-Patchwork-Delegate: echaudro@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=CafL2+cY; 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 4TNp9V4pmRz23fv for ; Mon, 29 Jan 2024 23:52:30 +1100 (AEDT) Received: from localhost (localhost [127.0.0.1]) by smtp1.osuosl.org (Postfix) with ESMTP id 163D483227; Mon, 29 Jan 2024 12:52:28 +0000 (UTC) DKIM-Filter: OpenDKIM Filter v2.11.0 smtp1.osuosl.org 163D483227 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=CafL2+cY X-Virus-Scanned: amavisd-new at osuosl.org Received: from smtp1.osuosl.org ([127.0.0.1]) by localhost (smtp1.osuosl.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id vc-xhBvytFkC; Mon, 29 Jan 2024 12:52:27 +0000 (UTC) Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [140.211.9.56]) by smtp1.osuosl.org (Postfix) with ESMTPS id E1E43831DE; Mon, 29 Jan 2024 12:52:25 +0000 (UTC) DKIM-Filter: OpenDKIM Filter v2.11.0 smtp1.osuosl.org E1E43831DE Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 9D4D3C0077; Mon, 29 Jan 2024 12:52:25 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp1.osuosl.org (smtp1.osuosl.org [140.211.166.138]) by lists.linuxfoundation.org (Postfix) with ESMTP id A4329C0037 for ; Mon, 29 Jan 2024 12:52:23 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp1.osuosl.org (Postfix) with ESMTP id 79F5B831F8 for ; Mon, 29 Jan 2024 12:52:23 +0000 (UTC) DKIM-Filter: OpenDKIM Filter v2.11.0 smtp1.osuosl.org 79F5B831F8 X-Virus-Scanned: amavisd-new at osuosl.org Received: from smtp1.osuosl.org ([127.0.0.1]) by localhost (smtp1.osuosl.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 24YZA58NKm4n for ; Mon, 29 Jan 2024 12:52:22 +0000 (UTC) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.129.124]) by smtp1.osuosl.org (Postfix) with ESMTPS id 61437831DE for ; Mon, 29 Jan 2024 12:52:22 +0000 (UTC) DKIM-Filter: OpenDKIM Filter v2.11.0 smtp1.osuosl.org 61437831DE DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1706532740; 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=qh5D8WkPnCAkclcMTjpdSkp8g6/OAPV24qgSH6pCZ8g=; b=CafL2+cYNsTyhfk9Pf+6lQocGz2Fq4gDyA4aEl3cX9+lgg/BAZa8QBxgG/PjDxIwd4AWBc vlYa37t0guGqUlwtmFZxfdlzobwowraJFIJxZMvwSDz1NwxpHN8RaCmtGGOUvZs/QFZbUr ClvIvHoXbTf1/oSJJeB+VSnavjZqv1E= Received: from mimecast-mx02.redhat.com (mx-ext.redhat.com [66.187.233.73]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-581-Vp80XaXeM_yz0DB2OJXeVg-1; Mon, 29 Jan 2024 07:52:17 -0500 X-MC-Unique: Vp80XaXeM_yz0DB2OJXeVg-1 Received: from smtp.corp.redhat.com (int-mx09.intmail.prod.int.rdu2.redhat.com [10.11.54.9]) (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 mimecast-mx02.redhat.com (Postfix) with ESMTPS id 758E81C05EB8; Mon, 29 Jan 2024 12:52:17 +0000 (UTC) Received: from ebuild.redhat.com (unknown [10.39.194.234]) by smtp.corp.redhat.com (Postfix) with ESMTP id BDBBB492BC6; Mon, 29 Jan 2024 12:52:16 +0000 (UTC) From: Eelco Chaudron To: dev@openvswitch.org Date: Mon, 29 Jan 2024 13:51:42 +0100 Message-ID: <133df783097cbd7c62d0ff3efdfd1f349c1aa421.1706532702.git.echaudro@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 3.4.1 on 10.11.54.9 X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Subject: [ovs-dev] [PATCH v2] utilities: Add TASK_STOPPED accounting to the kernel_delay.py script. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" This changes add statistics for when a thread is put into stop state. For example with the following: kill -STOP $(pidof ovs-vswitchd); sleep 1; kill -CONT $(pidof ovs-vswitchd); Acked-by: Simon Horman Signed-off-by: Eelco Chaudron --- v2: - Removed worst/max ns delay zero checks. utilities/usdt-scripts/kernel_delay.py | 110 ++++++++++++++++++------ utilities/usdt-scripts/kernel_delay.rst | 24 ++++++ 2 files changed, 110 insertions(+), 24 deletions(-) diff --git a/utilities/usdt-scripts/kernel_delay.py b/utilities/usdt-scripts/kernel_delay.py index b2012fdf2..de6b0c9de 100755 --- a/utilities/usdt-scripts/kernel_delay.py +++ b/utilities/usdt-scripts/kernel_delay.py @@ -81,7 +81,6 @@ struct event_t { u32 syscall; u64 entry_ts; - }; BPF_RINGBUF_OUTPUT(events, ); @@ -220,7 +219,7 @@ TRACEPOINT_PROBE(raw_syscalls, sys_exit) { u64 delta = bpf_ktime_get_ns() - *start_ns; val->count++; val->total_ns += delta; - if (val->worst_ns == 0 || delta > val->worst_ns) + if (delta > val->worst_ns) val->worst_ns = delta; if () { @@ -243,13 +242,12 @@ TRACEPOINT_PROBE(raw_syscalls, sys_exit) { /* - * For measuring the thread run time, we need the following. + * For measuring the thread stopped time, we need the following. */ -struct run_time_data_t { +struct stop_time_data_t { u64 count; u64 total_ns; - u64 max_ns; - u64 min_ns; + u64 worst_ns; }; struct pid_tid_key_t { @@ -257,6 +255,43 @@ struct pid_tid_key_t { u32 tid; }; +BPF_HASH(stop_start, u64, u64); +BPF_HASH(stop_data, struct pid_tid_key_t, struct stop_time_data_t); + +static inline void thread_handle_stopped_run(u32 pid, u32 tgid, u64 ktime) +{ + u64 pid_tgid = (u64) tgid << 32 | pid; + u64 *start_ns = stop_start.lookup(&pid_tgid); + + if (!start_ns || *start_ns == 0) + return; + + struct stop_time_data_t *val, zero = {}; + struct pid_tid_key_t key = { .pid = tgid, + .tid = pid }; + + val = stop_data.lookup_or_try_init(&key, &zero); + if (val) { + u64 delta = ktime - *start_ns; + val->count++; + val->total_ns += delta; + if (delta > val->worst_ns) + val->worst_ns = delta; + } + *start_ns = 0; +} + + +/* + * For measuring the thread run time, we need the following. + */ +struct run_time_data_t { + u64 count; + u64 total_ns; + u64 max_ns; + u64 min_ns; +}; + BPF_HASH(run_start, u64, u64); BPF_HASH(run_data, struct pid_tid_key_t, struct run_time_data_t); @@ -282,7 +317,7 @@ static inline void thread_stop_run(u32 pid, u32 tgid, u64 ktime) u64 delta = ktime - *start_ns; val->count++; val->total_ns += delta; - if (val->max_ns == 0 || delta > val->max_ns) + if (delta > val->max_ns) val->max_ns = delta; if (val->min_ns == 0 || delta < val->min_ns) val->min_ns = delta; @@ -312,6 +347,8 @@ static inline int sched_wakeup__(u32 pid, u32 tgid) u64 t = bpf_ktime_get_ns(); ready_start.update(&pid_tgid, &t); + + thread_handle_stopped_run(pid, tgid, t); return 0; } @@ -336,22 +373,26 @@ RAW_TRACEPOINT_PROBE(sched_switch) if (!capture_enabled__()) return 0; - if (prev-> == TASK_RUNNING && prev->tgid == MONITOR_PID) - sched_wakeup__(prev->pid, prev->tgid); - if (prev->tgid == MONITOR_PID) { + u64 prev_pid_tgid = (u64)next->tgid << 32 | next->pid; ktime = bpf_ktime_get_ns(); + + if (prev-> == TASK_RUNNING) + ready_start.update(&prev_pid_tgid, &ktime); + + if (prev-> & __TASK_STOPPED) + stop_start.update(&prev_pid_tgid, &ktime); + thread_stop_run(prev->pid, prev->tgid, ktime); } - u64 pid_tgid = (u64)next->tgid << 32 | next->pid; - if (next->tgid != MONITOR_PID) return 0; if (ktime == 0) ktime = bpf_ktime_get_ns(); + u64 pid_tgid = (u64)next->tgid << 32 | next->pid; u64 *start_ns = ready_start.lookup(&pid_tgid); if (start_ns && *start_ns != 0) { @@ -365,7 +406,7 @@ RAW_TRACEPOINT_PROBE(sched_switch) u64 delta = ktime - *start_ns; val->count++; val->total_ns += delta; - if (val->worst_ns == 0 || delta > val->worst_ns) + if (delta > val->worst_ns) val->worst_ns = delta; } *start_ns = 0; @@ -438,7 +479,7 @@ TRACEPOINT_PROBE(irq, irq_handler_exit) u64 delta = bpf_ktime_get_ns() - data->start_ns; val->count++; val->total_ns += delta; - if (val->worst_ns == 0 || delta > val->worst_ns) + if (delta > val->worst_ns) val->worst_ns = delta; } } @@ -508,7 +549,7 @@ TRACEPOINT_PROBE(irq, softirq_exit) u64 delta = bpf_ktime_get_ns() - data->start_ns; val->count++; val->total_ns += delta; - if (val->worst_ns == 0 || delta > val->worst_ns) + if (delta > val->worst_ns) val->worst_ns = delta; } @@ -844,6 +885,8 @@ def reset_capture(): bpf["softirq_start"].clear() bpf["softirq_data"].clear() bpf["stack_traces"].clear() + bpf["stop_start"].clear() + bpf["stop_data"].clear() # @@ -879,6 +922,9 @@ def process_results(syscall_events=None, trigger_delta=None): threads_ready = {k.tid for k, _ in bpf["ready_data"].items() if k.pid != 0xffffffff} + threads_stopped = {k.tid for k, _ in bpf["stop_data"].items() + if k.pid != 0xffffffff} + threads_hardirq = {k.tid for k, _ in bpf["hardirq_data"].items() if k.pid != 0xffffffff} @@ -886,7 +932,7 @@ def process_results(syscall_events=None, trigger_delta=None): if k.pid != 0xffffffff} threads = sorted(threads_syscall | threads_run | threads_ready | - threads_hardirq | threads_softirq, + threads_stopped | threads_hardirq | threads_softirq, key=lambda x: get_thread_name(options.pid, x)) # @@ -933,28 +979,44 @@ def process_results(syscall_events=None, trigger_delta=None): # # THREAD RUN STATISTICS # - print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16} {:>16}".format( - "", "", "[THREAD RUN STATISTICS]", indent, - "SCHED_CNT", "TOTAL ns", "MIN ns", "MAX ns")) - for k, v in filter(lambda t: t[0].tid == thread, bpf["run_data"].items()): + print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16} {:>16}".format( + "", "", "[THREAD RUN STATISTICS]", indent, + "SCHED_CNT", "TOTAL ns", "MIN ns", "MAX ns")) + print("{}{:10} {:16,} {:16,} {:16,}".format( indent, v.count, v.total_ns, v.min_ns, v.max_ns)) + break # # THREAD READY STATISTICS # - print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16}".format( - "", "", "[THREAD READY STATISTICS]", indent, - "SCHED_CNT", "TOTAL ns", "MAX ns")) - for k, v in filter(lambda t: t[0].tid == thread, bpf["ready_data"].items()): + print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16}".format( + "", "", "[THREAD READY STATISTICS]", indent, + "SCHED_CNT", "TOTAL ns", "MAX ns")) + print("{}{:10} {:16,} {:16,}".format( indent, v.count, v.total_ns, v.worst_ns)) + break + + # + # THREAD STOPPED STATISTICS + # + for k, v in filter(lambda t: t[0].tid == thread, + bpf["stop_data"].items()): + + print("\n{:10} {:16} {}\n{}{:10} {:>16} {:>16}".format( + "", "", "[THREAD STOPPED STATISTICS]", indent, + "STOP_CNT", "TOTAL ns", "MAX ns")) + + print("{}{:10} {:16,} {:16,}".format( + indent, v.count, v.total_ns, v.worst_ns)) + break # # HARD IRQ STATISTICS diff --git a/utilities/usdt-scripts/kernel_delay.rst b/utilities/usdt-scripts/kernel_delay.rst index 0ebd30afb..e2e43752d 100644 --- a/utilities/usdt-scripts/kernel_delay.rst +++ b/utilities/usdt-scripts/kernel_delay.rst @@ -75,6 +75,10 @@ with the ``--pid`` option. SCHED_CNT TOTAL ns MAX ns 7 11,334 6,636 + [THREAD STOPPED STATISTICS] + STOP_CNT TOTAL ns MAX ns + 3 3,045,728,323 1,015,739,474 + [HARD IRQ STATISTICS] NAME COUNT TOTAL ns MAX ns eno8303-rx-1 1 3,586 3,586 @@ -102,6 +106,7 @@ followed by resource-specific data. Which are: - ``SYSCALL STATISTICS`` - ``THREAD RUN STATISTICS`` - ``THREAD READY STATISTICS`` +- ``THREAD STOPPED STATISTICS`` - ``HARD IRQ STATISTICS`` - ``SOFT IRQ STATISTICS`` @@ -143,6 +148,25 @@ Note that these statistics only count events where the thread was getting ready to run and started running during the measurement interval. +``THREAD STOPPED STATISTICS`` +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +``THREAD STOPPED STATISTICS`` reveal the number of instances where the thread +has been scheduled out while in the running state due to its transition to +the TASK_STOPPED state. + +This behavior can be replicated by manually placing the thread in the stopped +state and subsequently resuming it. For instance: + +.. code-block:: console + + # kill -STOP $(pidof ovs-vswitchd); \ + sleep 1; \ + kill -CONT $(pidof ovs-vswitchd); + +Note that these statistics only count events where the thread was running at +the time it was put to stopped state. + + ``HARD IRQ STATISTICS`` ~~~~~~~~~~~~~~~~~~~~~~~ ``HARD IRQ STATISTICS`` tell you how much time was spent servicing hard