Message-ID: <CAE4VaGC1wbN54Dpd0THKBhdSM9hoVqAc=jrGoc7+5vZNwGpKpQ@mail.gmail.com>
Date: Mon, 25 Aug 2025 13:35:56 +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"

 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

Powered by blists - more mailing lists