Re: Xen-unstable: xen panic RIP: dpci_softirq

[Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>]

[-- Attachment #1: Type: text/plain, Size: 8588 bytes --]

On Tue, Nov 18, 2014 at 05:20:44PM +0000, Jan Beulich wrote:
> >>> On 18.11.14 at 18:03, <linux@eikelenboom.it> wrote:
> > Tuesday, November 18, 2014, 5:16:50 PM, you wrote:
> >>  1) test_and_[set|clear]_bit sometimes return unexpected values.
> >>     [But this might be invalid as the addition of the ffff8303faaf25a8
> >>      might be correct - as the second dpci the softirq is processing
> >>      could be the MSI one]
> > 
> > Would there be an easy way to stress test this function separately in some 
> > debugging function to see if it indeed is returning unexpected values ?
> 
> I don't think there's a reasonable chance of these functions to return
> "unexpected" values - they're being used elsewhere, and you'd have
> had other problems in the past if they didn't behave as expected.

Interestingly most of the 'test_and_[set|clear]_bit operate on 'unsigned long'
while we do 'unsigned int' here. But the 'test_and'' are all btXl so double-word
safe.

The fact that Sander is able to get 'test_and_clear_bit(STATE_SCHED)' to return
zero - when in fact it should return a positive value - implies that some actor
is messing with the 'state' outside our raise/softirq dialogue.

pt_irq_guest_eoi does pirq_dpci->state = 0 unconditionally!

Lets see if this debug + potential patch helps. This should be applied
on top of the other patch you had. Just in case I am attaching all four
to this email.

>From 8093140e374fceb9121ccd07726fb3898b212bfb Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Tue, 18 Nov 2014 15:08:15 -0500
Subject: [PATCH 4/5] DEBUG4: Add an 'stamp' and potential fix.

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 xen/drivers/passthrough/io.c | 57 +++++++++++++++++++++++++++++++-------------
 xen/include/xen/hvm/irq.h    |  1 +
 2 files changed, 41 insertions(+), 17 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index b786bd2..8a8fc62 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -26,6 +26,8 @@
 #include <asm/hvm/iommu.h>
 #include <asm/hvm/support.h>
 #include <xen/hvm/irq.h>
+#include <xen/console.h>
+
 
 static DEFINE_PER_CPU(struct list_head, dpci_list);
 
@@ -61,21 +63,29 @@ struct _debug_f {
     struct list_head list;
     unsigned int state;
     struct hvm_pirq_dpci *dpci;
+    unsigned long stamp;
 };
 
 struct __debug {
     struct _debug_f ok;
     struct _debug_f poison;
     struct _debug_f raise;
+    struct _debug_f busy_raise;
     struct _debug_f reset;
     struct _debug_f zombie_softirq;
     struct _debug_f zombie_raise;
+    struct _debug_f timeout;
+    struct _debug_f clear;
 };
 
 static DEFINE_PER_CPU(struct __debug, _d);
 
 void _record(struct _debug_f *d, struct hvm_pirq_dpci *pirq_dpci)
 {
+
+    if (pirq_dpci->pirq)
+        return;
+
     if (pirq_dpci->dom)
         d->domid = pirq_dpci->dom->domain_id;
     else
@@ -86,6 +96,7 @@ void _record(struct _debug_f *d, struct hvm_pirq_dpci *pirq_dpci)
     d->list.prev = pirq_dpci->softirq_list.prev;
     d->state = pirq_dpci->state;
     d->dpci = pirq_dpci;
+    d->stamp = pirq_dpci->stamp++;
 }
 
 enum {
@@ -95,6 +106,9 @@ enum {
     OK_SOFTIRQ,
     OK_RAISE,
     OK_RESET,
+    OK_TIMEOUT,
+    OK_BUSY,
+    OK_CLEAR,
 };
 
 static void dump_record(struct _debug_f *d, unsigned int type)
@@ -106,7 +120,11 @@ static void dump_record(struct _debug_f *d, unsigned int type)
         [OK_SOFTIRQ] = "OK-softirq",
         [OK_RAISE]   = "OK-raise  ",
         [OK_RESET]   = "OK-reset  ",
+        [OK_TIMEOUT] = "OK-timeout",
+        [OK_BUSY]    = "OK-busy   ",
+        [OK_CLEAR]   = "OK-clear  ",
     };
+#if 0
 #define LONG(x) [_HVM_IRQ_DPCI_##x] = #x
     static const char *const names_flag[] = {
         LONG(MACH_PCI_SHIFT),
@@ -117,6 +135,7 @@ static void dump_record(struct _debug_f *d, unsigned int type)
     };
 #undef LONG
     unsigned int i;
+#endif
     s_time_t now;
 
     if ( d->domid == 0 )
@@ -126,20 +145,21 @@ static void dump_record(struct _debug_f *d, unsigned int type)
         BUG();
 
     now = NOW();
-    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] %p",
+    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] %p %lx",
            d->domid, names[type],
            (unsigned long)((now - d->last) / MILLISECS(1)),
