Re: [Xen-devel] OSSTEST: Re-blessing cubietruck-{picasso, gleizes, metzinger} for production use

[Ian Campbell <ian.campbell@xxxxxxxxxx>]

On Wed, 2016-01-20 at 11:58 +0000, Ian Campbell wrote:
> > > With the recent timeout fixes they are working as well as the
> > > production
> > > cubietruck-braque.
> > > 
> > > There are two flakey testsÂtest-armhf-armhf-xl-rtds and test-armhf-
> > > armhf-
> > > libvirt-raw, but those appear to be much better than before the timeout
> > > changes and not specific to these three boards since the fourth one
> > > looks
> > > to behave much the same.
> > > 
> > > At first glance it looks like some later test steps might just need a
> > > bit
> > > more time on CT too.
> > 
> > Maybe we should have target_adjust_timeout honour a host property to
> > multiply timeouts by some factor.
> 
> That's not a bad idea, assuming the remaining issues really are timeouts of
> this sort.

The test-armhf-armhf-xl-rtds case is successfully booting, but just a
little too slow to bring up networking, it's hitting.

    2016-01-18 19:40:10 Z executing ssh ...     root@xxxxxxxxxxxxx     xl listÂ
    2016-01-18 19:40:11 Z guest debian.guest.osstest state is rÂ
    2016-01-18 19:40:11 Z guest debian.guest.osstest 5a:36:0e:59:00:0b 22 
link/ip/tcp: waiting 40s...Â
    2016-01-18 19:40:11 Z guest debian.guest.osstest 5a:36:0e:59:00:0b 22 
link/ip/tcp: no active lease (waiting) ...Â
    ...
    2016-01-18 19:40:56 Z FAILURE: guest debian.guest.osstest 5a:36:0e:59:00:0b 
22 link/ip/tcp: wait timed out: no active lease.Â
    failure: guest debian.guest.osstest 5a:36:0e:59:00:0b 22 link/ip/tcp: wait 
timed out: no active lease.
    + rc=255

http://osstest.test-lab.xenproject.org/~osstest/pub/logs/78425/test-armhf-armhf-xl-rtds/11.ts-guest-start.log

78506 passed and has:

    2016-01-19 17:56:11 Z guest debian.guest.osstest state is rÂ
    2016-01-19 17:56:11 Z guest debian.guest.osstest 5a:36:0e:aa:00:0b 22 
link/ip/tcp: waiting 40s...Â
    2016-01-19 17:56:11 Z guest debian.guest.osstest 5a:36:0e:aa:00:0b 22 
link/ip/tcp: no active lease (waiting) ...Â
    2016-01-19 17:56:32 Z guest debian.guest.osstest 5a:36:0e:aa:00:0b 22 
link/ip/tcp: nc: 256 (UNKNOWN) [172.16.145.103] 22 (ssh) : Connection refused |Â
Â(waiting) ...Â
    2016-01-19 17:56:45 Z guest debian.guest.osstest 5a:36:0e:aa:00:0b 22 
link/ip/tcp: ok. (34s)Â

http://osstest.test-lab.xenproject.org/~osstest/pub/logs/78506/test-armhf-armhf-xl-rtds/11.ts-guest-start.log

i.e. it took 34/40s, so a bit border line.

In the production env
http://logs.test-lab.xenproject.org/osstest/logs/78525/test-armhf-armhf-xl-rtds/11.ts-guest-start.log
has it taking 27s, in 78443 it was 41s (flying close to the edge there!),
78395 has 45s (flipping the edge the bird as it disappears into the
distance ;-) )

The guest console log shows:

    A start job is running for LSB: Raise network interf...34s / no limit)

http://osstest.test-lab.xenproject.org/~osstest/pub/logs/78425/test-armhf-armhf-xl-rtds/cubietruck-picasso---var-log-xen-console-guest-debian.guest.osstest.log

(it's messy in there, I thought I'd arranged for sane logging in guest,via
sysvinit and FANCYTTY=0, clearly not quite).

So bringing up the network does appear to be rather slow.

The host console has:

Jan 18 19:39:57.747858 [ 2354.661150] device vif1.0 entered promiscuous mode
Jan 18 19:40:10.795484 [ 2354.670132] IPv6: ADDRCONF(NETDEV_UP): vif1.0: link 
is not ready
Jan 18 19:40:10.805719 [ 2358.350734] xen-blkback:ring-ref 8, event-channel 3, 
protocol 1 (arm-abi) persistent grants
Jan 18 19:40:14.488585 [ 2358.522313] xen-blkback:ring-ref 9, event-channel 4, 
protocol 1 (arm-abi) persistent grants
Jan 18 19:40:14.660189 [ 2358.763589] IPv6: ADDRCONF(NETDEV_CHANGE): vif1.0: 
link becomes ready
Jan 18 19:40:14.899590 [ 2358.763859] xenbr0: port 2(vif1.0) entered forwarding 
state
Jan 18 19:40:14.905182 [ 2358.763933] xenbr0: port 2(vif1.0) entered forwarding 
state
Jan 18 19:40:14.910801 (XEN) mm.c:1259:d0v1 gnttab_mark_dirty not implemented 
yet

http://osstest.test-lab.xenproject.org/~osstest/pub/logs/78425/test-armhf-armhf-xl-rtds/serial-cubietruck-picasso.log

So it does appear to be taking nearly 20 to become forwarding.

In some other host logs I saw things like: 

Jan 18 11:07:43.692168 [ 2352.190458] device vif1.0 entered promiscuous mode
Jan 18 11:08:00.541965 [ 2352.200226] IPv6: ADDRCONF(NETDEV_UP): vif1.0: link 
is not ready
Jan 18 11:08:00.552908 [ 2355.872175] xen-blkback:ring-ref 8, event-channel 3, 
protocol 1 (arm-abi) persistent grants
Jan 18 11:08:04.227269 [ 2355.990407] xen-blkback:ring-ref 9, event-channel 4, 
protocol 1 (arm-abi) persistent grants
Jan 18 11:08:04.345476 [ 2356.173545] IPv6: ADDRCONF(NETDEV_CHANGE): vif1.0: 
link becomes ready
Jan 18 11:08:04.526627 [ 2356.173844] xenbr0: port 2(vif1.0) entered forwarding 
state
Jan 18 11:08:04.532224 [ 2356.173903] xenbr0: port 2(vif1.0) entered forwarding 
state
Jan 18 11:08:04.537973 (XEN) mm.c:1259:d0v0 gnttab_mark_dirty not implemented 
yet
Jan 18 11:08:04.548507 [ 2387.787532] vif vif-1-0 vif1.0: draining TX queue

http://logs.test-lab.xenproject.org/osstest/logs/78395/test-armhf-armhf-xl-rtds/serial-cubietruck-braque.log

Which was a similar delay, but with the extra "vif vif-1-0 vif1.0: draining
TX queue". I'm not sure but I think that might indicate a delay or a
recoverable issue passing traffic, which might be explainable by
"cubietruck's appear to be really slow in real life" or might equally well
be a real issue.

I'll add this to my list to investigate further, but I don't think we want
to tweak the t/o just yet.

Ian.

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