| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <2b732d25-63e7-40f7-8d66-b1e6dc0b701d@roeck-us.net> Date: Fri, 29 Nov 2024 08:09:17 -0800 From: Guenter Roeck <linux@...ck-us.net> To: Thomas Gleixner <tglx@...utronix.de>, John Stultz <jstultz@...gle.com> Cc: LKML <linux-kernel@...r.kernel.org>, Anna-Maria Behnsen <anna-maria@...utronix.de>, Frederic Weisbecker <frederic@...nel.org>, Stephen Boyd <sboyd@...nel.org>, Peter Zijlstra <peterz@...radead.org> Subject: Re: [patch 2/2] timekeeping: Always check for negative motion On 11/29/24 04:16, Thomas Gleixner wrote: > On Thu, Nov 28 2024 at 07:30, Guenter Roeck wrote: >> On 11/28/24 06:51, Thomas Gleixner wrote: >> [ 19.090000] ###### now: b5ac62 last: d447e38 mask: ffffff return: 712e2a >> [ 19.110000] ###### now: b9ebc3 last: db506d0 mask: ffffff return: 4e4f3 >> [ 19.120000] ###### now: bb842f last: db8d760 mask: ffffff return: 2accf >> [ 19.160000] ###### now: c43f2e last: dbabfa8 mask: ffffff return: 97f86 >> >> 'last' advances beyond 'mask', and after that the result is always bad. The call to >> clocksource_delta() is from timekeeping_advance(). > > This does not make any sense. The bits above the mask in cycle_last are > irrelevant: > > delta = (now - last) & mask; > >> [ 3.350000] ###### now: 6c4f last: fe6a84 mask: ffffff return: 201cb <--- >> [ 3.360000] ###### now: 40427 last: 10052cc mask: ffffff return: 3b15b <--- > > 0x40427 - 0x10052cc = 0xffffffffff03b15b > 0xffffffffff03b15b & 0xffffff = 0x3b15b > > That's not any different than before. The only difference is that the > return value is checked: > > return delta & ~(mask >> 1) ? 0 : delta; > > But clearly none of the resulting deltas (after masking) has bit 23 > set. So the function can't return 0, right? > > Coming back to my earlier assumption vs. the max idle time. Here is a > long idle sleep: > >> [ 18.500000] ###### now: 45b0a2 last: d1c7050 mask: ffffff return: 294052 >> [ 19.090000] ###### now: b5ac62 last: d447e38 mask: ffffff return: 712e2a > > The cycle interval is 125000 clock cycles per tick. That's a HZ=100 > kernel, so the nominal clock frequency is 12.5 MHz. > > 0x712e2a/12.5e6 = 0.593391s > > which is close to the 597268854ns max_idle_ns value. > > That's about 0.0776978s away from the point where the delta becomes > > mask/2. So there is a valid concern vs. these long idle sleeps on > machines with a small counter width. > > But none of this explains the problems you are observing. > > Can you instrument clocksource_delta() to print the values only when the > negative motion detection triggers? > With added WARN_ONCE() after the problem is seen for the first time: [ 13.860000] ##### now=0xd60127 last=0x85170f4 mask=0xffffff ret=0x849033 [ 13.860000] ------------[ cut here ]------------ [ 13.860000] WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping_internal.h:44 timekeeping_advance+0x844/0x9d0 [ 13.860000] clocksource_delta() time going backward: now=0xd60127 last=0x85170f4 mask=0xffffff ret=0x849033 [ 13.860000] Modules linked in: [ 13.860000] CPU: 0 UID: 0 PID: 0 Comm: swapper/0 Not tainted 6.12.0-10689-g7af08b57bcb9-dirty #1 [ 13.860000] Hardware name: Generic DT based system [ 13.860000] Call trace: [ 13.860000] unwind_backtrace from show_stack+0x10/0x14 [ 13.860000] show_stack from dump_stack_lvl+0x64/0x88 [ 13.860000] dump_stack_lvl from __warn+0x7c/0x1ac [ 13.860000] __warn from warn_slowpath_fmt+0x130/0x1a4 [ 13.860000] warn_slowpath_fmt from timekeeping_advance+0x844/0x9d0 [ 13.860000] timekeeping_advance from update_wall_time+0xc/0x1c [ 13.860000] update_wall_time from tick_irq_enter+0x6c/0xb0 [ 13.860000] tick_irq_enter from generic_handle_arch_irq+0xc/0x44 [ 13.860000] generic_handle_arch_irq from __irq_svc+0x88/0xb0 [ 13.860000] Exception stack(0xc2201f28 to 0xc2201f70) [ 13.860000] 1f20: 00000001 2d639000 c220da80 00000001 c220da80 c2208f14 [ 13.860000] 1f40: c24af000 c2208f54 00000000 00000000 00000097 00000000 c2208f14 c2201f78 [ 13.860000] 1f60: c1568504 c1568488 20000013 ffffffff [ 13.860000] __irq_svc from default_idle_call+0x1c/0x1bc [ 13.860000] default_idle_call from do_idle+0x200/0x288 [ 13.860000] do_idle from cpu_startup_entry+0x28/0x2c [ 13.860000] cpu_startup_entry from kernel_init+0x0/0x12c [ 13.860000] kernel_init from start_kernel+0x6a8/0x6c4 [ 13.860000] ---[ end trace 0000000000000000 ]--- [ 13.870000] ##### now=0xd747fa last=0x85170f4 mask=0xffffff ret=0x85d706 [ 13.880000] ##### now=0xda5bf3 last=0x85170f4 mask=0xffffff ret=0x88eaff [ 13.890000] ##### now=0xdb1868 last=0x85170f4 mask=0xffffff ret=0x89a774 [ 13.940000] ##### now=0xe541ba last=0x85170f4 mask=0xffffff ret=0x93d0c6 [ 13.950000] ##### now=0xe63e66 last=0x85170f4 mask=0xffffff ret=0x94cd72 [ 13.950000] platform iio-hwmon: deferred probe pending: iio_hwmon: Failed to get channels [ 13.960000] ##### now=0xe863a8 last=0x85170f4 mask=0xffffff ret=0x96f2b4 [ 13.970000] ##### now=0xeba3a3 last=0x85170f4 mask=0xffffff ret=0x9a32af [ 13.980000] ##### now=0xec1406 last=0x85170f4 mask=0xffffff ret=0x9aa312 [ 13.990000] ##### now=0xef85a4 last=0x85170f4 mask=0xffffff ret=0x9e14b0 [ 14.000000] ##### now=0xf0f07b last=0x85170f4 mask=0xffffff ret=0x9f7f87 [ 14.010000] ##### now=0xf1bff6 last=0x85170f4 mask=0xffffff ret=0xa04f02 [ 14.150000] ##### now=0xc609c last=0x85170f4 mask=0xffffff ret=0xbaefa8 [ 14.360000] ##### now=0x357f2d last=0x85170f4 mask=0xffffff ret=0xe40e39 [ 14.410000] ##### now=0x3e0a3a last=0x85170f4 mask=0xffffff ret=0xec9946 [ 14.420000] ##### now=0x3fed36 last=0x85170f4 mask=0xffffff ret=0xee7c42 [ 14.430000] ##### now=0x42b58a last=0x85170f4 mask=0xffffff ret=0xf14496 [ 14.440000] ##### now=0x44ba17 last=0x85170f4 mask=0xffffff ret=0xf34923 [ 14.450000] ##### now=0x46635e last=0x85170f4 mask=0xffffff ret=0xf4f26a [ 14.480000] ##### now=0x4bd58e last=0x85170f4 mask=0xffffff ret=0xfa649a [ 14.490000] ##### now=0x4d3b0c last=0x85170f4 mask=0xffffff ret=0xfbca18 [ 14.510000] ##### now=0x510ef4 last=0x85170f4 mask=0xffffff ret=0xff9e00 With more context (printing for each call to clocksource_delta() as well as the actual return value): [ 14.020000] ##### now=0x165aa2 last=0x913b49f mask=0xffffff ret=0x2a603 -> 0x2a603 [ 14.030000] ##### now=0x18aa49 last=0x9159ce7 mask=0xffffff ret=0x30d62 -> 0x30d62 [ 14.040000] ##### now=0x1a2971 last=0x917852f mask=0xffffff ret=0x2a442 -> 0x2a442 [ 14.050000] ##### now=0x1c78d5 last=0x9196d77 mask=0xffffff ret=0x30b5e -> 0x30b5e [ 14.060000] ##### now=0x1dfe88 last=0x91b55bf mask=0xffffff ret=0x2a8c9 -> 0x2a8c9 [ 14.090000] ##### now=0x236d57 last=0x91d3e07 mask=0xffffff ret=0x62f50 -> 0x62f50 [ 14.180000] ##### now=0x34aaa3 last=0x922f6df mask=0xffffff ret=0x11b3c4 -> 0x11b3c4 [ 14.890000] ##### now=0xbd0aad last=0x9342167 mask=0xffffff ret=0x88e946 -> 0x0 [ 14.890000] ------------[ cut here ]------------ [ 14.890000] WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping_internal.h:44 clocksource_delta+0x108/0x118 [ 14.890000] clocksource_delta() time going backward: now=0xbd0aad last=0x9342167 mask=0xffffff ret=0x88e946 [ 14.890000] Modules linked in: [ 14.890000] CPU: 0 UID: 0 PID: 0 Comm: swapper/0 Not tainted 6.12.0-10689-g7af08b57bcb9-dirty #1 [ 14.890000] Hardware name: Generic DT based system [ 14.890000] Call trace: [ 14.890000] unwind_backtrace from show_stack+0x10/0x14 [ 14.890000] show_stack from dump_stack_lvl+0x64/0x88 [ 14.890000] dump_stack_lvl from __warn+0x7c/0x1ac [ 14.890000] __warn from warn_slowpath_fmt+0x130/0x1a4 [ 14.890000] warn_slowpath_fmt from clocksource_delta+0x108/0x118 [ 14.890000] clocksource_delta from timekeeping_advance+0x6c/0x8e4 [ 14.890000] timekeeping_advance from update_wall_time+0xc/0x1c [ 14.890000] update_wall_time from tick_irq_enter+0x6c/0xb0 [ 14.890000] tick_irq_enter from generic_handle_arch_irq+0xc/0x44 [ 14.890000] generic_handle_arch_irq from __irq_svc+0x88/0xb0 [ 14.890000] Exception stack(0xc2201f28 to 0xc2201f70) [ 14.890000] 1f20: 00000001 2d639000 c220da80 00000001 c220da80 c2208f14 [ 14.890000] 1f40: c24af000 c2208f54 00000000 00000000 00000091 00000000 c2208f14 c2201f78 [ 14.890000] 1f60: c15684c4 c1568448 20000013 ffffffff [ 14.890000] __irq_svc from default_idle_call+0x1c/0x1bc [ 14.890000] default_idle_call from do_idle+0x200/0x288 [ 14.890000] do_idle from cpu_startup_entry+0x28/0x2c [ 14.890000] cpu_startup_entry from kernel_init+0x0/0x12c [ 14.890000] kernel_init from start_kernel+0x6a8/0x6c4 [ 14.890000] ---[ end trace 0000000000000000 ]--- [ 14.900000] ##### now=0xbdfc5c last=0x9342167 mask=0xffffff ret=0x89daf5 -> 0x0 [ 14.950000] ##### now=0xc8827a last=0x9342167 mask=0xffffff ret=0x946113 -> 0x0 [ 15.060000] ##### now=0xdc3907 last=0x9342167 mask=0xffffff ret=0xa817a0 -> 0x0 [ 15.110000] ##### now=0xe6b484 last=0x9342167 mask=0xffffff ret=0xb2931d -> 0x0 Sent SIGKILL to all processes Requesting system reboot [ 15.120000] ##### now=0xe7fd9a last=0x9342167 mask=0xffffff ret=0xb3dc33 -> 0x0 [ 15.170000] ##### now=0xf277d5 last=0x9342167 mask=0xffffff ret=0xbe566e -> 0x0 [ 15.260000] ##### now=0x26c10 last=0x9342167 mask=0xffffff ret=0xce4aa9 -> 0x0 [ 15.310000] ##### now=0xce799 last=0x9342167 mask=0xffffff ret=0xd8c632 -> 0x0 So, yes, it looks like the problem is seen after a large delta, and persists from there. Guenter
Powered by blists - more mailing lists