[ipxe-devel] virtnet_open_legacy() fails to find virtqueues on Google Compute Engine
Akihiro Suda
suda.kyoto at gmail.com
Mon Dec 19 09:40:20 UTC 2016
Hello, Ladi,
Thank you a lot for providing the patch.
However, unfortunately, it does not seem to have any effect.
BTW, when I was tackling with the issue without your patch, I found some
interesting behavior:
- Pinging from another instance (Linux) to an iPXE instance seems always
working as expected. (i.e. iPXE can successfully "pong" by transmitting
Ethernet packets)
- When an iPXE instance is being pinged, it can successfully send
non-"pong" packets as well. So `dhcp` and `imgfetch
http://10.146.0.2/a.ipxe` work!
So, I guess the issue is somehow related to interruption.
When iPXE is frequently interrupted due to RX, the interruptions seems
triggering TX as well.
However, TX seems failing when it is not triggered by frequent RX
interruptions.
(Please correct me if my guess is wrong 😅)
2016-12-19 18:00 GMT+09:00 Ladi Prosek <lprosek at redhat.com>:
> Hi Akihiro,
>
> On Mon, Dec 19, 2016 at 7:17 AM, Akihiro Suda <suda.kyoto at gmail.com>
> wrote:
> > Hello Ladi,
> >
> > Thank you a lot for looking into this issue and writing patches about the
> > queue size. The patch set looks good to me.
> >
> >>> I haven't captured DHCP packets (because I'm unsure how to do so in
> GCE's
> >>> fully managed DHCP server), but I guess DHCPACK is actually sent from
> the
> >>> DHCP server but somehow iPXE missed it.
> >>
> >> Do you see any interesting log output with DEBUG=virtio-net,virtio-pci ?
> >
> > Did not see any interesting log. No error about TX is printed, and it
> just
> > fails to receive DHCPACK.
> >
> > So, for ease of debugging with capturing packets, I tried to do `imgfetch
> > http://...` with a static IP address (`set net0/ip`) instead.
> >
> > The result implies that "iPXE believes it has sent the second Ethernet
> > packet without an error, but it is not sent actually".
> >
> > This assumption is consistent with my report about DHCP.
> > iPXE can successfully send the 1st packet (DHCPDISCOVER), but seems
> failing
> > to send the 2nd packet (DHCPREQUEST). It should be the reason why it
> cannot
> > receive DHCPACK.
> >
> >
> > Here is the log. In the client log, we can see "TX ... PSH ACK", but it
> is
> > not received on the server side.
> >
> > === iPXE Client 10.146.0.10 (DEBUG=virtio-net:7,virtio-
> pci:7,tcp:7,ipv4:7
> > CONFIG=cloud, 26050fd4 with Ladi's 4 great patches) ===
> >
> > iPXE> imgfetch http://10.146.0.2/a.ipxe
> > http://10.146.0.2/a.ipxe...TCP 0x12eda4 allocated
> > TCP 0x12eda4 transitioned from CLOSED to SYN_SENT
> > TCP 0x12eda4 bound to port 46673
> > TCP 0x12eda4 timer fired in SYN_SENT for 609cb55e..609cb55e 00000000
> > TCP 0x12eda4 TX 46673->80 609cb55e..609cb55f 00000000 0
> SYN
> > IPv4 TX 10.146.0.10->10.146.0.2 len 64 proto 6 id 0100 csum 6489
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ef90 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ef90
> > VIRTIO-NET 0xee704 rx complete iobuf 0x12f5f4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1335f4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x12eda4 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0
> SYN
> > ACK
> > TCP 0x12eda4 using timestamps, SACK, TX window x128, RX window x512
> > TCP 0x12eda4 transitioned from SYN_SENT to ESTABLISHED
> > TCP 0x12eda4 TX 46673->80 609cb55f..609cb5c1 5ae4dacc 98
> PSH
> > ACK
> > IPv4 TX 10.146.0.10->10.146.0.2 len 150 proto 6 id 0201 csum 6332
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ec94 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ec94
> > VIRTIO-NET 0xee704 rx complete iobuf 0x12fdf4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12f5f4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x12eda4 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0
> SYN
> > ACK
> > TCP 0x12eda4 timer fired in ESTABLISHED for 609cb55f..609cb5c1
> 5ae4dacc
> > TCP 0x12eda4 TX 46673->80 609cb55f..609cb5c1 5ae4dacc 98
> PSH
> > ACK
> > IPv4 TX 10.146.0.10->10.146.0.2 len 150 proto 6 id 0302 csum 6231
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ec94 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ec94
> > .TCP 0x12eda4 timer fired in ESTABLISHED for 609cb55f..609cb5c1
> 5ae4dacc
> > TCP 0x12eda4 TX 46673->80 609cb55f..609cb5c1 5ae4dacc 98
> PSH
> > ACK
> > IPv4 TX 10.146.0.10->10.146.0.2 len 150 proto 6 id 0402 csum 6131
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ec94 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ec94
> > VIRTIO-NET 0xee704 rx complete iobuf 0x1305f4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12fdf4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x12eda4 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0
> SYN
> > ACK
> > ..TCP 0x12eda4 timer fired in ESTABLISHED for 609cb55f..609cb5c1
> > 5ae4dacc
> > TCP 0x12eda4 TX 46673->80 609cb55f..609cb5c1 5ae4dacc 98
> PSH
> > ACK
> > IPv4 TX 10.146.0.10->10.146.0.2 len 150 proto 6 id 0503 csum 6030
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ec94 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ec94
> > ..VIRTIO-NET 0xee704 rx complete iobuf 0x130df4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1305f4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x12eda4 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0
> SYN
> > ACK
> > .TCP 0x12eda4 timer fired in ESTABLISHED for 609cb55f..609cb5c1
> 5ae4dacc
> > TCP 0x12eda4 TX 46673->80 609cb55f..609cb5c1 5ae4dacc 98
> PSH
> > ACK
> > IPv4 TX 10.146.0.10->10.146.0.2 len 150 proto 6 id 0604 csum 5f2f
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x12ec94 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x12ec94
> > ......TCP 0x12eda4 timer expired in ESTABLISHED for
> 609cb55f..609cb5c1
> > 5ae4dacc
> > TCP 0x12eda4 transitioned from ESTABLISHED to CLOSED
> > TCP 0x12eda4 connection deleted
> > Connection timed out (http://ipxe.org/4c0a6035)
> > iPXE> VIRTIO-NET 0xee704 rx complete iobuf 0x1315f4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x130df4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x0 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0 SYN
> ACK
> > IPv4 received packet rejected by stack: The socket is not connected
> > (http://ipxe.org/380a6001)
> >
> > iPXE> VIRTIO-NET 0xee704 rx complete iobuf 0x131df4 len 74
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1315f4 on vq 0
> > IPv4 RX 10.146.0.10<-10.146.0.2 len 60 proto 6 id 0000 csum 258d
> > TCP 0x0 RX 46673<-80 609cb55f 5ae4dacb..5ae4dacc 0 SYN
> ACK
> > IPv4 received packet rejected by stack: The socket is not connected
> > (http://ipxe.org/380a6001)
> > VIRTIO-NET 0xee704 rx complete iobuf 0x1325f4 len 42
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x131df4 on vq 0
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1325f4 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x1325f4
> > VIRTIO-NET 0xee704 rx complete iobuf 0x132df4 len 62
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1325f4 on vq 0
> > IPv4 RX 10.146.0.10<-221.204.224.56 len 48 proto 6 id 6aac csum 167b
> > TCP 0x0 RX 22<-2281 0a4bb0cf 3368312b..3368312c 0 SYN
> > IPv4 received packet rejected by stack: The socket is not connected
> > (http://ipxe.org/380a6001)
> > VIRTIO-NET 0xee704 rx complete iobuf 0x1335f4 len 42
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x132df4 on vq 0
> > VIRTIO-NET 0xee704 enqueuing iobuf 0x1335f4 on vq 1
> > VIRTIO-NET 0xee704 tx complete iobuf 0x1335f4
> >
> >
> >
> > === HTTP server 10.146.0.2 (ws01) ===
> >
> > $ sudo tcpdump host 10.146.0.10
> > tcpdump: verbose output suppressed, use -v or -vv for full protocol
> > decode
> > listening on ens4, link-type EN10MB (Ethernet), capture size 262144
> > bytes
> > 04:55:43.715483 IP ipxe01.c.suda-main.internal.46673 >
> > ws01.c.suda-main.internal.http: Flags [S], seq 1620882782, win 65532,
> > options [nop,nop,TS val 323011 ecr 0,nop,nop,sackOK,nop,wscale 9,mss
> 1460],
> > length 0
> > 04:55:43.715549 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77061640 ecr
> > 323011,nop,wscale 7], length 0
> > 04:55:44.712811 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77061890 ecr
> > 323011,nop,wscale 7], length 0
> > 04:55:46.712829 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77062390 ecr
> > 323011,nop,wscale 7], length 0
> > 04:55:50.712864 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77063390 ecr
> > 323011,nop,wscale 7], length 0
> > 04:55:58.712842 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77065390 ecr
> > 323011,nop,wscale 7], length 0
> > 04:56:14.712836 IP ws01.c.suda-main.internal.http >
> > ipxe01.c.suda-main.internal.46673: Flags [S.], seq 1524947659, ack
> > 1620882783, win 28160, options [mss 1420,sackOK,TS val 77069390 ecr
> > 323011,nop,wscale 7], length 0
>
> Thanks for the logs. Can you please try the following patch? It's a
> crazy workaround to reinitialize the driver on each transmitted
> packet. If it works, we'll go from there and try something more
> sophisticated. Thanks!
>
>
> --- a/src/drivers/net/virtio-net.c
> +++ b/src/drivers/net/virtio-net.c
> @@ -345,6 +345,8 @@ static void virtnet_close ( struct net_device *netdev
> ) {
> */
> static int virtnet_transmit ( struct net_device *netdev,
> struct io_buffer *iobuf ) {
> + virtnet_close ( netdev );
> + virtnet_open ( netdev );
> virtnet_enqueue_iob ( netdev, TX_INDEX, iobuf );
> return 0;
> }
>
>
> > 2016-12-14 18:17 GMT+09:00 Ladi Prosek <lprosek at redhat.com>:
> >>
> >> Hi Akihiro,
> >>
> >> On Wed, Dec 14, 2016 at 8:51 AM, Akihiro Suda <suda.kyoto at gmail.com>
> >> wrote:
> >> > Hi Christian,
> >> >
> >> > Thank you for the suggestion, I'll try to report this to google.
> >> >
> >> > I found that the cause of this issue is because GCE's
> >> > VIRTIO_PCI_QUEUE_NUM
> >> > is 4096, which is larger than iPXE's MAX_QUEUE_NUM (256).
> >> >
> >> >
> >> > https://git.ipxe.org/ipxe.git/blob/26050fd4c87c50503d5bd573b2ec91
> 703676e211:/src/drivers/bus/virtio-pci.c#l43
> >> >
> >> > https://git.ipxe.org/ipxe.git/blob/26050fd4c87c50503d5bd573b2ec91
> 703676e211:/src/include/ipxe/virtio-ring.h#l24
> >> >
> >> >
> >> > IIUC this issue will be resolved if GCE supports virtio 1.0, which
> would
> >> > allow iPXE to use custom queue num smaller than the virtio device's
> max
> >> > value.
> >>
> >> iPXE virtio 1.0 code does not cap the queue size to MAX_QUEUE_NUM. In
> >> fact, it does not check it against any maximum and still uses
> >> fixed-sized virtqueue data structures, just like legacy. This is a
> >> bug.
> >>
> >> > However, it would be great if iPXE can support setting MAX_QUEUE_NUM
> to
> >> > 4096
> >> > (via `config/general.h`, probably).
> >>
> >> Even better, iPXE should try to use the host provided size in legacy
> >> mode, i.e. no MAX_QUEUE_NUM needed. The few extra dynamic allocations
> >> shouldn't hurt anything.
> >>
> >> > Actually I tried to set MAX_QUEUE_NUM to 4096 and got
> >> > virtnet_open_legacy()
> >> > succeeded, but it still doesn't work:
> >> >
> >> > iPXE> dhcp
> >> > DHCP 0x120e44 entering discovery state
> >> > Configuring (net0 42:01:0a:92:00:0a)...DHCP 0x120e44 DHCPDISCOVER
> >> > DHCP 0x120e44 DHCPOFFER from 169.254.169.254:67 for 10.146.0.10
> >> > .DHCP 0x120e44 DHCPDISCOVER
> >> > ..DHCP 0x120e44 entering request state
> >> > DHCP 0x120e44 DHCPREQUEST to 169.254.169.254:67 for 10.146.0.10
> >> > DHCP 0x120e44 DHCPREQUEST to 169.254.169.254:67 for 10.146.0.10
> >> > .DHCP 0x120e44 DHCPREQUEST to 169.254.169.254:67 for 10.146.0.10
> >> > .DHCP 0x120e44 DHCPREQUEST to 169.254.169.254:67 for 10.146.0.10
> >> > ...DHCP 0x120e44 DHCPREQUEST to 169.254.169.254:67 for
> 10.146.0.10
> >> > ....... No configuration methods succeeded
> >> > (http://ipxe.org/040ee119)
> >> > iPXE>
> >> >
> >> > I haven't captured DHCP packets (because I'm unsure how to do so in
> >> > GCE's
> >> > fully managed DHCP server), but I guess DHCPACK is actually sent from
> >> > the
> >> > DHCP server but somehow iPXE missed it.
> >>
> >> Do you see any interesting log output with DEBUG=virtio-net,virtio-pci ?
> >>
> >> > I'd appreciate if anyone can support me to set MAX_QUEUE_NUM to 4096.
> >>
> >> I'll look into it. My proposal is to keep using 128 as the cap in
> >> virtio 1.0 and support any queue size in legacy, only subject to
> >> available memory.
> >>
> >> > 2016-12-14 16:19 GMT+09:00 Christian Nilsson <nikize at gmail.com>:
> >> >>
> >> >> You might want to report this to google as well if you haven't
> already.
> >> >>
> >> >> On Wed, Dec 14, 2016 at 7:16 AM, Akihiro Suda <suda.kyoto at gmail.com>
> >> >> wrote:
> >> >> > Hello,
> >> >> >
> >> >> > I tried to boot iPXE on a Google Compute Engine instance, but the
> >> >> > virtio
> >> >> > driver doesn't work because virtnet_open_legacy() fails to find
> >> >> > virtqueues.
> >> >> >
> >> >> > Please let me know what I can do for providing further information
> to
> >> >> > debug
> >> >> > the issue.
> >> >> >
> >> >> > The serial console output with "DEBUG=virtio-net" is as follows:
> >> >> >
> >> >> > iPXE initialising devices...Common virtio capability not found!
> >> >> > VIRTIO-NET 0xdf584 busaddr=0000:00:04.0 ioaddr=0xc040 irq=11
> >> >> > VIRTIO-NET 0xdf584 mac=42:01:0a:92:00:0a
> >> >> > ok
> >> >> >
> >> >> > iPXE 1.0.0+ (26050) -- Open Source Network Boot Firmware --
> >> >> > http://ipxe.org
> >> >> > Features: DNS HTTP iSCSI TFTP SRP AoE ELF MBOOT PXE bzImage
> Menu
> >> >> > PXEXT
> >> >> > iPXE> ifstat
> >> >> > net0: 42:01:0a:92:00:0a using virtio-net on 0000:00:04.0
> (closed)
> >> >> > [Link:up, TX:0 TXE:0 RX:0 RXE:0]
> >> >> > iPXE> dhcp
> >> >> > VIRTIO-NET 0xdf584 cannot register queue 0
> >> >> > Could not open net0: No such file or directory
> >> >> > (http://ipxe.org/2d5c403b)
> >> >> > iPXE>
> >> >> >
> >> >> >
> >> >> > This ENOENT is raised from virtnet_open_legacy():
> >> >> >
> >> >> >
> >> >> > https://git.ipxe.org/ipxe.git/blob/26050fd4c87c50503d5bd573b2ec91
> 703676e211:/src/drivers/net/virtio-net.c#l205
> >> >> >
> >> >> >
> >> >> > I also tested some previous commits, but all of them failed, so the
> >> >> > issue is
> >> >> > not a regression in some recent commit:
> >> >> >
> >> >> > * 26050fd (Dec 8, 2016): the last commit when I tested
> >> >> > * 7b499f8 (Apr 11, 2016): the last commit without support for
> virtio
> >> >> > 1.0
> >> >> > * e4419ff (Jul 2, 2010): the first commit with the "native iPXE
> >> >> > driver"
> >> >> > (The commit date is older than 232c208, but actually newer than
> >> >> > 232c208)
> >> >> > * 232c208 (Jul 11, 2010): the last commit without the "native iPXE
> >> >> > driver".
> >> >> > The error message is "ERROR: queue size 4096 > 512", "Cannot
> register
> >> >> > queue
> >> >> > #0"
> >> >> >
> >> >> >
> >> >> > Regards,
> >> >> >
> >> >> > Akihiro Suda
> >> >> >
> >> >> >
> >> >> > _______________________________________________
> >> >> > ipxe-devel mailing list
> >> >> > ipxe-devel at lists.ipxe.org
> >> >> > https://lists.ipxe.org/mailman/listinfo.cgi/ipxe-devel
> >> >> >
> >> >
> >> >
> >> >
> >> > _______________________________________________
> >> > ipxe-devel mailing list
> >> > ipxe-devel at lists.ipxe.org
> >> > https://lists.ipxe.org/mailman/listinfo.cgi/ipxe-devel
> >> >
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ipxe.org/pipermail/ipxe-devel/attachments/20161219/4b539c7d/attachment.htm>
More information about the ipxe-devel
mailing list