From patchwork Wed Jan 26 18:58:10 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Krzysztof Kozlowski X-Patchwork-Id: 1584635 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: bilbo.ozlabs.org; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=canonical.com header.i=@canonical.com header.a=rsa-sha256 header.s=20210705 header.b=B2OgsMnX; dkim-atps=neutral Authentication-Results: ozlabs.org; spf=none (no SPF record) smtp.mailfrom=lists.ubuntu.com (client-ip=91.189.94.19; helo=huckleberry.canonical.com; envelope-from=kernel-team-bounces@lists.ubuntu.com; receiver=) Received: from huckleberry.canonical.com (huckleberry.canonical.com [91.189.94.19]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by bilbo.ozlabs.org (Postfix) with ESMTPS id 4JkY1d3smBz9t0k for ; Thu, 27 Jan 2022 05:59:49 +1100 (AEDT) Received: from localhost ([127.0.0.1] helo=huckleberry.canonical.com) by huckleberry.canonical.com with esmtp (Exim 4.86_2) (envelope-from ) id 1nCnW8-0006jd-4z; Wed, 26 Jan 2022 18:59:40 +0000 Received: from smtp-relay-internal-1.internal ([10.131.114.114] helo=smtp-relay-internal-1.canonical.com) by huckleberry.canonical.com with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.86_2) (envelope-from ) id 1nCnVu-0006Ru-W1 for kernel-team@lists.ubuntu.com; Wed, 26 Jan 2022 18:59:27 +0000 Received: from mail-ed1-f69.google.com (mail-ed1-f69.google.com [209.85.208.69]) (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 smtp-relay-internal-1.canonical.com (Postfix) with ESMTPS id A85273F1D9 for ; Wed, 26 Jan 2022 18:59:26 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=canonical.com; s=20210705; t=1643223566; bh=+Rr1qbIwoOK9b9H/AxMUza07pBV16meHF81A+tuAjn0=; h=From:To:Subject:Date:Message-Id:In-Reply-To:References: MIME-Version; b=B2OgsMnX/D/oURt9MAZqzbbEbuYw4WkN8d46uXnB/1tTtlubBPd7g06aCHQ3iX0Mp MSdALmA1gtvm+RrRipaTqwN9GSdMdsMlqngKegziQ+keBRDD6ABDS1mB7ZGqcYc3p6 3/11+wTePAmk/hmYbBmj8ieMrDlzT/4WGPwrb6Xkmsng6qpiGOFZYRDOWyMJ8UCfTP OM+9fen4P7Wq/4BlUWepvth7q9ayVUE+Oah2kVXQYukTP0S9lZJ66dpDqJiUIAbr8d lgP0wb2xzUzELODuzeRTgCJgpOv150zA3F9/ZEiTLgxauvwX7UFtWtsanzVKvu18sk ucYKHMl2Y4gbw== Received: by mail-ed1-f69.google.com with SMTP id w23-20020a50d797000000b00406d33c039dso167389edi.11 for ; Wed, 26 Jan 2022 10:59:26 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:from:to:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=+Rr1qbIwoOK9b9H/AxMUza07pBV16meHF81A+tuAjn0=; b=nX+L2CSRcNy4znBbz5sPQu/sWuVXb/TMiiR9kummIRlLfUk85+dh9BI7U7CLLCOVmc XPCTwae7Ci27Nm9KbPL3MI8cfPU8zh6MshZNnbt2MvU+peJYzKKiJruSBH4VZIDmjj2X 0yPeNGqj1buZ2Du0qjcriadhx8wTEwGWqLNghkneyH0LkSSNJ4rD24XOnNRK0U5WOatE 5mUBZWSmvNcDo3aOqxmT4cBcH/d8KcErCAtLm3dthOj00FdZ5F65bflxl0ozFm4EAAhA 8h0OPGMcIMKgU9VfrRGh/Xy/tncY/ZL2Js2PgjiMPXMK0iblxBfIxCSxoSzEIMbv9r6V R6eg== X-Gm-Message-State: AOAM533BGEXyxigClRS4i4s96OrRrJLPBoefCjiT006HzVI8TmlPc6tu SVmwSCGtzYzPwpt2wu3XUDeTjR/kC9lG46zyEY4tTPj4e1pzGjUvyyvp/VuPyYMAQuJZiKCcaqw t/v2HaukxarpM8vSoOG3o0EiJ2CwfFNsFfQGaJycThg== X-Received: by 2002:a05:6402:524d:: with SMTP id t13mr419201edd.260.1643223565932; Wed, 26 Jan 2022 10:59:25 -0800 (PST) X-Google-Smtp-Source: ABdhPJzYf8CGzdY9BQV9fWfDuwoqAkpP6AZF8Hu8PGuTYmPUgpsfXoKfhuJhA4fO0AyQY3+Hq3youA== X-Received: by 2002:a05:6402:524d:: with SMTP id t13mr419187edd.260.1643223565630; Wed, 26 Jan 2022 10:59:25 -0800 (PST) Received: from localhost.localdomain (xdsl-188-155-168-84.adslplus.ch. [188.155.168.84]) by smtp.gmail.com with ESMTPSA id u18sm7767903eje.37.2022.01.26.10.59.25 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 26 Jan 2022 10:59:25 -0800 (PST) From: Krzysztof Kozlowski To: kernel-team@lists.ubuntu.com Subject: [J/realtime][PATCH 13/15] rtla: Add rtla timerlat top documentation Date: Wed, 26 Jan 2022 19:58:10 +0100 Message-Id: <20220126185812.300679-14-krzysztof.kozlowski@canonical.com> X-Mailer: git-send-email 2.32.0 In-Reply-To: <20220126185812.300679-1-krzysztof.kozlowski@canonical.com> References: <20220126185812.300679-1-krzysztof.kozlowski@canonical.com> MIME-Version: 1.0 X-BeenThere: kernel-team@lists.ubuntu.com X-Mailman-Version: 2.1.20 Precedence: list List-Id: Kernel team discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: kernel-team-bounces@lists.ubuntu.com Sender: "kernel-team" From: Daniel Bristot de Oliveira BugLink: https://bugs.launchpad.net/bugs/1959130 Man page for rtla timerlat top mode. Link: https://lkml.kernel.org/r/58c3d6212e6c6f1f012deb2e998dd082da92075f.1639158831.git.bristot@kernel.org Cc: Tao Zhou Cc: Ingo Molnar Cc: Tom Zanussi Cc: Masami Hiramatsu Cc: Juri Lelli Cc: Clark Williams Cc: John Kacur Cc: Peter Zijlstra Cc: Thomas Gleixner Cc: Sebastian Andrzej Siewior Cc: Daniel Bristot de Oliveira Cc: linux-rt-users@vger.kernel.org Cc: linux-trace-devel@vger.kernel.org Cc: linux-kernel@vger.kernel.org Signed-off-by: Daniel Bristot de Oliveira Signed-off-by: Steven Rostedt (cherry picked from commit df337d014b573fe567cd190753a4f5fa69281870) Signed-off-by: Krzysztof Kozlowski --- .../tools/rtla/common_timerlat_options.rst | 16 ++ .../tools/rtla/rtla-timerlat-top.rst | 145 ++++++++++++++++++ 2 files changed, 161 insertions(+) create mode 100644 Documentation/tools/rtla/common_timerlat_options.rst create mode 100644 Documentation/tools/rtla/rtla-timerlat-top.rst diff --git a/Documentation/tools/rtla/common_timerlat_options.rst b/Documentation/tools/rtla/common_timerlat_options.rst new file mode 100644 index 000000000000..e9c1bfd55d48 --- /dev/null +++ b/Documentation/tools/rtla/common_timerlat_options.rst @@ -0,0 +1,16 @@ +**-p**, **--period** *us* + + Set the *timerlat* tracer period in microseconds. + +**-i**, **--irq** *us* + + Stop trace if the *IRQ* latency is higher than the argument in us. + +**-T**, **--thread** *us* + + Stop trace if the *Thread* latency is higher than the argument in us. + +**-s**, **--stack** *us* + + Save the stack trace at the *IRQ* if a *Thread* latency is higher than the + argument in us. diff --git a/Documentation/tools/rtla/rtla-timerlat-top.rst b/Documentation/tools/rtla/rtla-timerlat-top.rst new file mode 100644 index 000000000000..1c321de1c171 --- /dev/null +++ b/Documentation/tools/rtla/rtla-timerlat-top.rst @@ -0,0 +1,145 @@ +==================== +rtla-timerlat-top +==================== +------------------------------------------- +Measures the operating system timer latency +------------------------------------------- + +:Manual section: 1 + +SYNOPSIS +======== +**rtla timerlat top** [*OPTIONS*] ... + +DESCRIPTION +=========== + +.. include:: common_timerlat_description.rst + +The **rtla timerlat top** displays a summary of the periodic output +from the *timerlat* tracer. It also provides information for each +operating system noise via the **osnoise:** tracepoints that can be +seem with the option **-T**. + +OPTIONS +======= + +.. include:: common_timerlat_options.rst + +.. include:: common_top_options.rst + +.. include:: common_options.rst + +EXAMPLE +======= + +In the example below, the *timerlat* tracer is set to capture the stack trace at +the IRQ handler, printing it to the buffer if the *Thread* timer latency is +higher than *30 us*. It is also set to stop the session if a *Thread* timer +latency higher than *30 us* is hit. Finally, it is set to save the trace +buffer if the stop condition is hit:: + + [root@alien ~]# rtla timerlat top -s 30 -t 30 -T + Timer Latency + 0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us) + CPU COUNT | cur min avg max | cur min avg max + 0 #58634 | 1 0 1 10 | 11 2 10 23 + 1 #58634 | 1 0 1 9 | 12 2 9 23 + 2 #58634 | 0 0 1 11 | 10 2 9 23 + 3 #58634 | 1 0 1 11 | 11 2 9 24 + 4 #58634 | 1 0 1 10 | 11 2 9 26 + 5 #58634 | 1 0 1 8 | 10 2 9 25 + 6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike + 7 #58634 | 1 0 1 9 | 11 2 9 23 + 8 #58633 | 1 0 1 9 | 11 2 9 26 + 9 #58633 | 1 0 1 9 | 10 2 9 26 + 10 #58633 | 1 0 1 13 | 11 2 9 28 + 11 #58633 | 1 0 1 13 | 12 2 9 24 + 12 #58633 | 1 0 1 8 | 10 2 9 23 + 13 #58633 | 1 0 1 10 | 10 2 9 22 + 14 #58633 | 1 0 1 18 | 12 2 9 27 + 15 #58633 | 1 0 1 10 | 11 2 9 28 + 16 #58633 | 0 0 1 11 | 7 2 9 26 + 17 #58633 | 1 0 1 13 | 10 2 9 24 + 18 #58633 | 1 0 1 9 | 13 2 9 22 + 19 #58633 | 1 0 1 10 | 11 2 9 23 + 20 #58633 | 1 0 1 12 | 11 2 9 28 + 21 #58633 | 1 0 1 14 | 11 2 9 24 + 22 #58633 | 1 0 1 8 | 11 2 9 22 + 23 #58633 | 1 0 1 10 | 11 2 9 27 + timerlat hit stop tracing + saving trace to timerlat_trace.txt + [root@alien bristot]# tail -60 timerlat_trace.txt + [...] + timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns + sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns + sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns + sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns + timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns + timerlat/6-79756 [006] ....1.. 426.271265: + => timerlat_irq + => __hrtimer_run_queues + => hrtimer_interrupt + => __sysvec_apic_timer_interrupt + => sysvec_apic_timer_interrupt + => asm_sysvec_apic_timer_interrupt + => _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt. + => try_to_wake_up + => autoremove_wake_function + => __wake_up_common + => __wake_up_common_lock + => ep_poll_callback + => __wake_up_common + => __wake_up_common_lock + => fsnotify_add_event + => inotify_handle_inode_event + => fsnotify + => __fsnotify_parent + => __fput + => task_work_run + => exit_to_user_mode_prepare + => syscall_exit_to_user_mode + => do_syscall_64 + => entry_SYSCALL_64_after_hwframe + => 0x7265000001378c + => 0x10000cea7 + => 0x25a00000204a + => 0x12e302d00000000 + => 0x19b51010901b6 + => 0x283ce00726500 + => 0x61ea308872 + => 0x00000fe3 + bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns + timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6 + +In the trace, it is possible the notice that the *IRQ* timer latency was +already high, accounting *12505 ns*. The IRQ delay was caused by the +*bash-109109* process that disabled IRQs in the wake-up path +(*_try_to_wake_up()* function). The duration of the IRQ handler that woke +up the timerlat thread, informed with the **osnoise:irq_noise** event, was +also high and added more *12553 ns* to the Thread latency. Finally, the +**osnoise:thread_noise** added by the currently running thread (including +the scheduling overhead) added more *4769 ns*. Summing up these values, +the *Thread* timer latency accounted for *30328 ns*. + +The primary reason for this high value is the wake-up path that was hit +twice during this case: when the *bash-109109* was waking up a thread +and then when the *timerlat* thread was awakened. This information can +then be used as the starting point of a more fine-grained analysis. + +Note that **rtla timerlat** was dispatched without changing *timerlat* tracer +threads' priority. That is generally not needed because these threads hava +priority *FIFO:95* by default, which is a common priority used by real-time +kernel developers to analyze scheduling delays. + +SEE ALSO +-------- +**rtla-timerlat**\(1), **rtla-timerlat-hist**\(1) + +*timerlat* tracer documentation: + +AUTHOR +------ +Written by Daniel Bristot de Oliveira + +.. include:: common_appendix.rst