Re: panic: data abort in critical section or under mutex (was: Re: panic: Unknown kernel exception 0 esr_el1 2000000 (on 14-CURRENT/aarch64 Feb 28))

On 2022-Mar-7, at 12:54, Ronald Klop <[email protected]> wrote:

> Van: Mark Johnston <[email protected]>
> Datum: maandag, 7 maart 2022 16:13
> Aan: Ronald Klop <[email protected]>
> CC: bob prohaska <[email protected]>, Mark Millard <[email protected]>, [email protected], freebsd-current <[email protected]>
> Onderwerp: Re: panic: data abort in critical section or under mutex (was: Re: panic: Unknown kernel exception 0 esr_el1 2000000 (on 14-CURRENT/aarch64 Feb 28))
> 
> On Mon, Mar 07, 2022 at 02:46:09PM +0100, Ronald Klop wrote:
> > Dear Mark Johnston,
> >
> > I did some binary search in the kernels and came to the conclusion that https://cgit.freebsd.org/src/commit/?id=1517b8d5a7f58897200497811de1b18809c07d3e still works and https://cgit.freebsd.org/src/commit/?id=407c34e735b5d17e2be574808a09e6d729b0a45a panics.
> >
> > I suspect your commit in https://cgit.freebsd.org/src/commit/?id=c84bb8cd771ce4bed58152e47a32dda470bef23a.
> >
> > Last panic:
> >
> > panic: vm_fault failed: ffff00000046e708 error 1
> > cpuid = 1
> > time = 1646660058
> > KDB: stack backtrace:
> > db_trace_self() at db_trace_self
> > db_trace_self_wrapper() at db_trace_self_wrapper+0x30
> > vpanic() at vpanic+0x174
> > panic() at panic+0x44
> > data_abort() at data_abort+0x2e8
> > handle_el1h_sync() at handle_el1h_sync+0x10
> > --- exception, esr 0x96000004
> > _rm_rlock_debug() at _rm_rlock_debug+0x8c
> > osd_get() at osd_get+0x5c
> > zio_execute() at zio_execute+0xf8
> > taskqueue_run_locked() at taskqueue_run_locked+0x178
> > taskqueue_thread_loop() at taskqueue_thread_loop+0xc8
> > fork_exit() at fork_exit+0x74
> > fork_trampoline() at fork_trampoline+0x14
> > KDB: enter: panic
> > [ thread pid 0 tid 100129 ]
> > Stopped at      kdb_enter+0x44: undefined       f902011f
> > db>
> >
> > A more recent kernel (912df91) still panics. See below.
> >
> > Do you have time to look into this? What can I provide in information to help?
> 
> Hmm.  So after my rmlock commits, we have the following disassembly for
> _rm_rlock() (with a few annotations added by me).  Note that the pcpu
> pointer is stored in register x18 by convention.
> 
>    0xffff00000046e304 <+0>:     stp     x29, x30, [sp, #-16]!
>    0xffff00000046e308 <+4>:     mov     x29, sp
>    0xffff00000046e30c <+8>:     ldr     x8, [x18]
>    0xffff00000046e310 <+12>:    ldr     x9, [x18]
>    0xffff00000046e314 <+16>:    ldr     x10, [x18]
>    0xffff00000046e318 <+20>:    cmp     x9, x10
>    0xffff00000046e31c <+24>:    b.ne    0xffff00000046e3cc <_rm_rlock+200>  // b.any
>    0xffff00000046e320 <+28>:    ldr     x9, [x18]
>    0xffff00000046e324 <+32>:    ldrh    w9, [x9, #314]
>    0xffff00000046e328 <+36>:    cbnz    w9, 0xffff00000046e3c0 <_rm_rlock+188>
>    0xffff00000046e32c <+40>:    str     wzr, [x1, #32]
>    0xffff00000046e330 <+44>:    stp     x0, x8, [x1, #16]
>    0xffff00000046e334 <+48>:    ldrb    w9, [x0, #10]
>    0xffff00000046e338 <+52>:    tbz     w9, #4, 0xffff00000046e358 <_rm_rlock+84>
>    0xffff00000046e33c <+56>:    ldr     x9, [x18]
>    0xffff00000046e340 <+60>:    ldr     w10, [x9, #888]
>    0xffff00000046e344 <+64>:    add     w10, w10, #0x1
>    0xffff00000046e348 <+68>:    str     w10, [x9, #888]
>    0xffff00000046e34c <+72>:    ldr     x9, [x18]
>    0xffff00000046e350 <+76>:    ldr     w9, [x9, #888]
>    0xffff00000046e354 <+80>:    cbz     w9, 0xffff00000046e3f4 <_rm_rlock+240>
>    0xffff00000046e358 <+84>:    ldr     w9, [x8, #1212]
>    0xffff00000046e35c <+88>:    add     x10, x18, #0x90
>    0xffff00000046e360 <+92>:    add     w9, w9, #0x1
>    0xffff00000046e364 <+96>:    str     w9, [x8, #1212]  <------- critical_enter
>    0xffff00000046e368 <+100>:   str     x10, [x1, #8]
>    0xffff00000046e36c <+104>:   ldr     x9, [x18, #144]
>    0xffff00000046e370 <+108>:   str     x9, [x1]
>    0xffff00000046e374 <+112>:   str     x1, [x9, #8]
>    0xffff00000046e378 <+116>:   str     x1, [x18, #144]
>    0xffff00000046e37c <+120>:   ldr     x9, [x18]
>    0xffff00000046e380 <+124>:   ldr     w10, [x9, #356]
>    0xffff00000046e384 <+128>:   add     w10, w10, #0x1
>    0xffff00000046e388 <+132>:   str     w10, [x9, #356]
>    0xffff00000046e38c <+136>:   ldr     w9, [x8, #1212]
>    0xffff00000046e390 <+140>:   sub     w9, w9, #0x1
>    0xffff00000046e394 <+144>:   str     w9, [x8, #1212]  <------- critical_exit
>    0xffff00000046e398 <+148>:   ldrb    w8, [x8, #304]
>    0xffff00000046e39c <+152>:   ldr     w9, [x18, #60]   <------- loading &pc->pc_cpuid
>    ...
> 
> A (the?) problem is that the compiler is treating "pc" as an alias
> for x18, but the rmlock code assumes that the pcpu pointer is loaded
> once, as it dereferences "pc" outside of the critical section.  On
> arm64, if a context switch occurs between the store at _rm_rlock+144 and
> the load at +152, and the thread is migrated to another CPU, then we'll
> end up using the wrong CPU ID in the rm->rm_writecpus test.
> 
> I suspect the problem is unique to arm64 as its get_pcpu()
> implementation is different from the others in that it doesn't use
> volatile-qualified inline assembly.  This has been the case since
> https://cgit.freebsd.org/src/commit/?id=63c858a04d56529eddbddf85ad04fc8e99e73762
> .
> 
> I haven't been able to reproduce any crashes running poudriere in an
> arm64 AWS instance, though.  Could you please try the patch below and
> confirm whether it fixes your panics?  I verified that the apparent
> problem described above is gone with the patch.
> 
> diff --git a/sys/kern/kern_rmlock.c b/sys/kern/kern_rmlock.c
> index 0cdcfb8fec62..e51c25136ae0 100644
> --- a/sys/kern/kern_rmlock.c
> +++ b/sys/kern/kern_rmlock.c
> @@ -437,6 +437,7 @@ _rm_rlock(struct rmlock *rm, struct rm_priotracker *tracker, int trylock)
>  {
>     struct thread *td = curthread;
>     struct pcpu *pc;
> +   int cpuid;
>  
>     if (SCHEDULER_STOPPED())
>         return (1);
> @@ -452,6 +453,7 @@ _rm_rlock(struct rmlock *rm, struct rm_priotracker *tracker, int trylock)
>     atomic_interrupt_fence();
>  
>     pc = get_pcpu();
> +   cpuid = pc->pc_cpuid;
>     rm_tracker_add(pc, tracker);
>     sched_pin();
>  
> @@ -463,7 +465,7 @@ _rm_rlock(struct rmlock *rm, struct rm_priotracker *tracker, int trylock)
>      * conditional jump.
>      */
>     if (__predict_true(0 == (td->td_owepreempt |
> -       CPU_ISSET(pc->pc_cpuid, &rm->rm_writecpus))))
> +       CPU_ISSET(cpuid, &rm->rm_writecpus))))
>         return (1);
>  
>     /* We do not have a read token and need to acquire one. */
> 
> Hi,
> 
> This patch paniced again:
> x0: ffffa00005a31500                                                                                             
>   x1: ffffa00005a0e000                                                                                                           
>   x2:                2                                                                                                           
>   x3: ffffa00076c4e9a0                                                                                                           
>   x4:                0                                                                                                           
>   x5:    e672743c8f9e5                                                                                                           
>   x6:    dc89f70500ab1
>   x7:               14
>   x8: ffffa00005a31518
>   x9:                1
>  x10: ffffa00005a0e000
>  x11:                0
>  x12:                0
>  x13:                a
>  x14: 1013e6b85a8ecbe4
>  x15:     1dce740d11a5
>  x16: ffff3ea86e2434bf
>  x17: fffffffffffffff2
>  x18: ffff0000fe661800 (g_ctx + fcf9fa54)
>  x19: ffffa00076c4e9a0
>  x20: ffff0000fec39000 (g_ctx + fd577254)
>  x21:                2
>  x22: ffff0000419b6090 (g_ctx + 402f42e4)
>  x23: ffff000000c0b137 (lockstat_enabled + 0)
>  x24:              100
>  x25: ffff000000c0b000 (version + a0)
>  x26: ffff000000c0b000 (version + a0)
>  x27: ffff000000c0b000 (version + a0)
>  x28:                0
>  x29: ffff0000fe661800 (g_ctx + fcf9fa54)
>   sp: ffff0000fe661800
>   lr: ffff00000154ea50 (zio_dva_throttle + 154)
>  elr: ffff00000154ea80 (zio_dva_throttle + 184)
> spsr:         60000045
>  far:     2b753286b0b8
> panic: Unknown kernel exception 0 esr_el1 2000000
> cpuid = 1
> time = 1646685857
> KDB: stack backtrace:
> db_trace_self() at db_trace_self
> db_trace_self_wrapper() at db_trace_self_wrapper+0x30
> vpanic() at vpanic+0x174
> panic() at panic+0x44
> do_el1h_sync() at do_el1h_sync+0x184
> handle_el1h_sync() at handle_el1h_sync+0x10
> --- exception, esr 0x2000000
> zio_dva_throttle() at zio_dva_throttle+0x184
> zio_execute() at zio_execute+0x58
> KDB: enter: panic
> [ thread pid 0 tid 100129 ]
> Stopped at      kdb_enter+0x44: undefined       f901c11f
> db>  


Hmm. My somewhat older source code shows zio_dva_throttle
as having:

        mutex_enter(&spa->spa_allocs[allocator].spaa_lock);
        avl_add(&spa->spa_allocs[allocator].spaa_tree, zio);
        nio = zio_io_to_allocate(spa, allocator);
        mutex_exit(&spa->spa_allocs[allocator].spaa_lock);
        return (nio);

That might have implications if the issue is actually
analogous to _rm_rlock_debug crashes in some way.


===
Mark Millard
marklmi at yahoo.com