-            d->state, d->count, d->list.prev, d->list.next, d->dpci);
+            d->state, d->count, d->list.prev, d->list.next, d->dpci, d->stamp);
 
     if ( d->dpci )
     {
         struct hvm_pirq_dpci *pirq_dpci = d->dpci;
-
+#if 0
         for ( i = 0; i <= _HVM_IRQ_DPCI_GUEST_MSI_SHIFT; i++ )
             if ( pirq_dpci->flags & (1 << i) )
                 printk("%s ", names_flag[i]);
 
         printk(" PIRQ:%d", pirq_dpci->pirq);
+#endif
         if (pirq_dpci->line)
             printk(" LINE: %d", pirq_dpci->line);
     }
@@ -159,7 +179,10 @@ static void dump_debug(unsigned char key)
         printk("CPU%02d: \n" ,cpu);
         dump_record(&d->ok, OK_SOFTIRQ);
         dump_record(&d->raise, OK_RAISE);
+        dump_record(&d->busy_raise, OK_RAISE);
         dump_record(&d->reset, OK_RESET);
+        dump_record(&d->timeout, OK_TIMEOUT);
+        dump_record(&d->clear, OK_TIMEOUT);
         dump_record(&d->poison, ERR_POISON);
         dump_record(&d->zombie_softirq, Z_SOFTIRQ);
         dump_record(&d->zombie_raise, Z_RAISE);
@@ -184,8 +207,10 @@ static void raise_softirq_for(struct hvm_pirq_dpci *pirq_dpci)
         return;
     }
     if ( test_and_set_bit(STATE_SCHED, &pirq_dpci->state) )
+    {
+        _record(&d->busy_raise, pirq_dpci);
         return;
-
+    }
     _record(&d->raise, pirq_dpci);
 
     get_knownalive_domain(pirq_dpci->dom);
@@ -264,10 +289,14 @@ bool_t pt_irq_need_timer(uint32_t flags)
 static int pt_irq_guest_eoi(struct domain *d, struct hvm_pirq_dpci *pirq_dpci,
                             void *arg)
 {
+    struct __debug *debug = &__get_cpu_var(_d);
+
     if ( __test_and_clear_bit(_HVM_IRQ_DPCI_EOI_LATCH_SHIFT,
                               &pirq_dpci->flags) )
     {
-        pirq_dpci->state = 0;
+        _record(&debug->clear, pirq_dpci);
+        pt_pirq_softirq_reset(pirq_dpci);
+        /* pirq_dpci->state = 0; <= OUCH! */
         pirq_dpci->pending = 0;
         pirq_guest_eoi(dpci_pirq(pirq_dpci));
     }
@@ -280,11 +309,13 @@ static void pt_irq_time_out(void *data)
     struct hvm_pirq_dpci *irq_map = data;
     const struct hvm_irq_dpci *dpci;
     const struct dev_intx_gsi_link *digl;
-
+    struct __debug *d = &__get_cpu_var(_d);
     spin_lock(&irq_map->dom->event_lock);
 
     dpci = domain_get_irq_dpci(irq_map->dom);
     ASSERT(dpci);
+
+    _record(&d->timeout, irq_map);
     list_for_each_entry ( digl, &irq_map->digl_list, list )
     {
         unsigned int guest_gsi = hvm_pci_intx_gsi(digl->device, digl->intx);
@@ -302,6 +333,9 @@ static void pt_irq_time_out(void *data)
     pt_pirq_iterate(irq_map->dom, pt_irq_guest_eoi, NULL);
 
     spin_unlock(&irq_map->dom->event_lock);
+    console_start_sync();
+    dump_debug((char)0);
+    console_end_sync();
 }
 
 struct hvm_irq_dpci *domain_get_irq_dpci(const struct domain *d)
@@ -901,8 +935,6 @@ unlock:
     spin_unlock(&d->event_lock);
 }
 
