From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.8 required=3.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,MAILING_LIST_MULTI, SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED autolearn=unavailable autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id EA42DC433E6 for ; Tue, 29 Dec 2020 19:42:54 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id AE44920867 for ; Tue, 29 Dec 2020 19:42:54 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726258AbgL2Tmj (ORCPT ); Tue, 29 Dec 2020 14:42:39 -0500 Received: from mail-oi1-f169.google.com ([209.85.167.169]:40865 "EHLO mail-oi1-f169.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726111AbgL2Tmi (ORCPT ); Tue, 29 Dec 2020 14:42:38 -0500 Received: by mail-oi1-f169.google.com with SMTP id p5so15687508oif.7; Tue, 29 Dec 2020 11:42:22 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=vCQe4wi6BS3tX0tzI09pDeYN8axsFGNQEB3OCiXr8sw=; b=EVkLrdg6z7cqmsAGxbkE3ZZccBMH5WdjUY/83dPmZvzOlJajGmyBsmXqQSyA2OdKrO xBqvdVvCRczgfjcbfsf+SgcAyK1i+nZh3usH1NTv7t8E2KM+KNd1UE9GLVryk433u/nW g4kcbcyoOE6TsE0oyBzXlBUuiU6bQLHfBHsyxZIw/faHrquu0Qp6jTCvGCs2q0YDvlC1 +sLVH+NjOKNWDlIhOmTq1gJBCshV8mW565gXavZI5b0gdQosYE65qLgSk7+/kutppHAa mkOUrF1i6U/9pbT6uvot4xwry9njmwTmdmZO/ohfeKfYL+CE3PsyRFO6ILpIzHSP5qQU qKMA== X-Gm-Message-State: AOAM5305ceqeKUwQRu+cIX2T2Uj27xU7TkvmqY2Zxg0PHmYPoPIfdeqX w99+eUglck1S/ZxHR4XIP48lAC3RBHPoCoFx/Tw= X-Google-Smtp-Source: ABdhPJyYeYmNS3uORHuhWP0YeMOl5M3apgVxsQG8MVEjZoiEl8XSEZ4gzS5C9+lw/HkcFJ0LrhWKaDE1rDMYLvmI92s= X-Received: by 2002:aca:4b16:: with SMTP id y22mr3266129oia.148.1609270917016; Tue, 29 Dec 2020 11:41:57 -0800 (PST) MIME-Version: 1.0 References: <20201206214613.444124194@linutronix.de> <20201206220542.062910520@linutronix.de> In-Reply-To: <20201206220542.062910520@linutronix.de> From: Geert Uytterhoeven Date: Tue, 29 Dec 2020 20:41:46 +0100 Message-ID: Subject: Re: [patch 5/8] ntp: Make the RTC synchronization more reliable To: Thomas Gleixner Cc: LKML , Alexandre Belloni , Jason Gunthorpe , Miroslav Lichvar , John Stultz , Prarit Bhargava , Alessandro Zummo , linux-rtc@vger.kernel.org, Peter Zijlstra , Wolfram Sang , Linux-Renesas Content-Type: text/plain; charset="UTF-8" Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi Thomas, On Sun, Dec 6, 2020 at 11:10 PM Thomas Gleixner wrote: > Miroslav reported that the periodic RTC synchronization in the NTP code > fails more often than not to hit the specified update window. > > The reason is that the code uses delayed_work to schedule the update which > needs to be in thread context as the underlying RTC might be connected via > a slow bus, e.g. I2C. In the update function it verifies whether the > current time is correct vs. the requirements of the underlying RTC. > > But delayed_work is using the timer wheel for scheduling which is > inaccurate by design. Depending on the distance to the expiry the wheel > gets less granular to allow batching and to avoid the cascading of the > original timer wheel. See 500462a9de65 ("timers: Switch to a non-cascading > wheel") and the code for further details. > > The code already deals with this by splitting the 660 seconds period into a > long 659 seconds timer and then retrying with a smaller delta. > > But looking at the actual granularities of the timer wheel (which depend on > the HZ configuration) the 659 seconds timer ends up in an outer wheel level > and is affected by a worst case granularity of: > > HZ Granularity > 1000 32s > 250 16s > 100 40s > > So the initial timer can be already off by max 12.5% which is not a big > issue as the period of the sync is defined as ~11 minutes. > > The fine grained second attempt schedules to the desired update point with > a timer expiring less than a second from now. Depending on the actual delta > and the HZ setting even the second attempt can end up in outer wheel levels > which have a large enough granularity to make the correctness check fail. > > As this is a fundamental property of the timer wheel there is no way to > make this more accurate short of iterating in one jiffies steps towards the > update point. > > Switch it to an hrtimer instead which schedules the actual update work. The > hrtimer will expire precisely (max 1 jiffie delay when high resolution > timers are not available). The actual scheduling delay of the work is the > same as before. > > The update is triggered from do_adjtimex() which is a bit racy but not much > more racy than it was before: > > if (ntp_synced()) > queue_delayed_work(system_power_efficient_wq, &sync_work, 0); > > which is racy when the work is currently executed and has not managed to > reschedule itself. > > This becomes now: > > if (ntp_synced() && !hrtimer_is_queued(&sync_hrtimer)) > queue_work(system_power_efficient_wq, &sync_work, 0); > > which is racy when the hrtimer has expired and the work is currently > executed and has not yet managed to rearm the hrtimer. > > Not a big problem as it just schedules work for nothing. > > The new implementation has a safe guard in place to catch the case where > the hrtimer is queued on entry to the work function and avoids an extra > update attempt of the RTC that way. > > Reported-by: Miroslav Lichvar > Signed-off-by: Thomas Gleixner Thanks for your patch, which is now commit c9e6189fb03123a7 ("ntp: Make the RTC synchronization more reliable"). Since this commit, the I2C RTC on the R-Car M2-W Koelsch development board is accessed every two seconds. Sticking a WARN() in the I2C activation path gives e.g. Modules linked in: CPU: 0 PID: 12 Comm: kworker/0:1 Not tainted 5.10.0-rc1-koelsch-00038-gc9e6189fb031-dirty #1021 Hardware name: Generic R-Car Gen2 (Flattened Device Tree) Workqueue: events rtc_timer_do_work [] (unwind_backtrace) from [] (show_stack+0x10/0x14) [] (show_stack) from [] (dump_stack+0xa0/0xc8) [] (dump_stack) from [] (__warn+0xbc/0xfc) [] (__warn) from [] (warn_slowpath_fmt+0x78/0xb0) [] (warn_slowpath_fmt) from [] (cpg_mstp_clock_endisable+0x94/0x1f4) [] (cpg_mstp_clock_endisable) from [] (clk_core_enable+0x194/0x29c) [] (clk_core_enable) from [] (clk_core_enable_lock+0x18/0x2c) [] (clk_core_enable_lock) from [] (pm_clk_resume+0x68/0xa0) [] (pm_clk_resume) from [] (genpd_runtime_resume+0xc8/0x174) [] (genpd_runtime_resume) from [] (__rpm_callback+0x30/0xe0) [] (__rpm_callback) from [] (rpm_callback+0x70/0x80) [] (rpm_callback) from [] (rpm_resume+0x438/0x4dc) [] (rpm_resume) from [] (__pm_runtime_resume+0x64/0x80) [] (__pm_runtime_resume) from [] (sh_mobile_i2c_xfer+0x38/0x554) [] (sh_mobile_i2c_xfer) from [] (__i2c_transfer+0x4e4/0x680) [] (__i2c_transfer) from [] (i2c_transfer+0x58/0xf8) [] (i2c_transfer) from [] (regmap_i2c_read+0x58/0x94) [] (regmap_i2c_read) from [] (_regmap_raw_read+0x19c/0x2f4) [] (_regmap_raw_read) from [] (_regmap_bus_read+0x44/0x68) [] (_regmap_bus_read) from [] (_regmap_read+0x84/0x1a4) [] (_regmap_read) from [] (_regmap_update_bits+0xa8/0xf4) [] (_regmap_update_bits) from [] (regmap_update_bits_base+0x4c/0x70) [] (regmap_update_bits_base) from [] (regmap_update_bits+0x18/0x20) [] (regmap_update_bits) from [] (rtc_alarm_disable+0x28/0x38) [] (rtc_alarm_disable) from [] (rtc_timer_do_work+0x88/0x294) [] (rtc_timer_do_work) from [] (process_one_work+0x308/0x524) [] (process_one_work) from [] (worker_thread+0x22c/0x2ec) [] (worker_thread) from [] (kthread+0x128/0x138) [] (kthread) from [] (ret_from_fork+0x14/0x28) Exception stack(0xc220ffb0 to 0xc220fff8) ffa0: 00000000 00000000 00000000 00000000 ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffe0: 00000000 00000000 00000000 00000000 00000013 00000000 irq event stamp: 74448 hardirqs last enabled at (74447): [] seqcount_lockdep_reader_access.constprop.0+0x58/0x68 hardirqs last disabled at (74448): [] _raw_spin_lock_irqsave+0x20/0x70 softirqs last enabled at (74360): [] __do_softirq+0x1b8/0x468 softirqs last disabled at (74353): [] __irq_exit_rcu+0x110/0x17c ---[ end trace 8c279400e5758606 ]--- Before, the synchronization happened only every 696s. Worse, this synchronization may also happen while the system is partly suspended, sometimes triggering a WARNING during resume from s2ram: Disabling non-boot CPUs ... Enabling non-boot CPUs ... +------------[ cut here ]------------ +WARNING: CPU: 0 PID: 21 at drivers/i2c/i2c-core.h:54 __i2c_transfer+0x464/0x4a0 +i2c i2c-6: Transfer while suspended +CPU: 0 PID: 21 Comm: kworker/0:1 Not tainted 5.11.0-rc1-shmobile-00107-gcf9760aa181f #829 +Hardware name: Generic R-Car Gen2 (Flattened Device Tree) +Workqueue: events_power_efficient sync_hw_clock +[] (unwind_backtrace) from [] (show_stack+0x10/0x14) +[] (show_stack) from [] (dump_stack+0x8c/0xa8) +[] (dump_stack) from [] (__warn+0xc0/0xec) +[] (__warn) from [] (warn_slowpath_fmt+0x78/0xb0) +[] (warn_slowpath_fmt) from [] (__i2c_transfer+0x464/0x4a0) +[] (__i2c_transfer) from [] (i2c_transfer+0x58/0xf8) +[] (i2c_transfer) from [] (regmap_i2c_read+0x58/0x94) +[] (regmap_i2c_read) from [] (_regmap_raw_read+0x108/0x1bc) +[] (_regmap_raw_read) from [] (_regmap_bus_read+0x44/0x68) +[] (_regmap_bus_read) from [] (_regmap_read+0x84/0x100) +[] (_regmap_read) from [] (_regmap_update_bits+0xa8/0xf4) +[] (_regmap_update_bits) from [] (_regmap_select_page+0xe4/0x100) +[] (_regmap_select_page) from [] (_regmap_raw_write_impl+0xd4/0x608) +[] (_regmap_raw_write_impl) from [] (_regmap_raw_write+0xd8/0x114) +[] (_regmap_raw_write) from [] (regmap_raw_write+0x58/0x7c) +[] (regmap_raw_write) from [] (regmap_bulk_write+0x118/0x13c) +[] (regmap_bulk_write) from [] (da9063_rtc_set_time+0x44/0x8c) +[] (da9063_rtc_set_time) from [] (rtc_set_time+0x8c/0x15c) +[] (rtc_set_time) from [] (sync_hw_clock+0x12c/0x210) +[] (sync_hw_clock) from [] (process_one_work+0x1bc/0x2ac) +[] (process_one_work) from [] (worker_thread+0x22c/0x2d0) +[] (worker_thread) from [] (kthread+0x100/0x10c) +[] (kthread) from [] (ret_from_fork+0x14/0x24) +Exception stack(0xc1195fb0 to 0xc1195ff8) +5fa0: 00000000 00000000 00000000 00000000 +5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 +5fe0: 00000000 00000000 00000000 00000000 00000013 00000000 +---[ end trace 5d3a7a10ee0cec3d ]--- +da9063-rtc da9063-rtc: Failed to set RTC time data: -108 +da9063-rtc da9063-rtc: Failed to read RTC time data: -108 CPU1 is up The latter is probably a pre-existing issue, just more likely to trigger now the sync interval is 2s. Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds