Re: Strange PVM spinlock case revisited

[Ian Campbell <Ian.Campbell@citrix.com>]

On Fri, 2013-02-08 at 15:33 +0000, Stefan Bader wrote:
> A while ago I had been reporting an issue which causes Xen PVM guests
> to hang (apparently related to spinlocks). Since then I was able to
> gather a few more facts which I try to provide below. For the real
> reasons, I am still puzzled and would be thankful for any hints or
> direction.
> 
> - Happens with Xen 4.1.2 and Xen 4.2 host-side.
> - PVM guest with 8 VCPUs is running 800 threads doing DB updates.

This is on a host with >= 8 PCPUs, correct?

> - When hanging at least 2 VCPUs in xen_spin_lock_slow with the lock free.
>   IIRC the weird lock always belongs to one VCPU runqueue.
> - Testcase shows the problem for guest kernel versions v3.2..v3.5 (not
>   verified farther back). Since v3.6 it cannot be reproduced. Bisect
>   ends up with: 611ae8e3f5204f7480b3b405993b3352cfa16662
>     "x86/tlb: enable tlb flush range support for x86"

That seems like a very odd candidate for impacting on this issue.

> - The other potential fix for this was to prevent xen_spin_lock_slow()
>   from unmasking events (enabling interrupts) if those were enabled
>   before the spinlock call.
> 
> Maybe allowing or not allowing the interrupts in xen_spin_lock_slow
> just manages to tip the likelihood of getting nested deeper.

