Message-ID: <CAE4VaGCr0L9bJ8ZUQwjhqc3DWT_z-AabMKOVZmvJm4PRR8v0qw@mail.gmail.com>
Date: Mon, 25 Aug 2025 22:04:00 +0200
From: Jirka Hladky <jhladky@...hat.com>
To: Thomas Gleixner <tglx@...utronix.de>
Cc: linux-kernel <linux-kernel@...r.kernel.org>, john.stultz@...aro.org, 
	anna-maria@...utronix.de, Philip Auld <pauld@...hat.com>, 
	Prarit Bhargava <prarit@...hat.com>, Luis Goncalves <lgoncalv@...hat.com>, 
	Miroslav Lichvar <mlichvar@...hat.com>, Luke Yang <luyang@...hat.com>, Jan Jurca <jjurca@...hat.com>, 
	Joe Mario <jmario@...hat.com>
Subject: Re: [REGRESSION] 76% performance loss in timer workloads caused by
 513793bc6ab3 "posix-timers: Make signal delivery consistent"

Let me close a loop on this one.

Colin Ian King has updated the timer test in Stress_ng accordingly:
https://github.com/ColinIanKing/stress-ng/commit/048b4cb1bbc83cee377330b20e1bd366b651e4ad

Thank you, everybody!
Jirka

