MIME-Version: 1.0
References: <0000000000006ac93505f42dda96@google.com> <87k00q1no2.ffs@tglx>
In-Reply-To: <87k00q1no2.ffs@tglx>
From:   John Stultz <jstultz@google.com>
Date:   Mon, 13 Feb 2023 14:28:33 -0800
Message-ID: <CANDhNCpua2g-jFRn-qK_yxck+_6m3Le1Dywh6A5zNj1qRhMeUw@mail.gmail.com>
Subject: Re: [syzbot] INFO: rcu detected stall in ext4_file_write_iter (6)
To:     Thomas Gleixner <tglx@linutronix.de>
Cc:     syzbot <syzbot+b9564ba6e8e00694511b@syzkaller.appspotmail.com>,
        linux-kernel@vger.kernel.org, sboyd@kernel.org,
        syzkaller-bugs@googlegroups.com,
        "Eric W. Biederman" <ebiederm@xmission.com>,
        Peter Zijlstra <peterz@infradead.org>,
        Oleg Nesterov <oleg@redhat.com>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Thu, Feb 9, 2023 at 2:25 PM Thomas Gleixner <tglx@linutronix.de> 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@google.com>

thanks
-john