[PATCH] KVM: PPC: Book3S HV: add smp_mb() in kvmppc_set_host_ipi()

Michael Roth mdroth at linux.vnet.ibm.com
Fri Sep 6 09:21:22 AEST 2019


Quoting Michael Ellerman (2019-09-04 22:04:48)
> Hi Mike,
> 
> Thanks for the patch & great change log, just a few comments.

Hi Michael,

Thank you for the suggestions. I will roll them into v2 unless otherwise
noted below.

> 
> Michael Roth <mdroth at linux.vnet.ibm.com> writes:
> > On a 2-socket Witherspoon system with 128 cores and 1TB of memory
>                            ^
>                            Power9 (not everyone knows what a Witherspoon is)
> 
> > running the following guest configs:
> >
> >   guest A:
> >     - 224GB of memory
> >     - 56 VCPUs (sockets=1,cores=28,threads=2), where:
> >       VCPUs 0-1 are pinned to CPUs 0-3,
> >       VCPUs 2-3 are pinned to CPUs 4-7,
> >       ...
> >       VCPUs 54-55 are pinned to CPUs 108-111
> >
> >   guest B:
> >     - 4GB of memory
> >     - 4 VCPUs (sockets=1,cores=4,threads=1)
> >
> > with the following workloads (with KSM and THP enabled in all):
> >
> >   guest A:
> >     stress --cpu 40 --io 20 --vm 20 --vm-bytes 512M
> >
> >   guest B:
> >     stress --cpu 4 --io 4 --vm 4 --vm-bytes 512M
> >
> >   host:
> >     stress --cpu 4 --io 4 --vm 2 --vm-bytes 256M
> >
> > the below soft-lockup traces were observed after an hour or so and
> > persisted until the host was reset (this was found to be reliably
> > reproducible for this configuration, for kernels 4.15, 4.18, 5.0,
> > and 5.3-rc5):
> >
> >   [ 1253.183290] rcu: INFO: rcu_sched self-detected stall on CPU
> >   [ 1253.183319] rcu:     124-....: (5250 ticks this GP) idle=10a/1/0x4000000000000002 softirq=5408/5408 fqs=1941
> >   [ 1256.287426] watchdog: BUG: soft lockup - CPU#105 stuck for 23s! [CPU 52/KVM:19709]
> >   [ 1264.075773] watchdog: BUG: soft lockup - CPU#24 stuck for 23s! [worker:19913]
> >   [ 1264.079769] watchdog: BUG: soft lockup - CPU#31 stuck for 23s! [worker:20331]
> >   [ 1264.095770] watchdog: BUG: soft lockup - CPU#45 stuck for 23s! [worker:20338]
> >   [ 1264.131773] watchdog: BUG: soft lockup - CPU#64 stuck for 23s! [avocado:19525]
> >   [ 1280.408480] watchdog: BUG: soft lockup - CPU#124 stuck for 22s! [ksmd:791]
> >   [ 1316.198012] rcu: INFO: rcu_sched self-detected stall on CPU
> >   [ 1316.198032] rcu:     124-....: (21003 ticks this GP) idle=10a/1/0x4000000000000002 softirq=5408/5408 fqs=8243
> >   [ 1340.411024] watchdog: BUG: soft lockup - CPU#124 stuck for 22s! [ksmd:791]
> >   [ 1379.212609] rcu: INFO: rcu_sched self-detected stall on CPU
> >   [ 1379.212629] rcu:     124-....: (36756 ticks this GP) idle=10a/1/0x4000000000000002 softirq=5408/5408 fqs=14714
> >   [ 1404.413615] watchdog: BUG: soft lockup - CPU#124 stuck for 22s! [ksmd:791]
> >   [ 1442.227095] rcu: INFO: rcu_sched self-detected stall on CPU
> >   [ 1442.227115] rcu:     124-....: (52509 ticks this GP) idle=10a/1/0x4000000000000002 softirq=5408/5408 fqs=21403
> >   [ 1455.111787] INFO: task worker:19907 blocked for more than 120 seconds.
> >   [ 1455.111822]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.111833] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.111884] INFO: task worker:19908 blocked for more than 120 seconds.
> >   [ 1455.111905]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.111925] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.111966] INFO: task worker:20328 blocked for more than 120 seconds.
> >   [ 1455.111986]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.111998] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.112048] INFO: task worker:20330 blocked for more than 120 seconds.
> >   [ 1455.112068]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.112097] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.112138] INFO: task worker:20332 blocked for more than 120 seconds.
> >   [ 1455.112159]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.112179] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.112210] INFO: task worker:20333 blocked for more than 120 seconds.
> >   [ 1455.112231]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.112242] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.112282] INFO: task worker:20335 blocked for more than 120 seconds.
> >   [ 1455.112303]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> >   [ 1455.112332] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >   [ 1455.112372] INFO: task worker:20336 blocked for more than 120 seconds.
> >   [ 1455.112392]       Tainted: G             L    5.3.0-rc5-mdr-vanilla+ #1
> 
> There should be stack traces here, did they get lost or you omitted them
> for brevity?