On Mon, Aug 25, 2025 at 1:35 PM Jirka Hladky <jhladky@...hat.com> wrote:
>
>  Hallo Thomas,
>
> Vielen Dank for the detailed analysis, explanations, and insights. You
> are right, I fully agree with your conclusions.
>
> I apologize for reporting this as a regression. I've filed an issue
> with stress-ng: https://github.com/ColinIanKing/stress-ng/issues/560
> to request improving or documenting the stress-ng timer test
> accordingly.
>
> Liebe Grüße,
> Jirka
>
>
> On Mon, Aug 25, 2025 at 9:15 AM Thomas Gleixner <tglx@...utronix.de> wrote:
> >
> > On Sun, Aug 24 2025 at 11:44, Thomas Gleixner wrote:
> > > On Sat, Aug 16 2025 at 18:38, Jirka Hladky wrote:
> > > And this has nothing to do with timer migration or whatever, that's just
> > > a matter of correctness.
> >
> > Just to come back to timer migration. That's completely irrelevant here
> > because /proc/sys/kernel/timer_migration only affects the timer wheel
> > and _not_ hrtimers, which are used here.
> >
> > And just a few more comments about your findings:
> >
> > > grep -c hrtimer_start hrtimer*txt
> > > 6.12: 10898132
> > > 6.13: 17105314
> > >
> > > grep -c hrtimer_expire_entry hrtimer-6.12.0-33.el10.x86_64.txt
> > > hrtimer-6.13.0-0.rc2.22.eln144.x86_64.txt
> > > 6.12: 8358469
> > > 6.13: 3476757
> > >
> > > The number of timers started increased significantly in 6.13, but most
> > > timers do not expire. Completion rate went down from 76% to 20%
> >
> > Did you actually look _which_ timers were started and which ones did
> > expire and which ones not?
> >
> > Data for a 2 seconds run (couldn't be bothered to wait 23 seconds)
> >
> > On 6.10:
> >
> > All start/expire:
> >
> > # grep -c 'hrtimer_start' t.txt
> > 248039
> > # grep -c 'hrtimer_expire' t.txt
> > 247530
> >
> > stress-ng Posix timer related:
> >
> > # grep -c 'hrtimer_start.*function=posix_timer_fn' t.txt
> > 246739
> > # grep -c 'hrtimer_expire.*function=posix_timer_fn' t.txt
> > 246739
> >
> > stress-ng nanosleep related:
> >
> > # grep -c 'hrtimer_start.*function=hrtimer_wakeup' t.txt
> > 2
> > # grep -c 'hrtimer_expire.*function=hrtimer_wakeup' t.txt
> > 2
> >
> > On 6.17-rc1:
> >
> > All start/expire:
> >
> > # grep -c 'hrtimer_start' t.txt
> > 457456
> > # grep -c 'hrtimer_expire' t.txt
> > 304959
> >
> > stress-ng Posix timer related:
> >
> > # grep -c 'hrtimer_start.*function=posix_timer_fn' t.txt
> > 304673
> > # grep -c 'hrtimer_expire.*function=posix_timer_fn' t.txt
> > 304674
> >
> > stress-ng nanosleep related:
> >
> > # grep -c 'hrtimer_start.*function=hrtimer_wakeup' t.txt
> > 152241
> > # grep -c 'hrtimer_expire.*function=hrtimer_wakeup' t.txt
> > 1
> >
> > The 150k timers which do not expire are related to the restarted
> > nanosleep(), because the nanosleep is canceled due to the signal and has
> > to be re-started.
> >
> > On 6.10 that does not even reach the nanosleep in the test thread
> > because the thing is too busy with bogus signal handling.
> >
> > Trace for 6.10
> >
> >  stress-ng-timer-2229    [110] .....   187.938505: sys_timer_settime(timer_id: 0, flags: 0, new_setting: 7f7880228ec0, old_setting: 0)
> >  stress-ng-timer-2229    [110] d..2.   187.938505: hrtimer_start: hrtimer=0000000023e2c3e0 function=posix_timer_fn expires=186716941003 softexpires=186716941003 mode=ABS
> >
> > Signal handler re-arms the timer
> >
> >  stress-ng-timer-2229    [110] .....   187.938505: sys_timer_settime -> 0x0
> >  stress-ng-timer-2229    [110] .....   187.938506: sys_rt_sigreturn()
> >
> > Returns from signal handler
> >
> >  stress-ng-timer-2229    [110] d..1.   187.938506: posixtimer_rearm <-dequeue_signal
> >
> > Dequeues the signal which was related to the arming _before_ the signal
> > handler re-arms it. So it's incorrectly delivered.
> >
> >  stress-ng-timer-2229    [110] d.h..   187.938507: hrtimer_expire_entry: hrtimer=0000000023e2c3e0 function=posix_timer_fn now=186716941468
> >
> > Now the timer which was armed in the signal handler above expires
> >
> >  stress-ng-timer-2229    [110] .....   187.938507: sys_timer_getoverrun(timer_id: 0)
> >  stress-ng-timer-2229    [110] .....   187.938507: sys_timer_getoverrun -> 0x0
> >
> > While the signal handler handles the bogus left over signal
> >
> > Lather, rinse and repeat.
> >
> >  stress-ng-timer-2229    [110] .....   187.938508: sys_timer_settime(timer_id: 0, flags: 0, new_setting: 7f7880228ec0, old_setting: 0)
> >  stress-ng-timer-2229    [110] d..2.   187.938508: hrtimer_start: hrtimer=0000000023e2c3e0 function=posix_timer_fn expires=186716943483 softexpires=186716943483 mode=ABS
> >  stress-ng-timer-2229    [110] .....   187.938508: sys_timer_settime -> 0x0
> >  stress-ng-timer-2229    [110] .....   187.938508: sys_rt_sigreturn()
> >  stress-ng-timer-2229    [110] d..1.   187.938508: posixtimer_rearm <-dequeue_signal
> >  stress-ng-timer-2229    [110] d.h..   187.938509: hrtimer_expire_entry: hrtimer=0000000023e2c3e0 function=posix_timer_fn now=186716943952
> >
> > vs. 6.17
> >
> >  stress-ng-timer-1828    [029] .....    84.089978: sys_rt_sigreturn()
> >  stress-ng-timer-1828    [029] d..1.    84.089979: posixtimer_deliver_signal <-dequeue_signal
> >
> > Signal, which was generated by the original armed timer is correctly ignored
> >
> >  stress-ng-timer-1828    [029] d..1.    84.089979: hrtimer_start: hrtimer=0000000081582a37 function=hrtimer_wakeup expires=83144889279 softexpires=83144839279 mode=REL
> >
> > Nanosleep is restarted
> >
> >           <idle>-0       [029] d.h1.    84.089980: hrtimer_expire_entry: hrtimer=000000009e0c5084 function=posix_timer_fn now=83134840265
> >
> > Timer which was armed in the signal handler expires
> >
> >  stress-ng-timer-1828    [029] d..1.    84.089981: posixtimer_deliver_signal <-dequeue_signal
> >
> > Signal is delivered and timer is re-armed:
> >
> >  stress-ng-timer-1828    [029] d..2.    84.089981: hrtimer_start: hrtimer=000000009e0c5084 function=posix_timer_fn expires=83134842396 softexpires=83134842396 mode=ABS
> >
> > Signal is handled
> >
> >  stress-ng-timer-1828    [029] .....    84.089982: sys_timer_getoverrun(timer_id: 0)
> >  stress-ng-timer-1828    [029] .....    84.089982: sys_timer_getoverrun -> 0x2
> >  stress-ng-timer-1828    [029] d.h..    84.089983: hrtimer_expire_entry: hrtimer=000000009e0c5084 function=posix_timer_fn now=83134842856
> >
> > Re-armed timer expires and queues a signal
> >
> >  stress-ng-timer-1828    [029] .....    84.089983: sys_timer_settime(timer_id: 0, flags: 0, new_setting: 7f7cccf7dec0, old_setting: 0)
> >
> > Timer is re-armed
> >
> >  stress-ng-timer-1828    [029] d..2.    84.089983: hrtimer_start: hrtimer=000000009e0c5084 function=posix_timer_fn expires=83134844444 softexpires=83134844444 mode=ABS
> >  stress-ng-timer-1828    [029] .....    84.089983: sys_timer_settime -> 0x0
> >  stress-ng-timer-1828    [029] .....    84.089983: sys_rt_sigreturn()
> >
> > Signal, which was generated by the timer armed on signal dequeue is
> > correctly ignored
> >
> >  stress-ng-timer-1828    [029] d..1.    84.089984: posixtimer_deliver_signal <-dequeue_signal
> >
> >
> > Thanks,
> >
> >         tglx
> >
>
>
> --
> -Jirka



-- 
-Jirka

Powered by blists - more mailing lists