Re: [syzbot] INFO: rcu detected stall in ext4_file_write_iter (6)
From: John Stultz
Date: Mon Feb 13 2023 - 17:28:50 EST
On Thu, Feb 9, 2023 at 2:25 PM Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
>
> On Wed, Feb 08 2023 at 02:37, syzbot wrote:
> > syzbot found the following issue on:
> >
> > HEAD commit: 4fafd96910ad Add linux-next specific files for 20230203
> > git tree: linux-next
> > console+strace: https://syzkaller.appspot.com/x/log.txt?x=17005023480000
> > kernel config: https://syzkaller.appspot.com/x/.config?x=1d2fba7d42502ca4
> > dashboard link: https://syzkaller.appspot.com/bug?extid=b9564ba6e8e00694511b
> > compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
> > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=110c6175480000
> > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=15ef5ad9480000
> >
> > Downloadable assets:
> > disk image: https://storage.googleapis.com/syzbot-assets/348cc2da441a/disk-4fafd969.raw.xz
> > vmlinux: https://storage.googleapis.com/syzbot-assets/e2dedc500f12/vmlinux-4fafd969.xz
> > kernel image: https://storage.googleapis.com/syzbot-assets/fae710d9ebd8/bzImage-4fafd969.xz
>
> <SNIP>
>
> > NMI backtrace for cpu 0
> > Call Trace:
> > <IRQ>
> > trace_alarmtimer_fired include/trace/events/alarmtimer.h:73 [inline]
> > alarmtimer_fired+0x327/0x670 kernel/time/alarmtimer.c:220
> > __run_hrtimer kernel/time/hrtimer.c:1685 [inline]
> > __hrtimer_run_queues+0x600/0xcf0 kernel/time/hrtimer.c:1749
> > hrtimer_interrupt+0x320/0x7b0 kernel/time/hrtimer.c:1811
> > local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1096 [inline]
> > __sysvec_apic_timer_interrupt+0x180/0x660 arch/x86/kernel/apic/apic.c:1113
> > sysvec_apic_timer_interrupt+0x92/0xc0 arch/x86/kernel/apic/apic.c:1107
> > </IRQ>
> > <TASK>
> > asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:645
>
> Looking at the reproducer:
>
> *(uint64_t*)0x2006b000 = 0;
> *(uint64_t*)0x2006b008 = 8;
> *(uint64_t*)0x2006b010 = 0;
> *(uint64_t*)0x2006b018 = 9;
> syscall(__NR_timer_settime, 0, 0ul, 0x2006b000ul, 0ul);
>
> This arms the alarm timer with a relative expiry of 8ns and an interval
> of 9ns. Not a problem per se, but that's an issue when the signal is
> ignored because then the timer is immediately rearmed because there is
> no way to delay that rearming to the signal delivery path.
> See posix_timer_fn() and commit 58229a189942 ("posix-timers: Prevent
> softirq starvation by small intervals and SIG_IGN") for details.
>
> The reproducer does not set SIG_IGN explicitely, but it does something
> nasty which has the same effect:
>
> *(uint64_t*)0x20000000 = 0;
> *(uint32_t*)0x20000008 = 0x12;
> *(uint32_t*)0x2000000c = 0;
> *(uint32_t*)0x20000010 = 0;
> syscall(__NR_timer_create, 9ul, 0x20000000ul, 0x20000180ul);
>
> 0x20000008 is the signal number, which decodes to SIGCONT. SIGCONT is
> ignored if there is no handler set and the task is not ptraced.
>
> The log clearly shows that:
>
> [pid 5102] --- SIGCONT {si_signo=SIGCONT, si_code=SI_TIMER, si_timerid=0, si_overrun=316014, si_int=0, si_ptr=NULL} ---
>
> It works because the tasks are traced and therefore the signal is queued
> so the tracer can see it, which delays the restart of the timer
> and the restart of the timer is delayed.
>
> [pid 5087] kill(-5102, SIGKILL <unfinished ...>
>
> Here the tracer is killed
>
> [pid 5107] --- SIGCONT {si_signo=SIGCONT, si_code=SI_TIMER, si_timerid=0, si_overrun=167448, si_int=0, si_ptr=NULL} ---
> [pid 5104] --- SIGCONT {si_signo=SIGCONT, si_code=SI_TIMER, si_timerid=0, si_overrun=157138, si_int=0, si_ptr=NULL} ---
> [pid 5103] --- SIGCONT {si_signo=SIGCONT, si_code=SI_TIMER, si_timerid=0, si_overrun=187150, si_int=0, si_ptr=NULL} ---
> [pid 5106] --- SIGCONT {si_signo=SIGCONT, si_code=SI_TIMER, si_timerid=0, si_overrun=190249, si_int=0, si_ptr=NULL} ---
> [pid 5102] --- stopped by SIGCONT ---
> ./strace-static-x86_64: ptrace(PTRACE_LISTEN,pid:5102,sig:0): Input/output error
> ./strace-static-x86_64: Process 5083 detached
> ./strace-static-x86_64: Process 5084 detached
> ./strace-static-x86_64: Process 5086 detached
> ./strace-static-x86_64: Process 5085 detached
> ./strace-static-x86_64: Process 5088 detached
> ./strace-static-x86_64: Process 5089 detached
> ./strace-static-x86_64: Process 5087 detached
> ./strace-static-x86_64: Process 5102 detached
> ./strace-static-x86_64: Process 5103 detached
> ./strace-static-x86_64: Process 5104 detached
> ./strace-static-x86_64: Process 5105 detached
> ./strace-static-x86_64: Process 5106 detached
> ./strace-static-x86_64: Process 5107 detached
>
> and after it's gone the drama starts:
>
> syzkaller login: [ 79.439102][ C0] hrtimer: interrupt took 68471 ns
> [ 184.460538][ C1] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> ...
> [ 184.658237][ C1] rcu: Stack dump where RCU GP kthread last ran:
> [ 184.664574][ C1] Sending NMI from CPU 1 to CPUs 0:
> [ 184.669821][ C0] NMI backtrace for cpu 0
> [ 184.669831][ C0] CPU: 0 PID: 5108 Comm: syz-executor192 Not tainted 6.2.0-rc6-next-20230203-syzkaller #0
> ...
> [ 184.670036][ C0] Call Trace:
> [ 184.670041][ C0] <IRQ>
> [ 184.670045][ C0] alarmtimer_fired+0x327/0x670
>
> posix_timer_fn() prevents that by checking whether the interval for
> timers which have the signal ignored is smaller than a jiffie and
> artifically delay it by shifting the next expiry out by a jiffie. That's
> accurate vs. the overrun accounting, but slightly inaccurate
> vs. timer_gettimer().
>
> The comment in that function says what needs to be done and there was a
> fix available for the regular userspace induced SIG_IGN mechanism, but
> that did not work due to the implicit ignore for SIGCONT. I gave up at
> that point and put it onto the ever growing todo list...
>
> So the only available workaround right now is to do exactly what
> posix_timer_fn() does.
>
> Untested patch below.
I ran your test for a bit with the reproducer and didn't see any
issues. Also ran it through the kselftests/timers
run_destructive_tests and didn't see any issues.
So I think this is ok. Haven't really dug through all the implications
for adding an extra jiffy to the expiration there, but it sounds
reasonable to me.
Acked-by: John Stultz <jstultz@xxxxxxxxxx>
thanks
-john