Re: [PATCH v2] KVM: PPC: Book3S HV: use smp_mb() when setting/clearing host_ipi flag

[Paul Mackerras <paulus@ozlabs.org>]

On Wed, Sep 11, 2019 at 05:31:55PM -0500, Michael Roth wrote:
> On a 2-socket Power9 system with 32 cores/128 threads (SMT4) and 1TB
> of memory running the following guest configs:
> 
>   guest A:
>     - 224GB of memory
>     - 56 VCPUs (sockets=1,cores(,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\x10a/1/0x4000000000000002 softirqT08/5408 fqs\x1941
>   [ 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\x10a/1/0x4000000000000002 softirqT08/5408 fqs‚43
>   [ 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\x10a/1/0x4000000000000002 softirqT08/5408 fqs\x14714
>   [ 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\x10a/1/0x4000000000000002 softirqT08/5408 fqs!403
>   [ 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
> 
> CPUs 45, 24, and 124 are stuck on spin locks, likely held by
> CPUs 105 and 31.
> 
> CPUs 105 and 31 are stuck in smp_call_function_many(), waiting on
> target CPU 42. For instance:
> 
>   # CPU 105 registers (via xmon)
>   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:
> 
>   # CPU 42 stack trace (via xmon)
>   [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 by CPU 42, causing the
> callers 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):
> 
>     CPU
>       X: smp_muxed_ipi_set_message():
>       X:   smp_mb()
>       X:   message[RESCHEDULE] = 1
>       X: doorbell_global_ipi(42):
>       X:   kvmppc_set_host_ipi(42, 1)
>       X:   ppc_msgsnd_sync()/smp_mb()
>       X:   ppc_msgsnd() -> 42
>      42: doorbell_exception(): // from CPU X
>      42:   ppc_msgsync()
>     105: smp_muxed_ipi_set_message():
>     105:   smb_mb()
>          // STORE DEFERRED DUE TO RE-ORDERING
>   --105:   message[CALL_FUNCTION] = 1
>   | 105: doorbell_global_ipi(42):
>   | 105:   kvmppc_set_host_ipi(42, 1)
>   |  42:   kvmppc_set_host_ipi(42, 0)
>   |  42: smp_ipi_demux_relaxed()
>   |  42: // returns to executing guest
>   |      // RE-ORDERED STORE COMPLETES
>   ->105:   message[CALL_FUNCTION] = 1
>     105:   ppc_msgsnd_sync()/smp_mb()
>     105:   ppc_msgsnd() -> 42
>      42: local_paca->kvm_hstate.host_ipi = 0 // IPI ignored
>     105: // hangs waiting on 42 to process messages/call_single_queue
> 
> This can be prevented with an smp_mb() at the beginning of
> kvmppc_set_host_ipi(), such that stores to message[<type>] (or other
> state indicated by the host_ipi flag) are ordered vs. the store to
> to host_ipi.
> 
> However, doing so might still allow for the following scenario (not
> yet observed):
> 
>     CPU
>       X: smp_muxed_ipi_set_message():
>       X:   smp_mb()
>       X:   message[RESCHEDULE] = 1
>       X: doorbell_global_ipi(42):
>       X:   kvmppc_set_host_ipi(42, 1)
>       X:   ppc_msgsnd_sync()/smp_mb()
>       X:   ppc_msgsnd() -> 42
>      42: doorbell_exception(): // from CPU X
>      42:   ppc_msgsync()
>          // STORE DEFERRED DUE TO RE-ORDERING
>   -- 42:   kvmppc_set_host_ipi(42, 0)
>   |  42: smp_ipi_demux_relaxed()
>   | 105: smp_muxed_ipi_set_message():
>   | 105:   smb_mb()
>   | 105:   message[CALL_FUNCTION] = 1
>   | 105: doorbell_global_ipi(42):
>   | 105:   kvmppc_set_host_ipi(42, 1)
>   |      // RE-ORDERED STORE COMPLETES
>   -> 42:   kvmppc_set_host_ipi(42, 0)
>      42: // returns to executing guest
>     105:   ppc_msgsnd_sync()/smp_mb()
>     105:   ppc_msgsnd() -> 42
>      42: local_paca->kvm_hstate.host_ipi = 0 // IPI ignored
>     105: // hangs waiting on 42 to process messages/call_single_queue
> 
> Fixing this scenario would require an smp_mb() *after* clearing
> host_ipi flag in kvmppc_set_host_ipi() to order the store vs.
> subsequent processing of IPI messages.
> 
> To handle both cases, this patch splits kvmppc_set_host_ipi() into
> separate set/clear functions, where we execute smp_mb() prior to
> setting host_ipi flag, and after clearing host_ipi flag. These
> functions pair with each other to synchronize the sender and receiver
> sides.
> 
> With that change in place the above workload ran for 20 hours without
> triggering any lock-ups.
> 
> Fixes: 755563bc79c7 ("powerpc/powernv: Fixes for hypervisor doorbell handling") # v4.0
> Cc: Michael Ellerman <mpe@ellerman.id.au>
> Cc: Paul Mackerras <paulus@ozlabs.org>
> Cc: Nicholas Piggin <npiggin@gmail.com>
> Cc: kvm-ppc@vger.kernel.org
> Signed-off-by: Michael Roth <mdroth@linux.vnet.ibm.com>

Looks good, makes sense.

Acked-by: Paul Mackerras <paulus@ozlabs.org>