Re: [Xen-devel] Xen-unstable: xen panic RIP: dpci_softirq

["Jan Beulich" <JBeulich@xxxxxxxx>]

>>> On 17.11.14 at 19:01, <linux@xxxxxxxxxxxxxx> wrote:
> (XEN) [2014-11-17 17:54:18.695] CPU00:
> (XEN) [2014-11-17 17:54:18.705] CPU01:
> (XEN) [2014-11-17 17:54:18.716] d16 OK-softirq 62msec ago, state:1, 2628 
> count, 
> [prev:ffff83054ef57e70, next:ffff83054ef57e70] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:18.765] d16 OK-raise   112msec ago, state:1, 2628 
> count, [prev:0000000000200200, next:0000000000100100] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:18.815] CPU02:
> (XEN) [2014-11-17 17:54:18.825] d17 OK-softirq 500msec ago, state:1, 3439 
> count, [prev:ffff83054ef47e70, next:ffff83054ef47e70] ffff83051a1c8c28<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:18.875] d17 OK-raise   549msec ago, state:1, 3439 
> count, [prev:0000000000200200, next:0000000000100100] ffff83051a1c8c28<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:18.924] CPU03:
> (XEN) [2014-11-17 17:54:18.935] d16 OK-softirq 313msec ago, state:1, 3533 
> count, [prev:ffff83054ef37e70, next:ffff83054ef37e70] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:18.984] d16 OK-raise   363msec ago, state:1, 3533 
> count, [prev:0000000000200200, next:0000000000100100] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:19.034] CPU04:
> (XEN) [2014-11-17 17:54:19.044] d16 OK-softirq 359msec ago, state:1, 3691 
> count, [prev:ffff83054ef27e88, next:ffff83054ef27e88] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:19.094] d16 OK-raise   408msec ago, state:1, 3691 
> count, [prev:0000000000200200, next:0000000000100100] ffff83051b904428<NULL> 
> MAPPED_SHIFT GUEST_MSI_SHIFT  PIRQ:87
> (XEN) [2014-11-17 17:54:19.143] CPU05:
> (XEN) [2014-11-17 17:54:19.154] d16 OK-softirq 458msec ago, state:1, 52039 
> count, [prev:ffff83054ef283e0, next:ffff83054ef283e0] 
> ffff83051b95fd28MACH_PCI_SHIFT MAPPED_SHIFT GUEST_PCI_SHIFT  PIRQ:0
> (XEN) [2014-11-17 17:54:19.205] d16 OK-raise   489msec ago, state:1, 52049 
> count, [prev:0000000000200200, next:0000000000100100] 
> ffff83051b95fd28MACH_PCI_SHIFT MAPPED_SHIFT GUEST_PCI_SHIFT  PIRQ:0
> (XEN) [2014-11-17 17:54:19.257] d16 ERR-poison 561msec ago, state:0, 1 count, 
> [prev:0000000000200200, next:0000000000100100] ffff83051b95fd28MACH_PCI_SHIFT 
> MAPPED_SHIFT GUEST_PCI_SHIFT  PIRQ:0
> (XEN) [2014-11-17 17:54:19.307] d16 Z-softirq  731msec ago, state:3, 3 count, 
> [prev:ffff83054ef283e0, next:ffff83054ef283e0] ffff83051b95fd28MACH_PCI_SHIFT 
> MAPPED_SHIFT GUEST_PCI_SHIFT  PIRQ:0
> (XEN) [2014-11-17 17:54:19.356] domain_crash called from io.c:938
> (XEN) [2014-11-17 17:54:19.356] Domain 16 reported crashed by domain 32767 on 
> cpu#5:

I think what would help establishing the sequence of events would
be to at the very least calculate the times printed above relative to
a single NOW() invocation done in dump_debug() rather than
dump_record(). That may, however, yield meaningless values when
done at millisecond granularity. Hence, either using nanosecond
granularity or not using time values but a simple sequence counter
might be a desirable approach.

What puzzles me additionally is that for list_del() to encounter an
already removed entry, I'd expect the entry to (mistakenly) have
got added twice. Yet there's no sign of that (the most recent
OK-raise entry shows the list entry still having poisoned pointers).
Or it would need to have got inserted a second time on another
CPU, but the track record thereof having got overwritten. Perhaps
now that we suspect the legacy IRQ to be the problematic one the
patch could be adjusted to track only operations on non-MSI IRQs
(or separately all three PT_IRQ_TYPE_*)?

Jan


_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel