From patchwork Fri Aug 4 15:52:11 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Daniel Bristot de Oliveira X-Patchwork-Id: 13342070 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id E4AB6C04A6A for ; Fri, 4 Aug 2023 15:52:29 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S232187AbjHDPw3 (ORCPT ); Fri, 4 Aug 2023 11:52:29 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47928 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S232176AbjHDPw2 (ORCPT ); Fri, 4 Aug 2023 11:52:28 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id B86E9170F; Fri, 4 Aug 2023 08:52:27 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 55E836207A; Fri, 4 Aug 2023 15:52:27 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 2F84FC433CA; Fri, 4 Aug 2023 15:52:25 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1691164346; bh=tPmxXhf66VncNKJK+vndDb+F6Ii3wvgP4mAYTkpL4kw=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=I1i2HxIZaHgL1mgzvBOn23KDcqn+sK9vCqus1XqEdcnDg9GTncI29cMTFaospxsQA rPSC18psAjYUQQ9VXSGT9IuNF3GD7dG6DTezEFLKv7TxYd/rcwBeSemuZCkaBU/Nlu PJim7T0MNxbpa7YJE4qrJAPVQLAdGQx4aydG11DdqSOO3hCn3waCgDXGmI/QYdCX3N 8d/b0ygvA2p+f/nhJwB+aass2JRtbkj8/lmoRbA+wgngkZ7vRJjdVx4TxpfM3tNcpe vZfnSsTrqzhh4jaEQjIma5xSV98a49NmD5jVfmn1+zOVJHtuL4uG0g88EZOCy1cTpV X0IUqGLhQhSxQ== From: Daniel Bristot de Oliveira To: linux-kernel@vger.kernel.org, linux-trace-devel@vger.kernel.org, Steven Rostedt Cc: William White , Daniel Bristot de Oliveira , Masami Hiramatsu Subject: [PATCH 1/3] rtla/timerlat_aa: Zero thread sum after every sample analysis Date: Fri, 4 Aug 2023 17:52:11 +0200 Message-Id: <97bff55b0141f2d01b47d9450a5672fde147b89a.1691162043.git.bristot@kernel.org> X-Mailer: git-send-email 2.38.1 In-Reply-To: References: MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org The thread thread_thread_sum accounts for thread interference during a single activation. It was not being zeroed, so it was accumulating thread interference over all activations. It was not that visible when timerlat was the highest priority. Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 1 + 1 file changed, 1 insertion(+) diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index e0ffe69c271c..dec5b4c4511e 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -159,6 +159,7 @@ static int timerlat_aa_irq_latency(struct timerlat_aa_data *taa_data, taa_data->thread_nmi_sum = 0; taa_data->thread_irq_sum = 0; taa_data->thread_softirq_sum = 0; + taa_data->thread_thread_sum = 0; taa_data->thread_blocking_duration = 0; taa_data->timer_irq_start_time = 0; taa_data->timer_irq_duration = 0; From patchwork Fri Aug 4 15:52:12 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Daniel Bristot de Oliveira X-Patchwork-Id: 13342071 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id EE3BDC04A6A for ; Fri, 4 Aug 2023 15:52:33 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S232215AbjHDPwc (ORCPT ); Fri, 4 Aug 2023 11:52:32 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47944 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S232212AbjHDPwb (ORCPT ); Fri, 4 Aug 2023 11:52:31 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [IPv6:2604:1380:4641:c500::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id DA2351734; Fri, 4 Aug 2023 08:52:29 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 705ED62083; Fri, 4 Aug 2023 15:52:29 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 3D2A1C433CB; Fri, 4 Aug 2023 15:52:27 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1691164348; bh=KWFM/wiu6viTEVt5MroQSNcNFMjFUslvuCwH+sOEIdY=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=guS2WrnT5Gzk/90BbYDxqcVbWMgYW8V90YnB6WynP11+/qFch/c9QWZ1cuhnuT9um aZNEXD9uliUtEE7BofkP1RRNXHkncNZgeAGKCoHGmdZbK71nGEKHnkaOO4kaxG8csm 83vMPQUb2xK2hfF1rtUjoHrADY6JeGkm0sAkSnGLdPOgBb86AHCRtPyZCCFqgzePbf hfUHPS1gP1iCjQVT4b/F1dFy5KM1YQaRpAbMXIIttrXnWmQXo2FZ3ply7eeDzAmvyG RUTMMnR4mk/X68gPXYl5Tw6DUgbojAxLyZvEv72jjymmJs4ZNYSVxiX6xfqpTSaXAQ 8reUbJiOl5Sqg== From: Daniel Bristot de Oliveira To: linux-kernel@vger.kernel.org, linux-trace-devel@vger.kernel.org, Steven Rostedt Cc: William White , Daniel Bristot de Oliveira , Masami Hiramatsu Subject: [PATCH 2/3] rtla/timerlat_aa: Fix negative IRQ delay Date: Fri, 4 Aug 2023 17:52:12 +0200 Message-Id: X-Mailer: git-send-email 2.38.1 In-Reply-To: References: MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org When estimating the IRQ timer delay, we are dealing with two different clock sources: the external clock source that timerlat uses as a reference and the clock used by the tracer. There are also two moments: the time reading the clock and the timer in which the event is placed in the buffer (the trace event timestamp). If the processor is slow or there is some hardware noise, the difference between the timestamp and the external clock, read can be longer than the IRQ handler delay, resulting in a negative time. If so, set IRQ to start delay as 0. In the end, it is less near-zero and relevant then the noise. Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index dec5b4c4511e..baf1efda0581 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -338,7 +338,23 @@ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *recor taa_data->timer_irq_start_time = start; taa_data->timer_irq_duration = duration; - taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; + /* + * We are dealing with two different clock sources: the + * external clock source that timerlat uses as a reference + * and the clock used by the tracer. There are also two + * moments: the time reading the clock and the timer in + * which the event is placed in the buffer (the trace + * event timestamp). If the processor is slow or there + * is some hardware noise, the difference between the + * timestamp and the external clock read can be longer + * than the IRQ handler delay, resulting in a negative + * time. If so, set IRQ start delay as 0. In the end, + * it is less relevant than the noise. + */ + if (expected_start < taa_data->timer_irq_start_time) + taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; + else + taa_data->timer_irq_start_delay = 0; /* * not exit from idle. From patchwork Fri Aug 4 15:52:13 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Daniel Bristot de Oliveira X-Patchwork-Id: 13342072 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 4824CC04A6A for ; Fri, 4 Aug 2023 15:52:36 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S232216AbjHDPwf (ORCPT ); Fri, 4 Aug 2023 11:52:35 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:48006 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S232221AbjHDPwd (ORCPT ); Fri, 4 Aug 2023 11:52:33 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [IPv6:2604:1380:4641:c500::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 4944B49CB; Fri, 4 Aug 2023 08:52:32 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id 82D806209C; Fri, 4 Aug 2023 15:52:31 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 51B18C433CA; Fri, 4 Aug 2023 15:52:29 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1691164351; bh=gTe7K81Fy/E2vjahMI33+dObPnl+nUbydfjT/SnxZuM=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=hQPFGtNzLnGg3aIvjUJA9gtmk2KqFUP4NGM9a9jSuQ9oWvRODlTupdKxJBokpou5K Nq4GyugvHYYwZmKbEMOSStikAyXJXWpcpjRQtkZuzPDV/DEl+d8eGW2Am9+jejQs0S uDXpEOoqWhpHpFfbpTuRMEfKeSYcWOuG7ZqX1B4ETlA+tci47Se9U1XlyFchU681s7 XWxsJhhfdkivGCPPBKM9UKJWyuCVSbLdcoiFCXlYtByjhzWpO/Ku5pjToCsyoZ/ZCr U+q+42fwMZcXqhwnHC2Vrl0FNj1ITdqHVzUiHKLIfFId9dJKPrhpRMWjEjRc8N2veA JODSip/inIsXA== From: Daniel Bristot de Oliveira To: linux-kernel@vger.kernel.org, linux-trace-devel@vger.kernel.org, Steven Rostedt Cc: William White , Daniel Bristot de Oliveira , Masami Hiramatsu Subject: [PATCH 3/3] rtla/timerlat_aa: Fix previous IRQ delay for IRQs that happens after thread sample Date: Fri, 4 Aug 2023 17:52:13 +0200 Message-Id: X-Mailer: git-send-email 2.38.1 In-Reply-To: References: MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org timerlat auto-analysis takes note of all IRQs, before or after the execution of the timerlat thread. Because we cannot go backward in the trace (we will fix it when moving to trace-cmd lib?), timerlat aa take note of the last IRQ execution in the waiting for the IRQ state, and then print it if it is executed after the expected timer IRQ starting time. After the thread sample, the timerlat starts recording the next IRQs as "previous" irq for the next occurrence. However, if an IRQ happens after the thread measurement but before the tracing stops, it is classified as a previous IRQ. That is not wrong, as it can be "previous" for the subsequent activation. What is wrong is considering it as a potential source for the last activation. Ignore the IRQ interference that happens after the IRQ starting time for now. A future improvement for timerlat can be either keeping a list of previous IRQ execution or using the trace-cmd library. Still, it requires further investigation - it is a new feature. Fixes: 27e348b221f6 ("rtla/timerlat: Add auto-analysis core") Signed-off-by: Daniel Bristot de Oliveira --- tools/tracing/rtla/src/timerlat_aa.c | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/tools/tracing/rtla/src/timerlat_aa.c b/tools/tracing/rtla/src/timerlat_aa.c index baf1efda0581..7093fd5333be 100644 --- a/tools/tracing/rtla/src/timerlat_aa.c +++ b/tools/tracing/rtla/src/timerlat_aa.c @@ -545,7 +545,7 @@ static int timerlat_aa_kworker_start_handler(struct trace_seq *s, struct tep_rec static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, int irq_thresh, int thread_thresh) { - unsigned long long exp_irq_ts; + long long exp_irq_ts; int total; int irq; @@ -562,12 +562,15 @@ static void timerlat_thread_analysis(struct timerlat_aa_data *taa_data, int cpu, /* * Expected IRQ arrival time using the trace clock as the base. + * + * TODO: Add a list of previous IRQ, and then run the list backwards. */ exp_irq_ts = taa_data->timer_irq_start_time - taa_data->timer_irq_start_delay; - - if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) - printf(" Previous IRQ interference: \t\t up to %9.2f us\n", - ns_to_usf(taa_data->prev_irq_duration)); + if (exp_irq_ts < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) { + if (taa_data->prev_irq_timstamp < taa_data->timer_irq_start_time) + printf(" Previous IRQ interference: \t\t up to %9.2f us\n", + ns_to_usf(taa_data->prev_irq_duration)); + } /* * The delay that the IRQ suffered before starting.