Both, I suppose :) This kernel was booted with 'quiet' option so I think the
traces were below CONFIG_CONSOLE_LOGLEVEL_QUIET=4 threshold, but the above
output was more to characterize that this was a persistent/re-occurring
lock-up, where I think brevity helps.

I do have the traces from xmon for all the CPUs that reported a soft-lockup,
but in some instances we don't see any lockups from spinlock waiters so I
wanted to keep the focus on the smp_call_function_many() callers.

Here's the trace for one of the spinlock waiters, if you think it would
be helpful to incorporate some or all of these into the commit log I can
certainly add them.

  # call trace/registers for CPU 124

  47:mon> c7c
  [link register   ] c00000000039cba4 follow_page_mask+0x6f4/0xcd0
  [c000008fe44c7b80] 0000000000000000 (unreliable)
  [c000008fe44c7bb0] c00000000039d0e4 follow_page_mask+0xc34/0xcd0
  [c000008fe44c7c40] c00000000039fef4 follow_page+0x44/0x110
  [c000008fe44c7c90] c0000000003ff6c8 ksm_scan_thread+0x5e8/0x1f60
  [c000008fe44c7db0] c00000000015e864 kthread+0x1a4/0x1b0
  [c000008fe44c7e20] c00000000000b760 ret_from_kernel_thread+0x5c/0x7c
  7c:mon> r
  R00 = c00000000039cba4   R16 = 0000000000000000
  R01 = c000008fe44c7b80   R17 = c000000001ca9a20
  R02 = c0000000019b3a00   R18 = c000000001b626b0
  R03 = c00c00000da5afe8   R19 = c00c00000da5afc0
  R04 = 0000000000000009   R20 = c000003696bfc610
  R05 = 0000000096bfc009   R21 = 0000000000000001
  R06 = 0000000000000009   R22 = c000003696bfc000
  R07 = 000000004d600386   R23 = 0000000000000610
  R08 = 4000000000000800   R24 = c000000001b62740
  R09 = 0000000080000069   R25 = c000000001b62738
  R10 = 000000008000007c   R26 = 00007d1c18490000
  R11 = 0000000000000000   R27 = c000008fe44c7c68
  R12 = 0000000000002000   R28 = 0000000000000000
  R13 = c000207fff60e800   R29 = c00000363df40af0
  R14 = c00c00000dd35800   R30 = c0000000019e1d80
  R15 = 5deadbeef0000100   R31 = c00c00000da5afe8
  pc  = c000000000ea1eb8 _raw_spin_lock+0x68/0x100
  cfar= c000000000ea1ee0 _raw_spin_lock+0x90/0x100
  lr  = c00000000039cba4 follow_page_mask+0x6f4/0xcd0
  msr = 9000000000089033   cr  = 24002824
  ctr = 0000000000000000   xer = 0000000000000000   trap =  100
  7c:mon> e
  cpu 0x7c: Vector: 100 (System Reset) at [c000207fff133d70]
      pc: c000000000ea1eb8: _raw_spin_lock+0x68/0x100
      lr: c00000000039cba4: follow_page_mask+0x6f4/0xcd0
      sp: c000008fe44c7b80
     msr: 9000000000089033
    current = 0xc000008fe6f94900
    paca    = 0xc000207fff60e800   irqmask: 0x03   irq_happened: 0x01
      pid   = 791, comm = ksmd

