Hi Akihiro,
On Mon, Dec 19, 2016 at 7:17 AM, Akihiro Suda <suda.ky...@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 <lpro...@redhat.com>:
>>
>> Hi Akihiro,
>>
>> On Wed, Dec 14, 2016 at 8:51 AM, Akihiro Suda <suda.ky...@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/26050fd4c87c50503d5bd573b2ec91703676e211:/src/drivers/bus/virtio-pci.c#l43
>> >
>> > https://git.ipxe.org/ipxe.git/blob/26050fd4c87c50503d5bd573b2ec91703676e211:/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 <nik...@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.ky...@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/26050fd4c87c50503d5bd573b2ec91703676e211:/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@lists.ipxe.org
>> >> > https://lists.ipxe.org/mailman/listinfo.cgi/ipxe-devel
>> >> >
>> >
>> >
>> >
>> > _______________________________________________
>> > ipxe-devel mailing list
>> > ipxe-devel@lists.ipxe.org
>> > https://lists.ipxe.org/mailman/listinfo.cgi/ipxe-devel
>> >
>
>
_______________________________________________
ipxe-devel mailing list
ipxe-devel@lists.ipxe.org
https://lists.ipxe.org/mailman/listinfo.cgi/ipxe-devel
