[PATCH OSSTEST] sg-run-job: Repeat rumpuserxen-demo-xenstorels test 150 times

[PATCH OSSTEST] sg-run-job: Repeat rumpuserxen-demo-xenstorels test 150 times

[Ian Campbell]

(Was: Re: [osstest test] 50423: regressions - FAIL)

On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
> On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
> > flight 50423 osstest real [real]
> > http://logs.test-lab.xenproject.org/osstest/logs/50423/
> > 
> > Regressions :-(
> > 
> > Tests which did not succeed and are blocking,
> > including tests which could not be run:
> >  test-amd64-amd64-rumpuserxen-amd64 15 rumpuserxen-demo-xenstorels/xenstorels.repeat fail REGR. vs. 50331
> 
> The previous pass of this must have been spurious. We should crank the
> number of repetitions I think.

I thought I'd sent such a patch, but no sign of it in the relevant
folders. Here's another.

I'm unsure if the testid should change, I think not in which case this
will take a force push to clear the is-a-regression-ness.

8<------------

>From b6ec9b81503b8e0a4fb3c529290e2da82b7421a4 Mon Sep 17 00:00:00 2001
From: Ian Campbell <ian.campbell@citrix.com>
Date: Fri, 17 Apr 2015 11:01:29 +0100
Subject: [PATCH] sg-run-job: Repeat rumpuserxen-demo-xenstorels test 150
times

With 50 we are still seeing occasional spurious passes.

Looking at some logs the current 50 iterations takes around 4 minutes
to run (3-4s per iteration).

I think we can justify spending 10 minutes running this test, which is
150x4s.

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>
---
 sg-run-job | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/sg-run-job b/sg-run-job
index 11e33a6..e393408 100755
--- a/sg-run-job
+++ b/sg-run-job
@@ -337,7 +337,7 @@ proc run-job/test-rumpuserxen {} {
     run-ts . =   ts-rumpuserxen-demo-setup      + host + $g
     run-ts . =   ts-rumpuserxen-demo-xenstorels + host + $g
     run-ts . =   ts-guest-destroy-hard          + host + $g
-    repeat-ts 50 =.repeat \
+    repeat-ts 150 =.repeat \
                  ts-rumpuserxen-demo-xenstorels + host + $g   + \; \
                  ts-guest-destroy-hard            host   $g   +
 }
-- 
2.1.4

Re: [PATCH OSSTEST] sg-run-job: Repeat rumpuserxen-demo-xenstorels test 150 times

[Ian Jackson]

Ian Campbell writes ("[PATCH OSSTEST] sg-run-job: Repeat rumpuserxen-demo-xenstorels test 150 times"):
> (Was: Re: [osstest test] 50423: regressions - FAIL)
...
> I thought I'd sent such a patch, but no sign of it in the relevant
> folders. Here's another.

Acked-by: Ian Jackson <ian.jackson@eu.citrix.com>

> I'm unsure if the testid should change, I think not in which case this
> will take a force push to clear the is-a-regression-ness.

IMO it should not, and indeed.

Ian.

kernel BUG at drivers/xen/grant-table.c:923!

[Ian Campbell]

(Was Re: [osstest test] 50423: regressions - FAIL)

This cropped up in an osstest flight (the results only go to Ian and I).

On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
> On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
> > flight 50423 osstest real [real]
> > http://logs.test-lab.xenproject.org/osstest/logs/50423/
> > 
> > Regressions :-(
> > 
> > Tests which did not succeed and are blocking,
> > including tests which could not be run:
> >  test-armhf-armhf-xl          15 guest-start/debian.repeat fail REGR. vs. 50331
> 
> 
> Looks to have been a real issue:
> 
> http://logs.test-lab.xenproject.org/osstest/logs/50423/test-armhf-armhf-xl/serial-cubietruck-gleizes.log
> Apr 14 19:01:21.834851 [ 1229.470934] ------------[ cut here ]------------
> Apr 14 19:01:22.445308 [ 1229.471001] kernel BUG at drivers/xen/grant-table.c:923!

This seems familiar, anyone remember it? (CCing ARM, netback and generic
Linux maintainers).

I had a look over

$ git log v3.16..origin/master -- drivers/net/xen-netback/ drivers/xen/ arch/*/xen

and nothing jumped out at me.

The new tests under flight include running tcpdump for the duration of
the migration. I wonder if that might have exposed the problem?

This is ARM for which osstest uses a 3.16 based kernel compared with x86
which is still on 3.14. That might explain why this was only seen on arm
(if tcpdump triggered it) or it might just be a very rare occurrence.

> Apr 14 19:01:22.450646 [ 1229.471026] Internal error: Oops - BUG: 0 [#1] SMP ARM
> Apr 14 19:01:22.455886 [ 1229.471052] Modules linked in: xen_gntalloc bridge stp ipv6 llc brcmfmac brcmutil cfg80211
> Apr 14 19:01:22.464140 [ 1229.471145] CPU: 0 PID: 18258 Comm: vif9.0-q0-guest Not tainted 3.16.7-ckt4+ #1
> Apr 14 19:01:22.471529 [ 1229.471181] task: d80e0d80 ti: db730000 task.ti: db730000
> Apr 14 19:01:22.477016 [ 1229.471219] PC is at gnttab_batch_copy+0xd4/0xe0
> Apr 14 19:01:22.481638 [ 1229.471257] LR is at gnttab_batch_copy+0x1c/0xe0
> Apr 14 19:01:22.486422 [ 1229.471285] pc : [<c04ab434>]    lr : [<c04ab37c>]    psr: a0000013
> Apr 14 19:01:22.492642 [ 1229.471285] sp : db731eb0  ip : deadbeef  fp : db731f3c
> Apr 14 19:01:22.498021 [ 1229.471329] r10: 00000001  r9 : 00000000  r8 : 00000002
> Apr 14 19:01:22.503293 [ 1229.471352] r7 : 00000001  r6 : 00000001  r5 : 00000000  r4 : e2003d30
> Apr 14 19:01:22.509907 [ 1229.471380] r3 : 00000001  r2 : deadbeef  r1 : deadbeef  r0 : fffffff2
> Apr 14 19:01:22.516431 [ 1229.471409] Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
> Apr 14 19:01:22.523802 [ 1229.471440] Control: 10c5387d  Table: 7987806a  DAC: 00000015
> Apr 14 19:01:22.529651 [ 1229.471469] Process vif9.0-q0-guest (pid: 18258, stack limit = 0xdb730248)
> Apr 14 19:01:22.536553 [ 1229.471515] Stack: (0xdb731eb0 to 0xdb732000)
> Apr 14 19:01:22.541024 [ 1229.471543] 1ea0:                                     00000001 00000000 00000000 e1ffb000
> Apr 14 19:01:22.549146 [ 1229.471581] 1ec0: 00000001 c05d6acc 0000004e 00000a02 db731f3c 00000000 00000000 00000001
> Apr 14 19:01:22.557387 [ 1229.471626] 1ee0: dbbbfcc0 00000000 00000000 00000002 00000000 db731f20 e2003cfc e2003d30
> Apr 14 19:01:22.565641 [ 1229.471663] 1f00: 00000001 00000000 00000001 00000000 e2003d30 e202e530 0000004e 00000202
> Apr 14 19:01:22.573891 [ 1229.471699] 1f20: d290ee40 d290ee40 00000001 00000000 db731f2c db731f34 db731f34 00000000
> Apr 14 19:01:22.582139 [ 1229.471736] 1f40: 00000000 db56d240 00000000 e1ffb000 c05d65f4 00000000 00000000 00000000
> Apr 14 19:01:22.590388 [ 1229.471772] 1f60: 00000000 c0264048 00000000 00000000 00000000 e1ffb000 00000000 00000000
> Apr 14 19:01:22.598639 [ 1229.471808] 1f80: db731f80 db731f80 00000000 00000000 db731f90 db731f90 db731fac db56d240
> Apr 14 19:01:22.606888 [ 1229.471843] 1fa0: c0263f7c 00000000 00000000 c020f038 00000000 00000000 00000000 00000000
> Apr 14 19:01:22.615016 [ 1229.471879] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> Apr 14 19:01:22.623268 [ 1229.471914] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
> Apr 14 19:01:22.631514 [ 1229.471978] [<c04ab434>] (gnttab_batch_copy) from [<c05d6acc>] (xenvif_kthread_guest_rx+0x4d8/0xbc0)
> Apr 14 19:01:22.640766 [ 1229.472045] [<c05d6acc>] (xenvif_kthread_guest_rx) from [<c0264048>] (kthread+0xcc/0xe8)
> Apr 14 19:01:22.648924 [ 1229.472093] [<c0264048>] (kthread) from [<c020f038>] (ret_from_fork+0x14/0x3c)
> Apr 14 19:01:22.656138 [ 1229.472132] Code: 0affffe5 eaffffed e8bd80f8 e7f001f2 (e7f001f2) 
> Apr 14 19:01:22.662285 [ 1229.472180] ---[ end trace 47a1647ddcea66dd ]---

Re: kernel BUG at drivers/xen/grant-table.c:923!

[David Vrabel]

On 17/04/15 11:28, Ian Campbell wrote:
> (Was Re: [osstest test] 50423: regressions - FAIL)
> 
> This cropped up in an osstest flight (the results only go to Ian and I).
> 
> On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
>> On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
>>> flight 50423 osstest real [real]
>>> http://logs.test-lab.xenproject.org/osstest/logs/50423/
>>>
>>> Regressions :-(
>>>
>>> Tests which did not succeed and are blocking,
>>> including tests which could not be run:
>>>  test-armhf-armhf-xl          15 guest-start/debian.repeat fail REGR. vs. 50331
>>
>>
>> Looks to have been a real issue:
>>
>> http://logs.test-lab.xenproject.org/osstest/logs/50423/test-armhf-armhf-xl/serial-cubietruck-gleizes.log
>> Apr 14 19:01:21.834851 [ 1229.470934] ------------[ cut here ]------------
>> Apr 14 19:01:22.445308 [ 1229.471001] kernel BUG at drivers/xen/grant-table.c:923!
> 
> This seems familiar, anyone remember it? (CCing ARM, netback and generic
> Linux maintainers).

This doesn't look familiar to me.  What BUG_ON() is this?

David

Re: kernel BUG at drivers/xen/grant-table.c:923!

[Ian Campbell]

On Fri, 2015-04-17 at 11:31 +0100, David Vrabel wrote:
> On 17/04/15 11:28, Ian Campbell wrote:
> > (Was Re: [osstest test] 50423: regressions - FAIL)
> > 
> > This cropped up in an osstest flight (the results only go to Ian and I).
> > 
> > On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
> >> On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
> >>> flight 50423 osstest real [real]
> >>> http://logs.test-lab.xenproject.org/osstest/logs/50423/
> >>>
> >>> Regressions :-(
> >>>
> >>> Tests which did not succeed and are blocking,
> >>> including tests which could not be run:
> >>>  test-armhf-armhf-xl          15 guest-start/debian.repeat fail REGR. vs. 50331
> >>
> >>
> >> Looks to have been a real issue:
> >>
> >> http://logs.test-lab.xenproject.org/osstest/logs/50423/test-armhf-armhf-xl/serial-cubietruck-gleizes.log
> >> Apr 14 19:01:21.834851 [ 1229.470934] ------------[ cut here ]------------
> >> Apr 14 19:01:22.445308 [ 1229.471001] kernel BUG at drivers/xen/grant-table.c:923!
> > 
> > This seems familiar, anyone remember it? (CCing ARM, netback and generic
> > Linux maintainers).
> 
> This doesn't look familiar to me.  What BUG_ON() is this?

The one in gnttab_batch_copy:

        void gnttab_batch_copy(struct gnttab_copy *batch, unsigned count)
        {
                struct gnttab_copy *op;
        
                if (HYPERVISOR_grant_table_op(GNTTABOP_copy, batch, count))
                        BUG();
                for (op = batch; op < batch + count; op++)
                        if (op->status == GNTST_eagain)
                                gnttab_retry_eagain_gop(GNTTABOP_copy, op,
                                                        &op->status, __func__);
        }
        EXPORT_SYMBOL_GPL(gnttab_batch_copy);
        
The actual hypercall has failed, which is a pretty unusual failure case.
r0 == fffffff2 is likely the return code, which is -14 == EFAULT.

So I suppose something is up with the pointer at batch.

Ian.

Re: kernel BUG at drivers/xen/grant-table.c:923!

[Wei Liu]

On Fri, Apr 17, 2015 at 11:28:39AM +0100, Ian Campbell wrote:
> (Was Re: [osstest test] 50423: regressions - FAIL)
> 
> This cropped up in an osstest flight (the results only go to Ian and I).
> 
> On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
> > On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
> > > flight 50423 osstest real [real]
> > > http://logs.test-lab.xenproject.org/osstest/logs/50423/
> > > 
> > > Regressions :-(
> > > 
> > > Tests which did not succeed and are blocking,
> > > including tests which could not be run:
> > >  test-armhf-armhf-xl          15 guest-start/debian.repeat fail REGR. vs. 50331
> > 
> > 
> > Looks to have been a real issue:
> > 
> > http://logs.test-lab.xenproject.org/osstest/logs/50423/test-armhf-armhf-xl/serial-cubietruck-gleizes.log
> > Apr 14 19:01:21.834851 [ 1229.470934] ------------[ cut here ]------------
> > Apr 14 19:01:22.445308 [ 1229.471001] kernel BUG at drivers/xen/grant-table.c:923!
> 
> This seems familiar, anyone remember it? (CCing ARM, netback and generic
> Linux maintainers).
> 
> I had a look over
> 
> $ git log v3.16..origin/master -- drivers/net/xen-netback/ drivers/xen/ arch/*/xen
> 
> and nothing jumped out at me.
> 
> The new tests under flight include running tcpdump for the duration of
> the migration. I wonder if that might have exposed the problem?
> 
> This is ARM for which osstest uses a 3.16 based kernel compared with x86
> which is still on 3.14. That might explain why this was only seen on arm
> (if tcpdump triggered it) or it might just be a very rare occurrence.
> 

I've never seen this before. If I'm not mistaken this is referring to 

 918 void gnttab_batch_copy(struct gnttab_copy *batch, unsigned count)
 919 {
 920         struct gnttab_copy *op;
 921
 922         if (HYPERVISOR_grant_table_op(GNTTABOP_copy, batch, count))
 923                 BUG();
 924         for (op = batch; op < batch + count; op++)
 925                 if (op->status == GNTST_eagain)
 926                         gnttab_retry_eagain_gop(GNTTABOP_copy, op,
 927                                                 &op->status, __func__);
 928 }

Grant table op hypercall returns an error.

Would be useful to know what the actually error is.

Wei.

> > Apr 14 19:01:22.450646 [ 1229.471026] Internal error: Oops - BUG: 0 [#1] SMP ARM
> > Apr 14 19:01:22.455886 [ 1229.471052] Modules linked in: xen_gntalloc bridge stp ipv6 llc brcmfmac brcmutil cfg80211
> > Apr 14 19:01:22.464140 [ 1229.471145] CPU: 0 PID: 18258 Comm: vif9.0-q0-guest Not tainted 3.16.7-ckt4+ #1
> > Apr 14 19:01:22.471529 [ 1229.471181] task: d80e0d80 ti: db730000 task.ti: db730000
> > Apr 14 19:01:22.477016 [ 1229.471219] PC is at gnttab_batch_copy+0xd4/0xe0
> > Apr 14 19:01:22.481638 [ 1229.471257] LR is at gnttab_batch_copy+0x1c/0xe0
> > Apr 14 19:01:22.486422 [ 1229.471285] pc : [<c04ab434>]    lr : [<c04ab37c>]    psr: a0000013
> > Apr 14 19:01:22.492642 [ 1229.471285] sp : db731eb0  ip : deadbeef  fp : db731f3c
> > Apr 14 19:01:22.498021 [ 1229.471329] r10: 00000001  r9 : 00000000  r8 : 00000002
> > Apr 14 19:01:22.503293 [ 1229.471352] r7 : 00000001  r6 : 00000001  r5 : 00000000  r4 : e2003d30
> > Apr 14 19:01:22.509907 [ 1229.471380] r3 : 00000001  r2 : deadbeef  r1 : deadbeef  r0 : fffffff2
> > Apr 14 19:01:22.516431 [ 1229.471409] Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
> > Apr 14 19:01:22.523802 [ 1229.471440] Control: 10c5387d  Table: 7987806a  DAC: 00000015
> > Apr 14 19:01:22.529651 [ 1229.471469] Process vif9.0-q0-guest (pid: 18258, stack limit = 0xdb730248)
> > Apr 14 19:01:22.536553 [ 1229.471515] Stack: (0xdb731eb0 to 0xdb732000)
> > Apr 14 19:01:22.541024 [ 1229.471543] 1ea0:                                     00000001 00000000 00000000 e1ffb000
> > Apr 14 19:01:22.549146 [ 1229.471581] 1ec0: 00000001 c05d6acc 0000004e 00000a02 db731f3c 00000000 00000000 00000001
> > Apr 14 19:01:22.557387 [ 1229.471626] 1ee0: dbbbfcc0 00000000 00000000 00000002 00000000 db731f20 e2003cfc e2003d30
> > Apr 14 19:01:22.565641 [ 1229.471663] 1f00: 00000001 00000000 00000001 00000000 e2003d30 e202e530 0000004e 00000202
> > Apr 14 19:01:22.573891 [ 1229.471699] 1f20: d290ee40 d290ee40 00000001 00000000 db731f2c db731f34 db731f34 00000000
> > Apr 14 19:01:22.582139 [ 1229.471736] 1f40: 00000000 db56d240 00000000 e1ffb000 c05d65f4 00000000 00000000 00000000
> > Apr 14 19:01:22.590388 [ 1229.471772] 1f60: 00000000 c0264048 00000000 00000000 00000000 e1ffb000 00000000 00000000
> > Apr 14 19:01:22.598639 [ 1229.471808] 1f80: db731f80 db731f80 00000000 00000000 db731f90 db731f90 db731fac db56d240
> > Apr 14 19:01:22.606888 [ 1229.471843] 1fa0: c0263f7c 00000000 00000000 c020f038 00000000 00000000 00000000 00000000
> > Apr 14 19:01:22.615016 [ 1229.471879] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> > Apr 14 19:01:22.623268 [ 1229.471914] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
> > Apr 14 19:01:22.631514 [ 1229.471978] [<c04ab434>] (gnttab_batch_copy) from [<c05d6acc>] (xenvif_kthread_guest_rx+0x4d8/0xbc0)
> > Apr 14 19:01:22.640766 [ 1229.472045] [<c05d6acc>] (xenvif_kthread_guest_rx) from [<c0264048>] (kthread+0xcc/0xe8)
> > Apr 14 19:01:22.648924 [ 1229.472093] [<c0264048>] (kthread) from [<c020f038>] (ret_from_fork+0x14/0x3c)
> > Apr 14 19:01:22.656138 [ 1229.472132] Code: 0affffe5 eaffffed e8bd80f8 e7f001f2 (e7f001f2) 
> > Apr 14 19:01:22.662285 [ 1229.472180] ---[ end trace 47a1647ddcea66dd ]---
> 

Re: kernel BUG at drivers/xen/grant-table.c:923!

[Ian Campbell]

On Fri, 2015-04-17 at 11:45 +0100, Wei Liu wrote:
> On Fri, Apr 17, 2015 at 11:28:39AM +0100, Ian Campbell wrote:
> > (Was Re: [osstest test] 50423: regressions - FAIL)
> > 
> > This cropped up in an osstest flight (the results only go to Ian and I).
> > 
> > On Fri, 2015-04-17 at 11:10 +0100, Ian Campbell wrote:
> > > On Thu, 2015-04-16 at 21:36 +0000, osstest service user wrote:
> > > > flight 50423 osstest real [real]
> > > > http://logs.test-lab.xenproject.org/osstest/logs/50423/
> > > > 
> > > > Regressions :-(
> > > > 
> > > > Tests which did not succeed and are blocking,
> > > > including tests which could not be run:
> > > >  test-armhf-armhf-xl          15 guest-start/debian.repeat fail REGR. vs. 50331
> > > 
> > > 
> > > Looks to have been a real issue:
> > > 
> > > http://logs.test-lab.xenproject.org/osstest/logs/50423/test-armhf-armhf-xl/serial-cubietruck-gleizes.log
> > > Apr 14 19:01:21.834851 [ 1229.470934] ------------[ cut here ]------------
> > > Apr 14 19:01:22.445308 [ 1229.471001] kernel BUG at drivers/xen/grant-table.c:923!
> > 
> > This seems familiar, anyone remember it? (CCing ARM, netback and generic
> > Linux maintainers).
> > 
> > I had a look over
> > 
> > $ git log v3.16..origin/master -- drivers/net/xen-netback/ drivers/xen/ arch/*/xen
> > 
> > and nothing jumped out at me.
> > 
> > The new tests under flight include running tcpdump for the duration of
> > the migration. I wonder if that might have exposed the problem?
> > 
> > This is ARM for which osstest uses a 3.16 based kernel compared with x86
> > which is still on 3.14. That might explain why this was only seen on arm
> > (if tcpdump triggered it) or it might just be a very rare occurrence.
> > 
> 
> I've never seen this before. If I'm not mistaken this is referring to 
> 
>  918 void gnttab_batch_copy(struct gnttab_copy *batch, unsigned count)
>  919 {
>  920         struct gnttab_copy *op;
>  921
>  922         if (HYPERVISOR_grant_table_op(GNTTABOP_copy, batch, count))
>  923                 BUG();
>  924         for (op = batch; op < batch + count; op++)
>  925                 if (op->status == GNTST_eagain)
>  926                         gnttab_retry_eagain_gop(GNTTABOP_copy, op,
>  927                                                 &op->status, __func__);
>  928 }
> 
> Grant table op hypercall returns an error.
> 
> Would be useful to know what the actually error is.

Based on r0 I think -EFAULT.

Ian.