> 
> > CPU 45/0x2d, 24/0x18, 124/0x7c are stuck on spin locks, likely held by
> > CPUs 105/31
> 
> That last one "105/31" is confusing because it looks like you're giving
> the decimal/hex values again, but you're not.
> 
> I know xmon uses hex CPU numbers, but you don't actually refer to them
> much in this change log, so it's probably clearer just to convert all
> CPU numbers to decimal for the sake of the change log.
> 
> > CPU 105/0x69, and 31/0x1f are stuck in smp_call_function_many(),
> > waiting on target CPU 42. For instance:
> >
> >   69:mon> r
> 
> I think here and below are the only places we have a hex CPU number, so
> instead of using the xmon prompt just do eg:
> 
>     Registers for CPU 105:
> >   R00 = c00000000020b20c   R16 = 00007d1bcd800000
> >   R01 = c00000363eaa7970   R17 = 0000000000000001
> >   R02 = c0000000019b3a00   R18 = 000000000000006b
> >   R03 = 000000000000002a   R19 = 00007d537d7aecf0
> >   R04 = 000000000000002a   R20 = 60000000000000e0
> >   R05 = 000000000000002a   R21 = 0801000000000080
> >   R06 = c0002073fb0caa08   R22 = 0000000000000d60
> >   R07 = c0000000019ddd78   R23 = 0000000000000001
> >   R08 = 000000000000002a   R24 = c00000000147a700
> >   R09 = 0000000000000001   R25 = c0002073fb0ca908
> >   R10 = c000008ffeb4e660   R26 = 0000000000000000
> >   R11 = c0002073fb0ca900   R27 = c0000000019e2464
> >   R12 = c000000000050790   R28 = c0000000000812b0
> >   R13 = c000207fff623e00   R29 = c0002073fb0ca808
> >   R14 = 00007d1bbee00000   R30 = c0002073fb0ca800
> >   R15 = 00007d1bcd600000   R31 = 0000000000000800
> >   pc  = c00000000020b260 smp_call_function_many+0x3d0/0x460
> >   cfar= c00000000020b270 smp_call_function_many+0x3e0/0x460
> >   lr  = c00000000020b20c smp_call_function_many+0x37c/0x460
> >   msr = 900000010288b033   cr  = 44024824
> >   ctr = c000000000050790   xer = 0000000000000000   trap =  100
> >
> > CPU 42 is running normally, doing VCPU work:
> >
> >   1f:mon> c2a
> 
> And similarly here just say "Backtrace for CPU 42:" and omit the xmon prompt.
> 
> >   [link register   ] c00800001be17188 kvmppc_book3s_radix_page_fault+0x90/0x2b0 [kvm_hv]
> >   [c000008ed3343820] c000008ed3343850 (unreliable)
> >   [c000008ed33438d0] c00800001be11b6c kvmppc_book3s_hv_page_fault+0x264/0xe30 [kvm_hv]
> >   [c000008ed33439d0] c00800001be0d7b4 kvmppc_vcpu_run_hv+0x8dc/0xb50 [kvm_hv]
> >   [c000008ed3343ae0] c00800001c10891c kvmppc_vcpu_run+0x34/0x48 [kvm]
> >   [c000008ed3343b00] c00800001c10475c kvm_arch_vcpu_ioctl_run+0x244/0x420 [kvm]
> >   [c000008ed3343b90] c00800001c0f5a78 kvm_vcpu_ioctl+0x470/0x7c8 [kvm]
> >   [c000008ed3343d00] c000000000475450 do_vfs_ioctl+0xe0/0xc70
> >   [c000008ed3343db0] c0000000004760e4 ksys_ioctl+0x104/0x120
> >   [c000008ed3343e00] c000000000476128 sys_ioctl+0x28/0x80
> >   [c000008ed3343e20] c00000000000b388 system_call+0x5c/0x70
> >   --- Exception: c00 (System Call) at 00007d545cfd7694
> >   SP (7d53ff7edf50) is in userspace
> >
> > It was subsequently found that ipi_message[PPC_MSG_CALL_FUNCTION]
> > was set for CPU 42 by at least 1 of the CPUs waiting in
> > smp_call_function_many(), but somehow the corresponding
> > call_single_queue entries were never processed, causing the callers
>                                                 ^
>                                                 "by CPU 42" (just to be completely clear?)
> > to spin in csd_lock_wait() indefinitely.
> >
> > Nick Piggin suggested something similar to the following sequence as
> > a possible explanation (interleaving of CALL_FUNCTION/RESCHEDULE
> > IPI messages seems to be most common, but any mix of CALL_FUNCTION and
> > !CALL_FUNCTION messages could trigger it):
> 
> It's not very clear below where the smp_mb()'s and other functions you
> refer to are located in the code, so worth commenting each I think, eg:
> 
> >   CPU
>       X: smp_mb()                       // in smp_muxed_ipi_set_message()
> >     X: ipi_message[RESCHEDULE] = 1
>       X: kvmppc_set_host_ipi(42, 1)     // in doorbell_global_ipi()
> >     X: smp_mb()
>          ^
> Where is that, I can't work out which one you're referring to?
> 
> We do call ppc_msgsnd_sync(), which is a `sync` which happens to be the
> same thing as smp_mb()? But that's not very clear to me.