-#include <xen/console.h>
-
 /*
  * Note: 'pt_pirq_softirq_reset' can clear the STATE_SCHED before we get to
  * doing it. If that is the case we let 'pt_pirq_softirq_reset' do ref-counting.
@@ -919,26 +951,17 @@ static void dpci_softirq(void)
             struct hvm_pirq_dpci *dpci;
     } l[4];
     unsigned int i = 0;
-#if DIFF_LIST
-    struct hvm_pirq_dpci *n;
-#endif
     debug = &per_cpu(_d, cpu);
 
     local_irq_disable();
     list_splice_init(&per_cpu(dpci_list, cpu), &our_list);
     local_irq_enable();
-#if DIFF_LIST
-    list_for_each_entry_safe(pirq_dpci, n, &our_list, softirq_list)
-#else
     while ( !list_empty(&our_list) )
-#endif
     {
         struct domain *d;
         struct list_head *entry;
 
-#ifndef DIFF_LIST
         pirq_dpci = list_entry(our_list.next, struct hvm_pirq_dpci, softirq_list);
-#endif
         entry = &pirq_dpci->softirq_list;
         if ( i <= 3 )
         {
diff --git a/xen/include/xen/hvm/irq.h b/xen/include/xen/hvm/irq.h
index 1fb1292..f5b6061 100644
--- a/xen/include/xen/hvm/irq.h
+++ b/xen/include/xen/hvm/irq.h
@@ -102,6 +102,7 @@ struct hvm_pirq_dpci {
     struct list_head softirq_list;
     unsigned int pirq;
     unsigned int line;
+    unsigned long stamp;
 };
 
 void pt_pirq_init(struct domain *, struct hvm_pirq_dpci *);
-- 
1.9.3


[-- Attachment #2: 0001-dpci-Add-ZOMBIE-state.patch --]
[-- Type: text/plain, Size: 3334 bytes --]

>From b8c267ea34663a9585e1aee9c09dede240b546f9 Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Fri, 14 Nov 2014 12:15:26 -0500
Subject: [PATCH 1/5] dpci: Add ZOMBIE state.

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 xen/drivers/passthrough/io.c | 29 ++++++++++++++++++++++-------
 1 file changed, 22 insertions(+), 7 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index efc66dc..8e9141e 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -50,20 +50,25 @@ static DEFINE_PER_CPU(struct list_head, dpci_list);
 
 enum {
     STATE_SCHED,
-    STATE_RUN
+    STATE_RUN,
+    STATE_ZOMBIE
 };
 
 /*
  * This can be called multiple times, but the softirq is only raised once.
- * That is until the STATE_SCHED state has been cleared. The state can be
- * cleared by: the 'dpci_softirq' (when it has executed 'hvm_dirq_assist'),
- * or by 'pt_pirq_softirq_reset' (which will try to clear the state before
- * the softirq had a chance to run).
+ * That is until the STATE_SCHED and STATE_ZOMBIE state has been cleared. The
+ * STATE_SCHED and STATE_ZOMBIE state can be cleared by the 'dpci_softirq'
+ * (when it has executed 'hvm_dirq_assist'). The STATE_SCHED can be cleared
+ * by 'pt_pirq_softirq_reset' (which will try to clear the state before the
+ * softirq had a chance to run).
  */
 static void raise_softirq_for(struct hvm_pirq_dpci *pirq_dpci)
 {
     unsigned long flags;
 
+    if ( test_bit(STATE_ZOMBIE, &pirq_dpci->state) )
+        return;
+
     if ( test_and_set_bit(STATE_SCHED, &pirq_dpci->state) )
         return;
 
@@ -85,7 +90,7 @@ static void raise_softirq_for(struct hvm_pirq_dpci *pirq_dpci)
  */
 bool_t pt_pirq_softirq_active(struct hvm_pirq_dpci *pirq_dpci)
 {
-    if ( pirq_dpci->state & ((1 << STATE_RUN) | (1 << STATE_SCHED)) )
+    if ( pirq_dpci->state & ((1 << STATE_RUN) | (1 << STATE_SCHED) | (1 << STATE_ZOMBIE) ) )
         return 1;
 
     /*
@@ -109,7 +114,7 @@ static void pt_pirq_softirq_reset(struct hvm_pirq_dpci *pirq_dpci)
 
     ASSERT(spin_is_locked(&d->event_lock));
 
-    switch ( cmpxchg(&pirq_dpci->state, 1 << STATE_SCHED, 0) )
+    switch ( cmpxchg(&pirq_dpci->state, 1 << STATE_SCHED, 1 << STATE_ZOMBIE ) )
     {
     case (1 << STATE_SCHED):
         /*
@@ -120,6 +125,7 @@ static void pt_pirq_softirq_reset(struct hvm_pirq_dpci *pirq_dpci)
         /* fallthrough. */
     case (1 << STATE_RUN):
     case (1 << STATE_RUN) | (1 << STATE_SCHED):
+    case (1 << STATE_RUN) | (1 << STATE_SCHED) | (1 << STATE_ZOMBIE):
         /*
          * The reason it is OK to reset 'dom' when STATE_RUN bit is set is due
          * to a shortcut the 'dpci_softirq' implements. It stashes the 'dom'
@@ -779,6 +785,7 @@ unlock:
 static void dpci_softirq(void)
 {
     unsigned int cpu = smp_processor_id();
+    unsigned int reset = 0;
     LIST_HEAD(our_list);
 
     local_irq_disable();
@@ -805,7 +812,15 @@ static void dpci_softirq(void)
             hvm_dirq_assist(d, pirq_dpci);
             put_domain(d);
         }
+        else
+            reset = 1;
+
         clear_bit(STATE_RUN, &pirq_dpci->state);
+        if ( reset )
+        {
+            clear_bit(STATE_ZOMBIE, &pirq_dpci->state);
+            reset = 0;
+        }
     }
 }
 
-- 
1.9.3


[-- Attachment #3: 0002-debug.patch --]
[-- Type: text/plain, Size: 9583 bytes --]

>From a4171fa12583eabd126bc5b4c305f49b2fb2b515 Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Fri, 14 Nov 2014 15:00:39 -0500
Subject: [PATCH 2/5] debug:

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 xen/drivers/passthrough/io.c | 180 ++++++++++++++++++++++++++++++++++++++++++-
 xen/include/xen/hvm/irq.h    |   2 +
 2 files changed, 178 insertions(+), 4 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 8e9141e..23e5ed1 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -54,6 +54,117 @@ enum {
     STATE_ZOMBIE
 };
 
+struct _debug_f {
+    unsigned int domid;
+    unsigned long count;
+    s_time_t last;
+    struct list_head list;
+    unsigned int state;
+    struct hvm_pirq_dpci *dpci;
+};
+
+struct __debug {
+    struct _debug_f ok;
+    struct _debug_f poison;
+    struct _debug_f raise;
+    struct _debug_f reset;
+    struct _debug_f zombie_softirq;
+    struct _debug_f zombie_raise;
+};
+
+static DEFINE_PER_CPU(struct __debug, _d);
+
+void _record(struct _debug_f *d, struct hvm_pirq_dpci *pirq_dpci)
+{
+    if (pirq_dpci->dom)
+        d->domid = pirq_dpci->dom->domain_id;
+    else
+        d->domid = 0xdead;
+    d->count ++;
+    d->last = NOW();
+    d->list.next = pirq_dpci->softirq_list.next;
+    d->list.prev = pirq_dpci->softirq_list.prev;
+    d->state = pirq_dpci->state;
+    d->dpci = pirq_dpci;
+}
+
+enum {
+    Z_SOFTIRQ,
+    Z_RAISE,
+    ERR_POISON,
+    OK_SOFTIRQ,
+    OK_RAISE,
+    OK_RESET,
+};
+
+static void dump_record(struct _debug_f *d, unsigned int type)
+{
+    static const char *const names[] = {
+        [Z_SOFTIRQ]  = "Z-softirq ",
+        [Z_RAISE]    = "Z-raise   ",
+        [ERR_POISON] = "ERR-poison",
+        [OK_SOFTIRQ] = "OK-softirq",
+        [OK_RAISE]   = "OK-raise  ",
+        [OK_RESET]   = "OK-reset  ",
+    };
+#define LONG(x) [_HVM_IRQ_DPCI_##x] = #x
+    static const char *const names_flag[] = {
+        LONG(MACH_PCI_SHIFT),
+        LONG(MAPPED_SHIFT),
+        LONG(EOI_LATCH_SHIFT),
+        LONG(GUEST_PCI_SHIFT),
+        LONG(GUEST_MSI_SHIFT),
+    };
+#undef LONG
+    unsigned int i;
+    s_time_t now;
+
+    if ( d->domid == 0 )
+        return;
+
+    if ( type >= ARRAY_SIZE(names) )
+        BUG();
+
+    now = NOW();
+    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] ",
+           d->domid, names[type],
+           (unsigned long)((now - d->last) / MILLISECS(1)),
+            d->state, d->count, d->list.prev, d->list.next);
+
+    if ( d->dpci )
+    {
+        struct hvm_pirq_dpci *pirq_dpci = d->dpci;
+
+        for ( i = 0; i <= _HVM_IRQ_DPCI_GUEST_MSI_SHIFT; i++ )
+            if ( pirq_dpci->flags & 1 << _HVM_IRQ_DPCI_TRANSLATE_SHIFT )
+                printk("%s ", names_flag[i]);
+
+        printk(" PIRQ:%d", pirq_dpci->pirq);
+        if (pirq_dpci->line)
+            printk(" LINE: %d", pirq_dpci->line);
+    }
+    printk("\n");
+    memset(d, 0, sizeof(struct _debug_f));
+}
+
+static void dump_debug(unsigned char key)
+{
+    unsigned int cpu;
+
+    for_each_online_cpu ( cpu )
+    {
+        struct __debug *d;
+        d = &per_cpu(_d, cpu);
+
+        printk("CPU%02d: \n" ,cpu);
+        dump_record(&d->ok, OK_SOFTIRQ);
+        dump_record(&d->raise, OK_RAISE);
+        dump_record(&d->reset, OK_RESET);
+        dump_record(&d->poison, ERR_POISON);
+        dump_record(&d->zombie_softirq, Z_SOFTIRQ);
+        dump_record(&d->zombie_raise, Z_RAISE);
+    }
+}
 /*
  * This can be called multiple times, but the softirq is only raised once.
  * That is until the STATE_SCHED and STATE_ZOMBIE state has been cleared. The
@@ -65,13 +176,18 @@ enum {
 static void raise_softirq_for(struct hvm_pirq_dpci *pirq_dpci)
 {
     unsigned long flags;
+    struct __debug *d = &__get_cpu_var(_d);
 
     if ( test_bit(STATE_ZOMBIE, &pirq_dpci->state) )
+    {
+        _record(&d->zombie_raise, pirq_dpci);
         return;
-
+    }
     if ( test_and_set_bit(STATE_SCHED, &pirq_dpci->state) )
         return;
 
+    _record(&d->raise, pirq_dpci);
+
     get_knownalive_domain(pirq_dpci->dom);
 
     local_irq_save(flags);
@@ -111,9 +227,12 @@ bool_t pt_pirq_softirq_active(struct hvm_pirq_dpci *pirq_dpci)
 static void pt_pirq_softirq_reset(struct hvm_pirq_dpci *pirq_dpci)
 {
     struct domain *d = pirq_dpci->dom;
+    struct __debug *debug = &__get_cpu_var(_d);
 
     ASSERT(spin_is_locked(&d->event_lock));
 
+    _record(&debug->reset, pirq_dpci);
+
     switch ( cmpxchg(&pirq_dpci->state, 1 << STATE_SCHED, 1 << STATE_ZOMBIE ) )
     {
     case (1 << STATE_SCHED):
@@ -277,6 +396,7 @@ int pt_irq_create_bind(
              * As such on every 'pt_irq_create_bind' call we MUST set it.
              */
             pirq_dpci->dom = d;
+            pirq_dpci->pirq = pirq;
             /* bind after hvm_irq_dpci is setup to avoid race with irq handler*/
             rc = pirq_guest_bind(d->vcpu[0], info, 0);
             if ( rc == 0 && pt_irq_bind->u.msi.gtable )
@@ -291,6 +411,7 @@ int pt_irq_create_bind(
                      * to be scheduled but we must deal with the one that may be
                      * in the queue.
                      */
+                    pirq_dpci->line = __LINE__;
                     pt_pirq_softirq_reset(pirq_dpci);
                 }
             }
@@ -300,6 +421,7 @@ int pt_irq_create_bind(
                 pirq_dpci->gmsi.gvec = 0;
                 pirq_dpci->dom = NULL;
                 pirq_dpci->flags = 0;
+                pirq_dpci->pirq = -pirq;
                 pirq_cleanup_check(info, d);
                 spin_unlock(&d->event_lock);
                 return rc;
@@ -544,6 +666,7 @@ int pt_irq_destroy_bind(
          * See comment in pt_irq_create_bind's PT_IRQ_TYPE_MSI before the
          * call to pt_pirq_softirq_reset.
          */
+        pirq_dpci->line = __LINE__;
         pt_pirq_softirq_reset(pirq_dpci);
 
         pirq_cleanup_check(pirq, d);
@@ -778,6 +901,8 @@ unlock:
     spin_unlock(&d->event_lock);
 }
 
+#include <xen/console.h>
+
 /*
  * Note: 'pt_pirq_softirq_reset' can clear the STATE_SCHED before we get to
  * doing it. If that is the case we let 'pt_pirq_softirq_reset' do ref-counting.
@@ -787,6 +912,9 @@ static void dpci_softirq(void)
     unsigned int cpu = smp_processor_id();
     unsigned int reset = 0;
     LIST_HEAD(our_list);
+    struct __debug *debug;
+
+    debug = &per_cpu(_d, cpu);
 
     local_irq_disable();
     list_splice_init(&per_cpu(dpci_list, cpu), &our_list);
@@ -796,9 +924,22 @@ static void dpci_softirq(void)
     {
         struct hvm_pirq_dpci *pirq_dpci;
         struct domain *d;
+        struct list_head *entry;
 
         pirq_dpci = list_entry(our_list.next, struct hvm_pirq_dpci, softirq_list);
-        list_del(&pirq_dpci->softirq_list);
+        entry = &pirq_dpci->softirq_list;
+        if ( entry->next == LIST_POISON1 || entry->next == LIST_POISON2 ||
+             entry->prev == LIST_POISON2 || entry->prev == LIST_POISON2 )
+        {
+            _record(&debug->poison, pirq_dpci);
+            console_start_sync();
+            dump_debug((char)0);
+            console_end_sync();
+            domain_crash(pirq_dpci->dom);
+            break;
+        }
+        _record(&debug->ok, pirq_dpci);
+        list_del(entry);
 
         d = pirq_dpci->dom;
         smp_mb(); /* 'd' MUST be saved before we set/clear the bits. */
@@ -813,8 +954,10 @@ static void dpci_softirq(void)
             put_domain(d);
         }
         else
+        {
+            _record(&debug->zombie_softirq, pirq_dpci);
             reset = 1;
-
+        }
         clear_bit(STATE_RUN, &pirq_dpci->state);
         if ( reset )
         {
@@ -833,6 +976,7 @@ static int cpu_callback(
     {
     case CPU_UP_PREPARE:
         INIT_LIST_HEAD(&per_cpu(dpci_list, cpu));
+        memset(&per_cpu(_d, cpu), 0, sizeof(struct __debug));
         break;
     case CPU_UP_CANCELED:
     case CPU_DEAD:
@@ -854,15 +998,43 @@ static struct notifier_block cpu_nfb = {
     .notifier_call = cpu_callback,
 };
 
+#include <xen/keyhandler.h>
+
+static struct keyhandler dump_debug_keyhandler = {
+    .diagnostic = 1,
+    .u.fn = dump_debug,
+    .desc = "dpci debug stats"
+};
+static struct timer debug_timer;
+static s_time_t last_time = 0;
+static unsigned int debug_cnt = 0;
+
+static void debug_timer_fn(void *d)
+{
+    if ( ( debug_cnt ++ % 10 ) == 0 )
+        printk("--MARK--\n");
+
+    last_time = NOW();
+    set_timer(&debug_timer, last_time + SECONDS(1));
+}
+
 static int __init setup_dpci_softirq(void)
 {
     unsigned int cpu;
 
     for_each_online_cpu(cpu)
+    {
         INIT_LIST_HEAD(&per_cpu(dpci_list, cpu));
-
+        memset(&per_cpu(_d, cpu), 0, sizeof(struct __debug));
+    }
     open_softirq(HVM_DPCI_SOFTIRQ, dpci_softirq);
     register_cpu_notifier(&cpu_nfb);
+
+    init_timer(&debug_timer, debug_timer_fn, NULL, smp_processor_id());
+    last_time = NOW();
+    set_timer(&debug_timer, NOW() + SECONDS(1));
+    register_keyhandler('k', &dump_debug_keyhandler);
+
     return 0;
 }
 __initcall(setup_dpci_softirq);
diff --git a/xen/include/xen/hvm/irq.h b/xen/include/xen/hvm/irq.h
index 9709397..1fb1292 100644
--- a/xen/include/xen/hvm/irq.h
+++ b/xen/include/xen/hvm/irq.h
@@ -100,6 +100,8 @@ struct hvm_pirq_dpci {
     struct hvm_gmsi_info gmsi;
     struct timer timer;
     struct list_head softirq_list;
+    unsigned int pirq;
+    unsigned int line;
 };
 
 void pt_pirq_init(struct domain *, struct hvm_pirq_dpci *);
-- 
1.9.3


[-- Attachment #4: 0003-DEBUG-2.patch --]
[-- Type: text/plain, Size: 3522 bytes --]

>From 3163117e2ceb8dfcc11545dcc385aa3d147614e8 Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Mon, 17 Nov 2014 17:32:43 -0500
Subject: [PATCH 3/5] DEBUG 2

---
 xen/drivers/passthrough/io.c | 42 ++++++++++++++++++++++++++++++++++--------
 1 file changed, 34 insertions(+), 8 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 23e5ed1..b786bd2 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -126,17 +126,17 @@ static void dump_record(struct _debug_f *d, unsigned int type)
         BUG();
 
     now = NOW();
-    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] ",
+    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] %p",
            d->domid, names[type],
            (unsigned long)((now - d->last) / MILLISECS(1)),
-            d->state, d->count, d->list.prev, d->list.next);
+            d->state, d->count, d->list.prev, d->list.next, d->dpci);
 
     if ( d->dpci )
     {
         struct hvm_pirq_dpci *pirq_dpci = d->dpci;
 
         for ( i = 0; i <= _HVM_IRQ_DPCI_GUEST_MSI_SHIFT; i++ )
-            if ( pirq_dpci->flags & 1 << _HVM_IRQ_DPCI_TRANSLATE_SHIFT )
+            if ( pirq_dpci->flags & (1 << i) )
                 printk("%s ", names_flag[i]);
 
         printk(" PIRQ:%d", pirq_dpci->pirq);
@@ -545,9 +545,9 @@ int pt_irq_create_bind(
 
         if ( iommu_verbose )
             dprintk(XENLOG_G_INFO,
-                    "d%d: bind: m_gsi=%u g_gsi=%u dev=%02x.%02x.%u intx=%u\n",
+                    "d%d: bind: m_gsi=%u g_gsi=%u dev=%02x.%02x.%u intx=%u %p\n",
                     d->domain_id, pirq, guest_gsi, bus,
-                    PCI_SLOT(device), PCI_FUNC(device), intx);
+                    PCI_SLOT(device), PCI_FUNC(device), intx, pirq_dpci);
         break;
     }
 
@@ -913,26 +913,52 @@ static void dpci_softirq(void)
     unsigned int reset = 0;
     LIST_HEAD(our_list);
     struct __debug *debug;
-
+    struct hvm_pirq_dpci *pirq_dpci;
+    struct __x {
+            struct list_head l;
+            struct hvm_pirq_dpci *dpci;
+    } l[4];
+    unsigned int i = 0;
+#if DIFF_LIST
+    struct hvm_pirq_dpci *n;
+#endif
     debug = &per_cpu(_d, cpu);
 
     local_irq_disable();
     list_splice_init(&per_cpu(dpci_list, cpu), &our_list);
     local_irq_enable();
-
+#if DIFF_LIST
+    list_for_each_entry_safe(pirq_dpci, n, &our_list, softirq_list)
+#else
     while ( !list_empty(&our_list) )
+#endif
     {
-        struct hvm_pirq_dpci *pirq_dpci;
         struct domain *d;
         struct list_head *entry;
 
+#ifndef DIFF_LIST
         pirq_dpci = list_entry(our_list.next, struct hvm_pirq_dpci, softirq_list);
+#endif
         entry = &pirq_dpci->softirq_list;
+        if ( i <= 3 )
+        {
+            struct __x *p;
+
+            p = &l[i];
+            p->dpci = pirq_dpci;
+            p->l.prev = entry->prev;
+            p->l.next = entry->next;
+            i++;
+        }
         if ( entry->next == LIST_POISON1 || entry->next == LIST_POISON2 ||
              entry->prev == LIST_POISON2 || entry->prev == LIST_POISON2 )
         {
+            unsigned int j;
+
             _record(&debug->poison, pirq_dpci);
             console_start_sync();
+            for (j=0; j < i;j++)
+                printk(" %u: %p [p:%p, n:%p]\n", j, l[j].dpci, l[j].l.prev, l[j].l.next);
             dump_debug((char)0);
             console_end_sync();
             domain_crash(pirq_dpci->dom);
-- 
1.9.3


[-- Attachment #5: 0004-DEBUG4-Add-an-stamp-and-potential-fix.patch --]
[-- Type: text/plain, Size: 7175 bytes --]

>From 8093140e374fceb9121ccd07726fb3898b212bfb Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Tue, 18 Nov 2014 15:08:15 -0500
Subject: [PATCH 4/5] DEBUG4: Add an 'stamp' and potential fix.

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 xen/drivers/passthrough/io.c | 57 +++++++++++++++++++++++++++++++-------------
 xen/include/xen/hvm/irq.h    |  1 +
 2 files changed, 41 insertions(+), 17 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index b786bd2..8a8fc62 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -26,6 +26,8 @@
 #include <asm/hvm/iommu.h>
 #include <asm/hvm/support.h>
 #include <xen/hvm/irq.h>
+#include <xen/console.h>
+
 
 static DEFINE_PER_CPU(struct list_head, dpci_list);
 
@@ -61,21 +63,29 @@ struct _debug_f {
     struct list_head list;
     unsigned int state;
     struct hvm_pirq_dpci *dpci;
+    unsigned long stamp;
 };
 
 struct __debug {
     struct _debug_f ok;
     struct _debug_f poison;
     struct _debug_f raise;
+    struct _debug_f busy_raise;
     struct _debug_f reset;
     struct _debug_f zombie_softirq;
     struct _debug_f zombie_raise;
+    struct _debug_f timeout;
+    struct _debug_f clear;
 };
 
 static DEFINE_PER_CPU(struct __debug, _d);
 
 void _record(struct _debug_f *d, struct hvm_pirq_dpci *pirq_dpci)
 {
+
+    if (pirq_dpci->pirq)
+        return;
+
     if (pirq_dpci->dom)
         d->domid = pirq_dpci->dom->domain_id;
     else
@@ -86,6 +96,7 @@ void _record(struct _debug_f *d, struct hvm_pirq_dpci *pirq_dpci)
     d->list.prev = pirq_dpci->softirq_list.prev;
     d->state = pirq_dpci->state;
     d->dpci = pirq_dpci;
+    d->stamp = pirq_dpci->stamp++;
 }
 
 enum {
@@ -95,6 +106,9 @@ enum {
     OK_SOFTIRQ,
     OK_RAISE,
     OK_RESET,
+    OK_TIMEOUT,
+    OK_BUSY,
+    OK_CLEAR,
 };
 
 static void dump_record(struct _debug_f *d, unsigned int type)
@@ -106,7 +120,11 @@ static void dump_record(struct _debug_f *d, unsigned int type)
         [OK_SOFTIRQ] = "OK-softirq",
         [OK_RAISE]   = "OK-raise  ",
         [OK_RESET]   = "OK-reset  ",
+        [OK_TIMEOUT] = "OK-timeout",
+        [OK_BUSY]    = "OK-busy   ",
+        [OK_CLEAR]   = "OK-clear  ",
     };
+#if 0
 #define LONG(x) [_HVM_IRQ_DPCI_##x] = #x
     static const char *const names_flag[] = {
         LONG(MACH_PCI_SHIFT),
@@ -117,6 +135,7 @@ static void dump_record(struct _debug_f *d, unsigned int type)
     };
 #undef LONG
     unsigned int i;
+#endif
     s_time_t now;
 
     if ( d->domid == 0 )
@@ -126,20 +145,21 @@ static void dump_record(struct _debug_f *d, unsigned int type)
         BUG();
 
     now = NOW();
-    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] %p",
+    printk("d%d %s %lumsec ago, state:%x, %ld count, [prev:%p, next:%p] %p %lx",
            d->domid, names[type],
            (unsigned long)((now - d->last) / MILLISECS(1)),
-            d->state, d->count, d->list.prev, d->list.next, d->dpci);
+            d->state, d->count, d->list.prev, d->list.next, d->dpci, d->stamp);
 
     if ( d->dpci )
     {
         struct hvm_pirq_dpci *pirq_dpci = d->dpci;
-
+#if 0
         for ( i = 0; i <= _HVM_IRQ_DPCI_GUEST_MSI_SHIFT; i++ )
             if ( pirq_dpci->flags & (1 << i) )
                 printk("%s ", names_flag[i]);
 
         printk(" PIRQ:%d", pirq_dpci->pirq);
+#endif
         if (pirq_dpci->line)
             printk(" LINE: %d", pirq_dpci->line);
     }
@@ -159,7 +179,10 @@ static void dump_debug(unsigned char key)
         printk("CPU%02d: \n" ,cpu);
         dump_record(&d->ok, OK_SOFTIRQ);
         dump_record(&d->raise, OK_RAISE);
+        dump_record(&d->busy_raise, OK_RAISE);
         dump_record(&d->reset, OK_RESET);
+        dump_record(&d->timeout, OK_TIMEOUT);
+        dump_record(&d->clear, OK_TIMEOUT);
         dump_record(&d->poison, ERR_POISON);
         dump_record(&d->zombie_softirq, Z_SOFTIRQ);
         dump_record(&d->zombie_raise, Z_RAISE);
@@ -184,8 +207,10 @@ static void raise_softirq_for(struct hvm_pirq_dpci *pirq_dpci)
         return;
     }
     if ( test_and_set_bit(STATE_SCHED, &pirq_dpci->state) )
+    {
+        _record(&d->busy_raise, pirq_dpci);
         return;
-
+    }
     _record(&d->raise, pirq_dpci);
 
     get_knownalive_domain(pirq_dpci->dom);
@@ -264,10 +289,14 @@ bool_t pt_irq_need_timer(uint32_t flags)
 static int pt_irq_guest_eoi(struct domain *d, struct hvm_pirq_dpci *pirq_dpci,
                             void *arg)
 {
+    struct __debug *debug = &__get_cpu_var(_d);
+
     if ( __test_and_clear_bit(_HVM_IRQ_DPCI_EOI_LATCH_SHIFT,
                               &pirq_dpci->flags) )
     {
-        pirq_dpci->state = 0;
+        _record(&debug->clear, pirq_dpci);
+        pt_pirq_softirq_reset(pirq_dpci);
+        /* pirq_dpci->state = 0; <= OUCH! */
         pirq_dpci->pending = 0;
         pirq_guest_eoi(dpci_pirq(pirq_dpci));
     }
@@ -280,11 +309,13 @@ static void pt_irq_time_out(void *data)
     struct hvm_pirq_dpci *irq_map = data;
     const struct hvm_irq_dpci *dpci;
     const struct dev_intx_gsi_link *digl;
-
+    struct __debug *d = &__get_cpu_var(_d);
     spin_lock(&irq_map->dom->event_lock);
 
     dpci = domain_get_irq_dpci(irq_map->dom);
     ASSERT(dpci);
+
+    _record(&d->timeout, irq_map);
     list_for_each_entry ( digl, &irq_map->digl_list, list )
     {
         unsigned int guest_gsi = hvm_pci_intx_gsi(digl->device, digl->intx);
@@ -302,6 +333,9 @@ static void pt_irq_time_out(void *data)
     pt_pirq_iterate(irq_map->dom, pt_irq_guest_eoi, NULL);
 
     spin_unlock(&irq_map->dom->event_lock);
+    console_start_sync();
+    dump_debug((char)0);
+    console_end_sync();
 }
 
 struct hvm_irq_dpci *domain_get_irq_dpci(const struct domain *d)
@@ -901,8 +935,6 @@ unlock:
     spin_unlock(&d->event_lock);
 }
 
-#include <xen/console.h>
-
 /*
  * Note: 'pt_pirq_softirq_reset' can clear the STATE_SCHED before we get to
  * doing it. If that is the case we let 'pt_pirq_softirq_reset' do ref-counting.
@@ -919,26 +951,17 @@ static void dpci_softirq(void)
             struct hvm_pirq_dpci *dpci;
     } l[4];
     unsigned int i = 0;
-#if DIFF_LIST
-    struct hvm_pirq_dpci *n;
-#endif
     debug = &per_cpu(_d, cpu);
 
     local_irq_disable();
     list_splice_init(&per_cpu(dpci_list, cpu), &our_list);
     local_irq_enable();
-#if DIFF_LIST
-    list_for_each_entry_safe(pirq_dpci, n, &our_list, softirq_list)
-#else
     while ( !list_empty(&our_list) )
-#endif
     {
         struct domain *d;
         struct list_head *entry;
 
-#ifndef DIFF_LIST
         pirq_dpci = list_entry(our_list.next, struct hvm_pirq_dpci, softirq_list);
-#endif
         entry = &pirq_dpci->softirq_list;
         if ( i <= 3 )
         {
diff --git a/xen/include/xen/hvm/irq.h b/xen/include/xen/hvm/irq.h
index 1fb1292..f5b6061 100644
--- a/xen/include/xen/hvm/irq.h
+++ b/xen/include/xen/hvm/irq.h
@@ -102,6 +102,7 @@ struct hvm_pirq_dpci {
     struct list_head softirq_list;
     unsigned int pirq;
     unsigned int line;
+    unsigned long stamp;
 };
 
 void pt_pirq_init(struct domain *, struct hvm_pirq_dpci *);
-- 
1.9.3


[-- Attachment #6: 0005-debug-Remove-the-MARK-code.patch --]
[-- Type: text/plain, Size: 1499 bytes --]

>From 8e0edc1e6d51eeb5a401f686adccefa623332bcd Mon Sep 17 00:00:00 2001
From: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
Date: Tue, 18 Nov 2014 15:29:12 -0500
Subject: [PATCH 5/5] debug: Remove the --MARK-- code.

We could use it to check every 1msec for some case and print
data, but we never used it.

Signed-off-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 xen/drivers/passthrough/io.c | 15 ---------------
 1 file changed, 15 deletions(-)

diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 8a8fc62..aad5607 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -1054,18 +1054,6 @@ static struct keyhandler dump_debug_keyhandler = {
     .u.fn = dump_debug,
     .desc = "dpci debug stats"
 };
-static struct timer debug_timer;
-static s_time_t last_time = 0;
-static unsigned int debug_cnt = 0;
-
-static void debug_timer_fn(void *d)
-{
-    if ( ( debug_cnt ++ % 10 ) == 0 )
-        printk("--MARK--\n");
-
-    last_time = NOW();
-    set_timer(&debug_timer, last_time + SECONDS(1));
-}
 
 static int __init setup_dpci_softirq(void)
 {
@@ -1079,9 +1067,6 @@ static int __init setup_dpci_softirq(void)
     open_softirq(HVM_DPCI_SOFTIRQ, dpci_softirq);
     register_cpu_notifier(&cpu_nfb);
 
-    init_timer(&debug_timer, debug_timer_fn, NULL, smp_processor_id());
-    last_time = NOW();
-    set_timer(&debug_timer, NOW() + SECONDS(1));
     register_keyhandler('k', &dump_debug_keyhandler);
 
     return 0;
-- 
1.9.3


[-- Attachment #7: Type: text/plain, Size: 126 bytes --]

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