Either that or the bug is in the nesting aspect of xen_spin_lock_slow(),
which seems to be a rather complex dance judging from the comments in
that function (and one I confess I don't really follow).

>  The same
> way that the changed TLB flush may reduce it by causing lesser IPIs.

Ah, that might explain why that patch is relevant, yes.

> From the static information I can extract from a dump it is hard to
> tell what exactly is going on. VCPU2 seems to be doing something but
> looks to be rather deep in event handling. The irq_count is at 2, but
> irq_count seems to be used in a few more places than just xen_hypervisor
> callback. Though that at least seems to be the entry on the stack I can
> see for VCPU2. The contents of the per-cpu variables for irq_reqs and
> irq_stack_ptr at least seem consistent as if a callback came in while
> being on the sched_op hypercall. But then the bt command seems to be
> operating on a completely different stack.
> VCPU2 seems to be active, not polling (event processing could be initiated
> from enable_irqs via force callback or before finally exiting the sched_op
> hypercall), there seems to be a pending upcall but upcalls are masked.
> The next thing I would try is to instrument the sites incrementing and
> decrementing irq_count...
> ---
> 
> Below some of the info seen from dom0 debugging keys and looking
> at a dump with crash:
> 
> Dom0 Info:
> 
> Polling vCPUs: {1,5-7}
> VCPU0: CPU0 [has=F] poll=0  upcall_pend = 00, upcall_mask = 00
> VCPU1: CPU1 [has=F] poll=10 upcall_pend = 00, upcall_mask = 00
> VCPU2: CPU6 [has=T] poll=0  upcall_pend = 01, upcall_mask = 01
> VCPU3: CPU2 [has=F] poll=0  upcall_pend = 00, upcall_mask = 00
> VCPU4: CPU4 [has=F] poll=0  upcall_pend = 00, upcall_mask = 00
> VCPU5: CPU3 [has=F] poll=0  upcall_pend = 00, upcall_mask = 00
> VCPU6: CPU7 [has=F] poll=40 upcall_pend = 01, upcall_mask = 01
> VCPU7: CPU4 [has=F] poll=46 upcall_pend = 01, upcall_mask = 01
> 
> 10 [0/1]: s=6 n=1 x=0
> 40 [0/1]: s=6 n=6 x=0
> 46 [0/1]: s=6 n=7 x=0
> 
> Guest Info:
> 
> lock_spinners:
> [0] (struct xen_spinlock *) 0x
> [1] (struct xen_spinlock *) 0xffff8803bffc8ae8 = { lock=1, spinners=2 }
> [2] (struct xen_spinlock *) 0xffff8803bfc93700 = { lock=0, spinners=2 }

If I understand correctly this means that 2 threads (VCPU2 & 6, I
suppose) are spinning on this lock, but no one is holding it?

An interesting hack^Wexperiment might be to make xen_poll_irq use a
timeout and see if that unwedges things -- this would help confirm that
the issue is on nested wakeup.

I suppose xen_spin_unlock could also be instrumented to indicate who it
last kicked and for which lock and that might show us something?

Can someone explain why the non-locked update of lock_spinners in
spinning_lock() is safe against xen_spin_unlock reading the field from
another VCPU? I suspect it isn't, so what happens if the other VCPU
kicks the lock which is just about to become prev? maybe this is handled
in xen_spin_lock_slow somehow?

In a similar vein do we not need a barrier in unspinning_lock to ensure
that the remote cpu sees prev getting restored?

> [3] (struct xen_spinlock *) 0x
> [4] (struct xen_spinlock *) 0x
> [5] (struct xen_spinlock *) 0xffff8803bffc8ae8 -> [1]
> [6] (struct xen_spinlock *) 0xffff8803bfc93700 -> [2]
> [7] (struct xen_spinlock *) 0xffffffff81f15ef0 = { lock=1, spinners=1 }
> 
> VCPU[2,6] -> lock of runqueue[2] = (struct rq *) 0xffff8803bfc93700
> 
> irq_count[1] = 1
> irq_count[2] = 2
> It is -1 for the rest.
> 
> *(struct pt_regs *) irq_regs[2] = {
> 	.ip = 0xffffffff810013aa == hypercall_page+938 -> sched_op
> 	.sp = 0xffff8803bfc83ce8
> }
> 
> char *irq_stack_ptr[2] = 0xffff8803bfc83fc0
> 
> #> bt -T ffff88033d65c4a0
> PID: 2050   TASK: ffff88033d65c4a0  CPU: 2   COMMAND: "postgres"
>   [ffff88033d72d530] get_page_from_freelist at ffffffff8111e6df
>   [ffff88033d72d600] __alloc_pages_nodemask at ffffffff8111ebec
>   [ffff88033d72d620] check_preempt_curr at ffffffff81050254
>   [ffff88033d72d640] pull_task at ffffffff8105e33e
>   [ffff88033d72d670] balance_tasks at ffffffff8105e4b6
>   [ffff88033d72d680] radix_tree_lookup_slot at ffffffff8130db5e
>   [ffff88033d72d690] find_get_page at ffffffff811161ee
>   [ffff88033d72d6b0] find_lock_page at ffffffff81116286
>   [ffff88033d72d6e0] shmem_getpage_gfp at ffffffff8112dd10
>   [ffff88033d72d748] pte_pfn_to_mfn at ffffffff81005a78
>   [ffff88033d72d7a0] get_page_from_freelist at ffffffff8111e6df
>   [ffff88033d72d7c0] _raw_spin_lock at ffffffff81655e4e
>   [ffff88033d72d7d0] ext4_ext_check_cache at ffffffff81239248
>   [ffff88033d72d820] ext4_ext_map_blocks at ffffffff8123e269
>   [ffff88033d72d870] _raw_spin_lock at ffffffff81655e4e
>   [ffff88033d72d880] enqueue_to_backlog at ffffffff8153e55f
>   [ffff88033d72d890] __wake_up_common at ffffffff8104c1c8
>   [ffff88033d72d8e0] netif_rx.part.82 at ffffffff8153f2de
>   [ffff88033d72d920] netif_rx at ffffffff8153f400
>   [ffff88033d72d960] loopback_xmit at ffffffff8146fb1c
>   [ffff88033d72d990] dev_hard_start_xmit at ffffffff8153fea6
>   [ffff88033d72d9d0] do_softirq at ffffffff81016284
>   [ffff88033d72d9f0] local_bh_enable at ffffffff8106d614
>   [ffff88033d72da00] dev_queue_xmit at ffffffff81540309
>   [ffff88033d72da50] ip_finish_output at ffffffff815769ab
>   [ffff88033d72da90] ip_output at ffffffff81577518
>   [ffff88033d72dac0] ip_local_out at ffffffff81576c09
>   [ffff88033d72dae0] ip_send_skb at ffffffff81577f4b
>   [ffff88033d72db00] udp_send_skb at ffffffff8159aaa1
>   [ffff88033d72db40] ip_generic_getfrag at ffffffff81575030
>   [ffff88033d72db50] udp_sendmsg at ffffffff8159bd38
>   [ffff88033d72db90] irq_to_desc at ffffffff810d70b7
>   [ffff88033d72dbd0] notify_remote_via_irq at ffffffff813a74c1
>   [ffff88033d72dc10] ttwu_queue at ffffffff81052672
>   [ffff88033d72dc38] _raw_spin_unlock_irqrestore at ffffffff8165605e
>   [ffff88033d72dc90] inet_sendmsg at ffffffff815a6474
>   --- bt -t would end here
>   [ffff88033d72dcb0] apparmor_socket_sendmsg at ffffffff812d43f7
>   [ffff88033d72dcd0] sock_sendmsg at ffffffff815266fe
>   [ffff88033d72dd70] md_make_request at ffffffff814e0606
>   [ffff88033d72ddd0] kmem_cache_free at ffffffff811605cf
>   [ffff88033d72de10] mempool_free_slab at ffffffff81118507
>   [ffff88033d72de20] mempool_free at ffffffff811185b7
>   [ffff88033d72de50] sys_sendto at ffffffff8152974d
>   [ffff88033d72dee0] ext4_sync_file at ffffffff8120f07b
>   [ffff88033d72df00] vfs_write at ffffffff811764b0
>   [ffff88033d72df50] xen_hypervisor_callback at ffffffff816606db
>     RIP: 00007f6852c7b39a  RSP: 00007fff431454e0  RFLAGS: 00000212
>     RAX: 00007f6852fb38b8  RBX: 00007f6852fb3720  RCX: 000000000000014a
>     RDX: 0000000000000150  RSI: 0000000000000140  RDI: 00007f6852fb3720
>     RBP: 0000000000000150   R8: 0000000000000015   R9: 0000000000000000
>     R10: 0000000000000000  R11: 00007f6852c9174a  R12: 00007f6852fb3778
>     R13: 0000000000000140  R14: 00007f6852fb38b8  R15: 0000000000000001
>     ORIG_RAX: ffffffffffffffff  CS: e033  SS: e02b
> 
> #> bt -T ffff88033b812dc0
> PID: 2069   TASK: ffff88033b812dc0  CPU: 6   COMMAND: "postgres"
>   [ffff88033b897530] get_page_from_freelist at ffffffff8111e6df
>   [ffff88033b897600] __alloc_pages_nodemask at ffffffff8111ebec
>   [ffff88033b897640] radix_tree_lookup at ffffffff8130db6b
>   [ffff88033b897650] irq_to_desc at ffffffff810d70b7
>   [ffff88033b897660] irq_get_irq_data at ffffffff810d9f4e
>   [ffff88033b897670] balance_tasks at ffffffff8105e493
>   [ffff88033b897680] radix_tree_lookup_slot at ffffffff8130db5e
>   [ffff88033b897690] find_get_page at ffffffff811161ee
>   [ffff88033b8976b0] find_lock_page at ffffffff81116286
>   [ffff88033b8976e0] shmem_getpage_gfp at ffffffff8112dd10
>   [ffff88033b897748] pte_pfn_to_mfn at ffffffff81005a78
>   [ffff88033b897770] xen_set_pte_at at ffffffff81008e29
>   [ffff88033b897788] __raw_callee_save_xen_make_pte at ffffffff810052cd
>   [ffff88033b8977b0] unlock_page at ffffffff8111589a
>   [ffff88033b8977d0] __do_fault at ffffffff81138ac9
>   [ffff88033b8978a0] pvclock_clocksource_read at ffffffff8103dd15
>   [ffff88033b8978f0] xen_clocksource_read at ffffffff8100a850
>   [ffff88033b897900] sched_clock at ffffffff8101bd79
>   [ffff88033b897910] blk_rq_init at ffffffff812ec262
>   [ffff88033b897930] get_request at ffffffff812f004e
>   [ffff88033b8979c0] cpumask_next_and at ffffffff81308c66
>   [ffff88033b8979e0] find_busiest_group at ffffffff8105a061
>   --- bt -t ends here
>   [ffff88033b897a30] radix_tree_lookup at ffffffff8130db6b
>   [ffff88033b897a40] irq_to_desc at ffffffff810d70b7
>   [ffff88033b897a50] irq_get_irq_data at ffffffff810d9f4e
>   [ffff88033b897a60] info_for_irq at ffffffff813a636e
>   [ffff88033b897a80] xen_poll_irq_timeout at ffffffff813a696e
>   [ffff88033b897ac0] xen_poll_irq at ffffffff813a8450
>   [ffff88033b897ad0] xen_spin_lock_slow at ffffffff8163ad77
>   [ffff88033b897b20] xen_spin_lock at ffffffff810121da
>   [ffff88033b897b40] _raw_spin_lock at ffffffff81655e4e
>   [ffff88033b897b50] double_rq_lock at ffffffff8105119c
>   [ffff88033b897b80] load_balance at ffffffff8105e788
>   [ffff88033b897b88] _raw_spin_unlock_irqrestore at ffffffff8165605e
>   [ffff88033b897c10] idle_balance at ffffffff8163d57c
>   [ffff88033b897c60] __schedule at ffffffff81653ea9
>   [ffff88033b897cc0] sleep_on_page at ffffffff81115810
>   [ffff88033b897ce0] schedule at ffffffff81653fcf
>   [ffff88033b897cf0] io_schedule at ffffffff8165407f
>   [ffff88033b897d10] sleep_on_page at ffffffff8111581e
>   [ffff88033b897d20] __wait_on_bit at ffffffff8165489f
>   [ffff88033b897d70] wait_on_page_bit at ffffffff81115988
>   [ffff88033b897da0] wake_bit_function at ffffffff8108a140
>   [ffff88033b897dc0] filemap_fdatawait_range at ffffffff81115a9c
>   [ffff88033b897e60] do_writepages at ffffffff81120ee1
>   [ffff88033b897eb0] filemap_write_and_wait_range at ffffffff81117398
>   [ffff88033b897ee0] ext4_sync_file at ffffffff8120ef9f
>   [ffff88033b897f00] vfs_write at ffffffff811764b0
>   [ffff88033b897f40] do_fsync at ffffffff811a4a36
>   [ffff88033b897f70] sys_fdatasync at ffffffff811a4d83
>   [ffff88033b897f80] system_call_fastpath at ffffffff8165e442
>     RIP: 00007f6852ce8240  RSP: 00007fff43145618  RFLAGS: 00000246
>     RAX: 000000000000004b  RBX: ffffffff8165e442  RCX: 00007f6852ce1900
>     RDX: 00000000000000c5  RSI: 000000000000000c  RDI: 000000000000000c
>     RBP: 00000000000000c5   R8: 000000000073a550   R9: 0000000000000000
>     R10: 0000000000000004  R11: 0000000000000246  R12: ffffffff811a4d83
>     R13: ffff88033b897f78  R14: 0000000000000001  R15: 0000000000af7488
>     ORIG_RAX: 000000000000004b  CS: e033  SS: e02b
>