Yes, that's the one. I thought it would be easier to reason about this
particular example by applying the smp_mb() naming, but I agree it should
be clarified better. Something like this maybe?

  X: smp_mb() // via the `sync` in ppc_msgsnd_sync()

or would this be clearer?

  X: ppc_msgsnd_sync() // same as smp_mb() in current code

> 
> >     X: doorbell/msgsnd -> 42
> >    42: doorbell_exception() (from CPU X)
> >    42: msgsync
>     105: smb_mb()                       // in smp_muxed_ipi_set_message()
> 
> The key point is that the store we think we do here is reordered vs the
> next store, at least from the other CPUs POV. So that's probably worth
> explicitly annotating, something like:
> 
>     105: store issued but delayed: ipi_message[CALL_FUNCTION] = 1 ...
> 
> Or some better syntax that someone else can think of :)
> 
>     105: kvmppc_set_host_ipi(42, 1)     // in doorbell_global_ipi()
> >    42: kvmppc_set_host_ipi(42, 0)
> >    42: smp_ipi_demux_relaxed()
> >    42: // returns to executing guest
> >   105: ipi_message[CALL_FUNCTION] = 1 // due to re-ordering
> >   105: smp_mb()
> >   105: doorbell/msgsnd -> 42
> >    42: local_paca->kvm_hstate.host_ipi == 0 // IPI ignored
> >   105: // hangs waiting on 42 to process messages/call_single_queue
> >
> > This patch avoids that scenario by placing a barrier at the start
> 
> "prevents" is better than "avoids" IMHO.
> 
> > of kvmppc_set_host_ipi() such that the storing of these messages (or
> > other state indicated by host_ipi being set) cannot be re-ordered past
> > it.
> 
> I think I'd phrase it more like : ".. placing a barrier at the start of
> kvmppc_set_host_ipi() so that stores to the ipi_message (or other state)
> are ordered vs the store to host_ipi."
> 
> That raises the question of whether this needs to be a full barrier or
> just a write barrier, and where is the matching barrier on the reading
> side?

For this particular case I think the same barrier orders it on the
read-side via kvmppc_set_host_ipi(42, 0) above, but I'm not sure that
work as a general solution, unless maybe we make that sort of usage
(clear-before-processing) part of the protocol of using
kvmppc_set_host_ipi()... it makes sense given we already need to take
care to not miss clearing them else we get issues like what was fixed
in 755563bc79c7, which introduced the clear in doorbell_exception(). So
then it's a matter of additionally making sure we do it prior to
processing host_ipi state. I haven't looked too closely at the other
users of kvmppc_set_host_ipi() yet though.

Alternatively, if I'm reading things right we currently have a four places
(A, B, C, and D below) that read host_ipi and branch when it's set:

