From nobody Sun Apr 19 23:31:55 2026 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 07300C433EF for ; Fri, 24 Jun 2022 07:21:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S230120AbiFXHVr (ORCPT ); Fri, 24 Jun 2022 03:21:47 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:49424 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229441AbiFXHVq (ORCPT ); Fri, 24 Jun 2022 03:21:46 -0400 X-Greylist: delayed 64 seconds by postgrey-1.37 at lindbergh.monkeyblade.net; Fri, 24 Jun 2022 00:21:45 PDT Received: from esa6.hc1455-7.c3s2.iphmx.com (esa6.hc1455-7.c3s2.iphmx.com [68.232.139.139]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 3ABCB699A2 for ; Fri, 24 Jun 2022 00:21:45 -0700 (PDT) X-IronPort-AV: E=McAfee;i="6400,9594,10387"; a="78291326" X-IronPort-AV: E=Sophos;i="5.92,218,1650898800"; d="scan'208";a="78291326" Received: from unknown (HELO yto-r2.gw.nic.fujitsu.com) ([218.44.52.218]) by esa6.hc1455-7.c3s2.iphmx.com with ESMTP; 24 Jun 2022 16:20:39 +0900 Received: from yto-m1.gw.nic.fujitsu.com (yto-nat-yto-m1.gw.nic.fujitsu.com [192.168.83.64]) by yto-r2.gw.nic.fujitsu.com (Postfix) with ESMTP id 5D014D624C for ; Fri, 24 Jun 2022 16:20:38 +0900 (JST) Received: from m3002.s.css.fujitsu.com (msm3.b.css.fujitsu.com [10.128.233.104]) by yto-m1.gw.nic.fujitsu.com (Postfix) with ESMTP id B23573C681 for ; Fri, 24 Jun 2022 16:20:37 +0900 (JST) Received: from localhost.localdomain (unknown [10.125.5.220]) by m3002.s.css.fujitsu.com (Postfix) with ESMTP id 9506C2020B09; Fri, 24 Jun 2022 16:20:37 +0900 (JST) From: Rei Yamamoto To: tglx@linutronix.de Cc: geert+renesas@glider.be, linux-kernel@vger.kernel.org, yamamoto.rei@jp.fujitsu.com Subject: [PATCH] hrtimer: CPU and entry_time is added to a warning message in hrtimer_interrupt() Date: Fri, 24 Jun 2022 16:00:11 +0900 Message-Id: <20220624070011.128234-1-yamamoto.rei@jp.fujitsu.com> X-Mailer: git-send-email 2.27.0 In-Reply-To: <87h77lhkzh.ffs@tglx> References: <87h77lhkzh.ffs@tglx> MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable X-TM-AS-GCONF: 00 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Type: text/plain; charset="utf-8" A warning message in hrtimer_interrupt() is output up to 5 times by default, and CPU and entry_time are also shown. These changes are helpful that the function spending a lot of time is clear by using ftrace: ----- dmesg : [ 1462.836971] start repro_hrtimer_interrupt [ 1462.836976] test_handler =3D test_handler [repro] 0xffff9788f7bb3048 : [ 1462.879117] hrtimer: CPU 7, entry_time =3D 1462807264840, interrupt took 60048886 ns ^^^^^ ^^^^^^^^^^^^^ cat /sys/kernel/debug/tracing/trace : -0 [007] d.h1. 1462.838075: hrtimer_expire_entry: ^^^^^ hrtimer=3D0000000041fcee42 function=3Dtest_handler [repro] now=3D1462807264= 840 ^^^^^^^^^^^^^ ----- Signed-off-by: Rei Yamamoto --- include/linux/hrtimer.h | 1 + kernel/sysctl.c | 10 ++++++++++ kernel/time/hrtimer.c | 16 +++++++++++++++- 3 files changed, 26 insertions(+), 1 deletion(-) diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h index 0ee140176f10..1a6e03b3015b 100644 --- a/include/linux/hrtimer.h +++ b/include/linux/hrtimer.h @@ -317,6 +317,7 @@ static inline int hrtimer_is_hres_active(struct hrtimer= *timer) struct clock_event_device; =20 extern void hrtimer_interrupt(struct clock_event_device *dev); +extern int sysctl_hrtimer_interrupt_warnings; =20 extern unsigned int hrtimer_resolution; =20 diff --git a/kernel/sysctl.c b/kernel/sysctl.c index e52b6e372c60..b0420d60cec9 100644 --- a/kernel/sysctl.c +++ b/kernel/sysctl.c @@ -64,6 +64,7 @@ #include #include #include +#include =20 #include "../lib/kstrtox.h" =20 @@ -2038,6 +2039,15 @@ static struct ctl_table kern_table[] =3D { .extra1 =3D SYSCTL_ONE, .extra2 =3D SYSCTL_INT_MAX, }, +#endif +#ifdef CONFIG_HIGH_RES_TIMERS + { + .procname =3D "hrtimer_interrupt_warnings", + .data =3D &sysctl_hrtimer_interrupt_warnings, + .maxlen =3D sizeof(int), + .mode =3D 0644, + .proc_handler =3D proc_dointvec, + }, #endif { } }; diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c index 0ea8702eb516..19adcbcf92e4 100644 --- a/kernel/time/hrtimer.c +++ b/kernel/time/hrtimer.c @@ -1773,6 +1773,7 @@ static __latent_entropy void hrtimer_run_softirq(stru= ct softirq_action *h) } =20 #ifdef CONFIG_HIGH_RES_TIMERS +int sysctl_hrtimer_interrupt_warnings =3D 5; =20 /* * High resolution timer interrupt @@ -1866,7 +1867,20 @@ void hrtimer_interrupt(struct clock_event_device *de= v) else expires_next =3D ktime_add(now, delta); tick_program_event(expires_next, 1); - pr_warn_once("hrtimer: interrupt took %llu ns\n", ktime_to_ns(delta)); + + /* + * If a message is output many times, the delayed funciton + * may be identified by resetting sysctl_hrtimer_interrupt_warnings + * and enabling ftrace. + */ + if (sysctl_hrtimer_interrupt_warnings) { + if (sysctl_hrtimer_interrupt_warnings > 0) + sysctl_hrtimer_interrupt_warnings--; + pr_warn("hrtimer: CPU %d, entry_time =3D %llu, " + "interrupt took %llu ns\n", + cpu_base->cpu, entry_time, + ktime_to_ns(delta)); + } } =20 /* called with interrupts disabled */ --=20 2.27.0