Received: by 2002:a05:6a10:5bc5:0:0:0:0 with SMTP id os5csp416861pxb; Wed, 27 Oct 2021 05:31:17 -0700 (PDT) X-Google-Smtp-Source: ABdhPJzP5RE3HM2NuOmeQD8HfGbII0MiboIUKqfRPMlWq/uXEi5kWcMdZrF5smR7ipu+dMT74z7x X-Received: by 2002:a17:907:3d87:: with SMTP id he7mr11500462ejc.223.1635337877193; Wed, 27 Oct 2021 05:31:17 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1635337877; cv=none; d=google.com; s=arc-20160816; b=UI6TDPP5fwVLw0IkqBYuDpZwReewWgeuGczAGWRVpaU+UwKCKADpRWhqDbFEpVPYSS NxQ8P2LnhOf1ug3tIr/fWo6jUCkTeUzoT2XSHPm2SVqMOFvZKXC+PJkV2NVfI/J5dMhV BLnRj0ybt2BkmQMQqEK79X5oJNzKm17YYaEe3g4q33P+rWpdLR7VcwJBZ8P3IGHgfTIw B9BwW2Bj3d9kfitXS8GXhRnQP4wgGmlQnyMxG2LN5Pd+O2jet37gnc4/VNsOQjKqOrO1 pPxBj6UQdA6rf3JLSrXjtfqmRxXa2N3dHrDh4XyHoPGpyOZBTorrKl3rDrN0lttsIcve pULg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:mime-version :references:in-reply-to:message-id:date:subject:cc:to:from; bh=UOUoprvYJg9eV4MjVvsK0FttVLVQK1JqDXU2f8mKCm8=; b=pX1Gs2OEvdvuFYreGQ9uCp9JnP6XXY4EMzaTcx4yO2Br4NtghCLrC1Gcin7yAdMLyy qhkoYVHxKdltF4T4FvkbEkH+sJXp+DCQvr4cVfVmwfkvVYtQViXFYObc20Byp9ZoRoGd PF+bF+AW0aDltZei3bKcdRtJdV5K51Q4ti0J9C5QnrAOnqPqakBuDPDHiTLgJeRoV9Li vlVXjmn1IEVM4tF8M1m/8hwCi/y/k+TKgg1Ln2cTmw8kHyAc4Ba5nreYeC+vQgEnIX77 h9ktD8e5tl058avRdNl1KHQZ3O+jCyE2d9+/UOlhjfeRABJASBg06/NugyfNFwrBCHmQ yuZQ== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [23.128.96.18]) by mx.google.com with ESMTP id hg3si1107196ejc.295.2021.10.27.05.30.06; Wed, 27 Oct 2021 05:31:17 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S240106AbhJZWMr convert rfc822-to-8bit (ORCPT + 99 others); Tue, 26 Oct 2021 18:12:47 -0400 Received: from us-smtp-delivery-44.mimecast.com ([205.139.111.44]:58333 "EHLO us-smtp-delivery-44.mimecast.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S240036AbhJZWL7 (ORCPT ); Tue, 26 Oct 2021 18:11:59 -0400 Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-2-5tmm8Q0qOoaH1krXjEt3sA-1; Tue, 26 Oct 2021 18:09:30 -0400 X-MC-Unique: 5tmm8Q0qOoaH1krXjEt3sA-1 Received: from smtp.corp.redhat.com (int-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.12]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 3A8B4801A85; Tue, 26 Oct 2021 22:09:28 +0000 (UTC) Received: from x1.com (unknown [10.22.32.3]) by smtp.corp.redhat.com (Postfix) with ESMTP id 9245C60BF1; Tue, 26 Oct 2021 22:09:23 +0000 (UTC) From: Daniel Bristot de Oliveira To: Steven Rostedt Cc: Tao Zhou , Daniel Bristot de Oliveira , Ingo Molnar , Tom Zanussi , Masami Hiramatsu , Juri Lelli , Clark Williams , John Kacur , Peter Zijlstra , Thomas Gleixner , Sebastian Andrzej Siewior , linux-rt-users@vger.kernel.org, linux-trace-devel@vger.kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH V6 19/20] rtla: Add rtla timerlat top documentation Date: Wed, 27 Oct 2021 00:06:30 +0200 Message-Id: In-Reply-To: References: MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.12 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=bristot@kernel.org X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: kernel.org Content-Transfer-Encoding: 8BIT Content-Type: text/plain; charset=WINDOWS-1252 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Man page for rtla timerlat top mode. Cc: Steven Rostedt 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 --- .../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 -- 2.31.1