in arch/powerpc/kvm/book3s_hv_rmhandlers.S:

       kvmppc_check_wake_reason:
               ...
               /* hypervisor doorbell */
       3:      li      r12, BOOK3S_INTERRUPT_H_DOORBELL
       
               /*
                * Clear the doorbell as we will invoke the handler
                * explicitly in the guest exit path.
                */
               lis     r6, (PPC_DBELL_SERVER << (63-36))@h
               PPC_MSGCLR(6)
               /* see if it's a host IPI */
               li      r3, 1
       BEGIN_FTR_SECTION
               PPC_MSGSYNC
               lwsync
       END_FTR_SECTION_IFSET(CPU_FTR_ARCH_300)

  A)
               lbz     r0, HSTATE_HOST_IPI(r13)
               cmpwi   r0, 0
               bnelr
               /* if not, return -1 */
               li      r3, -1
               blr
  
               ...
  
               /* external interrupt - create a stack frame so we can call C */
       7:      mflr    r0
               std     r0, PPC_LR_STKOFF(r1)
               stdu    r1, -PPC_MIN_STKFRM(r1)
  B)
               bl      kvmppc_read_intr
               nop
               li      r12, BOOK3S_INTERRUPT_EXTERNAL
               cmpdi   r3, 1
               ble     1f
  
        kvmppc_interrupt_hv:
                ...
                /* Hypervisor doorbell - exit only if host IPI flag set */
                cmpwi   r12, BOOK3S_INTERRUPT_H_DOORBELL
                bne     3f
        BEGIN_FTR_SECTION
                PPC_MSGSYNC
                lwsync
                /* always exit if we're running a nested guest */
                ld      r0, VCPU_NESTED(r9)
                cmpdi   r0, 0
                bne     guest_exit_cont
        END_FTR_SECTION_IFSET(CPU_FTR_ARCH_300)
        
  C)
                lbz     r0, HSTATE_HOST_IPI(r13)
                cmpwi   r0, 0
                beq     maybe_reenter_guest
                b       guest_exit_cont
        
                ...
        
                /* External interrupt ? */
                cmpwi   r12, BOOK3S_INTERRUPT_EXTERNAL
                beq     kvmppc_guest_external
        
        kvmppc_guest_external:
                /* External interrupt, first check for host_ipi. If this is
                 * set, we know the host wants us out so let's do it now
                 */
  D)
                bl      kvmppc_read_intr
        
                ...
        
                li      r12, BOOK3S_INTERRUPT_EXTERNAL
        
                /*
                 * kvmppc_read_intr return codes:
                 *
                 * Exit to host (r3 > 0)
                 *   1 An interrupt is pending that needs to be handled by the host
                 *     Exit guest and return to host by branching to guest_exit_cont
                 *
                 *   2 Passthrough that needs completion in the host
                 *     Exit guest and return to host by branching to guest_exit_cont
                 *     However, we also set r12 to BOOK3S_INTERRUPT_HV_RM_HARD
                 *     to indicate to the host to complete handling the interrupt
                 *
                 * Before returning to guest, we check if any CPU is heading out
                 * to the host and if so, we head out also. If no CPUs are heading
                 * check return values <= 0.
                 *
                 * Return to guest (r3 <= 0)
                 *  0 No external interrupt is pending
                 * -1 A guest wakeup IPI (which has now been cleared)
                 *    In either case, we return to guest to deliver any pending
                 *    guest interrupts.
                 *
                 * -2 A PCI passthrough external interrupt was handled
                 *    (interrupt was delivered directly to guest)
                 *    Return to guest to deliver any pending guest interrupts.
                 */
        
                cmpdi   r3, 1
                ble     1f
        
                /* Return code = 2 */
                li      r12, BOOK3S_INTERRUPT_HV_RM_HARD
                stw     r12, VCPU_TRAP(r9)
                b       guest_exit_cont
        
        1:      /* Return code <= 1 */
                cmpdi   r3, 0
                bgt     guest_exit_cont


We could add an explicit `sync` after A) and C), and an smp_mb() in the
2 places where we test for it and find it set in kvmppc_read_intr() to
cover instances like B) and D). I was thinking maybe guest_exit_cont was
a common point where we could cover all these cases but kvm_novcpu_wakeup
seems to be at least one exception, plus if we went that route we'd issue
smp_mb()'s in cases where we don't actually need them.

Definitely open to other alternatives.

As far as using rw barriers, I can't think of any reason we couldn't, but
I wouldn't say I'm at all confident in declaring that safe atm...

> 
> > With this the above workload ran for 6 hours (so far) without
> 
> s/this/that fix in place/
> 
> > triggering any lock-ups.
> >
> > Cc: Paul Mackerras <paulus at ozlabs.org>
> > Cc: Nicholas Piggin <npiggin at gmail.com>
> > Cc: kvm-ppc at vger.kernel.org
> > Signed-off-by: Michael Roth <mdroth at linux.vnet.ibm.com>
> 
> Can we think of a Fixes tag?

For this particular issue I think:

Fixes: 755563bc79c7 ("powerpc/powernv: Fixes for hypervisor doorbell handling") # v4.0

> 
> > ---
> >  arch/powerpc/include/asm/kvm_ppc.h | 1 +
> >  1 file changed, 1 insertion(+)
> >
> > diff --git a/arch/powerpc/include/asm/kvm_ppc.h b/arch/powerpc/include/asm/kvm_ppc.h
> > index 2484e6a8f5ca..254abad0f55e 100644
> > --- a/arch/powerpc/include/asm/kvm_ppc.h
> > +++ b/arch/powerpc/include/asm/kvm_ppc.h
> > @@ -454,6 +454,7 @@ static inline u32 kvmppc_get_xics_latch(void)
> >  
> >  static inline void kvmppc_set_host_ipi(int cpu, u8 host_ipi)
> >  {
> > +     smp_mb();
> 
> This needs a big comment explaining why it's there and what it orders vs
> what. I know you explained it all in the change log, but people don't
> see that when they're browsing the code, so we need a summarised version
> in a comment here please.

Yes, of course.

Thanks!

> 
> >       paca_ptrs[cpu]->kvm_hstate.host_ipi = host_ipi;
> >  }
> 
> 
> cheers


More information about the Linuxppc-dev mailing list