KVM guest sees lots of TCP Retransmissions for SSL traffic

[hverbeek]

I'm not sure if this issue is related to Proxmox or KVM but I'm hoping for some advice anyway. Thx people!

I have a 2-node cluster with Proxmox 1.7 (2.6.32), running Debian Lenny5 amd64 as KVM guests (standard 2.6.26 kernel). Some of the guests are Apache 2.2 reverse-proxies, terminating the SSL session of the users. The webservice we are offering runs exclusively on HTTPS; HTTP traffic gets redirected to HTTPS.

Problem: A handful of our customer cannot successfully use the webservice - "the webpage loads extremely slowly". Analysing the customer's traffic on the KVM guests shows a very high number of TCP Retransmissions and Duplicate Acks (approx 20% of their traffic).

Most of our users are not complaining, and we do see bandwidth being used nicely. However, analysing everyone's traffic I see between 1-2.5% of frames being TCP Retransmissions, Fast Retransmissions, Dup Acks, etc.

Could this be related to KVM somehow?
Does anyone else see a similar situation?

Some more details:
- The network setup is Hetzner-specific, whereby the subnet for the guests is routed via the KVM host.

- KVM guests use e1000 NICs at the moment (for better latency, until qemu 0.14 is considered stable by the proxmox guys)

- IPtables packetfilter runs on the KVM hosts allowing
* inbound ICMP (destination-unreachable, time-exceeded, echo-reply, echo-request)
* forward ICMP (destination-unreachable, time-exceeded, echo-reply, echo-request)
* forward HTTP/HTTPS

- IPtables shows the 'destination-unreachable' forward-rule being hit quite a bit, so I gather Path MTU Discovery works - at least for some customers .

Thanks for any pointers!

 

[tom]

what kernel do you run on your lenny guests?
if you use virtio, 2.6.26 is not recommended, I remember some hints on the KVM lists.

maybe you should try a 2.6.32 kernel in your guest - maybe.

 

[hverbeek]

what kernel do you run on your lenny guests?

Standard kernel 2.6.26 so far, plus e1000. I'll update the orig post in a sec.

Do you think this could be related to KVM at all?

 

[tom]

Standard kernel 2.6.26 so far, plus e1000. I'll update the orig post in a sec.

Do you think this could be related to KVM at all?

not really, just a wild guess.

 

[dswartz]

Possibly dropped tcp segments and/or corrupted ones? What does 'netstat -s' on guest show?

 

[hverbeek]

# netstat -s
Ip:
    1834585113 total packets received
    16 with invalid addresses
    0 forwarded
    0 incoming packets discarded
    1834585097 incoming packets delivered
    734924782 requests sent out
    2 outgoing packets dropped
    72 dropped because of missing route
    2 fragments failed
Icmp:
    646869 ICMP messages received
    344 input ICMP message failed.
    ICMP input histogram:
        destination unreachable: 1488
        timeout in transit: 439203
        source quenches: 165
        echo requests: 159933
        echo replies: 46044
    681042 ICMP messages sent
    0 ICMP messages failed
    ICMP output histogram:
        destination unreachable: 617
        echo request: 8
        echo replies: 159932
IcmpMsg:
        InType0: 46044
        InType3: 1488
        InType4: 165
        InType8: 159933
        InType11: 439203
        OutType0: 159932
        OutType3: 617
        OutType8: 8
        OutType69: 520485
Tcp:
    408509 active connections openings
    937725 passive connection openings
    3602 failed connection attempts
    167348 connection resets received
    38 connections established
    1833520286 segments received
    726455060 segments send out
    6365556 segments retransmited
    27464 bad segments received.
    379826 resets sent
Udp:
    395115 packets received
    240 packets to unknown port received.
    0 packet receive errors
    1423139 packets sent
UdpLite:
TcpExt:
    2966 resets received for embryonic SYN_RECV sockets
    273168 packets pruned from receive queue because of socket buffer overrun
    137 ICMP packets dropped because they were out-of-window
    702266 TCP sockets finished time wait in fast timer
    2497 time wait sockets recycled by time stamp
    13546 packets rejects in established connections because of timestamp
    15538434 delayed acks sent
    17591 delayed acks further delayed because of locked socket
    Quick ack mode was activated 856706 times
    234156 packets directly queued to recvmsg prequeue.
    1860304 bytes directly in process context from backlog
    519738 bytes directly received in process context from prequeue
    1138536915 packet headers predicted
    1636 packets header predicted and directly queued to user
    289925513 acknowledgments not containing data payload received
    350760161 predicted acknowledgments
    11522 times recovered from packet loss due to fast retransmit
    1634693 times recovered from packet loss by selective acknowledgements
    11970 bad SACK blocks received
    Detected reordering 502 times using FACK
    Detected reordering 28016 times using SACK
    Detected reordering 1005 times using reno fast retransmit
    Detected reordering 718 times using time stamp
    654 congestion windows fully recovered without slow start
    7248 congestion windows partially recovered using Hoe heuristic
    2383 congestion windows recovered without slow start by DSACK
    4364 congestion windows recovered without slow start after partial ack
    3587748 TCP data loss events
    TCPLostRetransmit: 67595
    12283 timeouts after reno fast retransmit
    775637 timeouts after SACK recovery
    16716 timeouts in loss state
    3791990 fast retransmits
    96433 forward retransmits
    1444840 retransmits in slow start
    131579 other TCP timeouts
    603 classic Reno fast retransmits failed
    49237 SACK retransmits failed
    130295685 packets collapsed in receive queue due to low socket buffer
    632087 DSACKs sent for old packets
    10783 DSACKs sent for out of order packets
    309172 DSACKs received
    868 DSACKs for out of order packets received
    73122 connections reset due to unexpected data
    155611 connections reset due to early user close
    2077 connections aborted due to timeout
    TCPSACKDiscard: 317012
    TCPDSACKIgnoredOld: 51593
    TCPDSACKIgnoredNoUndo: 254165
    TCPSpuriousRTOs: 2489
IpExt:
    InBcastPkts: 22537

Does that help? What would I be looking for?

I have also just created an additional guest, upgraded its kernel to 2.6.32 and gave it virtio NICs. Gotta love Proxmox + puppet... I'll redirect some customers to there and see what happens with retransmissions.

 

[dswartz]

On the guest, looking for IP dropped packets (none visible here) and tcp dropped segments. I note a lot of bad segments received. Can you capture this output, run a test where you see slow transfer to the guest, capture again, and compare the count of "bad segments received"? Might want to do this on the non-guest too...

 

[hverbeek]

Thanks!

The new reverse proxy (KVM guest, debian lenny 5, kernel 2.6.32 from backports, virtio NICs) has been running for over 24 hours now, and the statistics look much better (however, I only switched a few customers across):

$ netstat -s
Ip:
    21875448 total packets received
    0 forwarded
    0 incoming packets discarded
    21875196 incoming packets delivered
    8926699 requests sent out
    48 dropped because of missing route
Icmp:
    10375 ICMP messages received
    15 input ICMP message failed.
    ICMP input histogram:
        destination unreachable: 35
        echo requests: 327
        echo replies: 10002
    10329 ICMP messages sent
    0 ICMP messages failed
    ICMP output histogram:
        echo request: 10002
        echo replies: 327
IcmpMsg:
        InType0: 10002
        InType3: 35
        InType8: 327
        OutType0: 327
        OutType8: 10002
Tcp:
    7156 active connections openings
    4280 passive connection openings
    54 failed connection attempts
    5321 connection resets received
    25 connections established
    21853762 segments received
    8768540 segments send out
    94954 segments retransmited
    1 bad segments received.
    6281 resets sent
Udp:
    11059 packets received
    0 packets to unknown port received.
    0 packet receive errors
    52876 packets sent
UdpLite:
TcpExt:
    47 resets received for embryonic SYN_RECV sockets
    6 packets pruned from receive queue because of socket buffer overrun
    3307 TCP sockets finished time wait in fast timer
    10 time wait sockets recycled by time stamp
    39 packets rejects in established connections because of timestamp
    286720 delayed acks sent
    121 delayed acks further delayed because of locked socket
    Quick ack mode was activated 10585 times
    862482 packets directly queued to recvmsg prequeue.
    25306896 bytes directly in process context from backlog
    1451229515 bytes directly received in process context from prequeue
    12518409 packet headers predicted
    1019617 packets header predicted and directly queued to user
    2904862 acknowledgments not containing data payload received
    4551225 predicted acknowledgments
    6575 times recovered from packet loss due to fast retransmit
    33583 times recovered from packet loss by selective acknowledgements
    14 bad SACK blocks received
    Detected reordering 4 times using FACK
    Detected reordering 7 times using SACK
    Detected reordering 3 times using time stamp
    6 congestion windows fully recovered without slow start
    126 congestion windows partially recovered using Hoe heuristic
    16 congestion windows recovered without slow start by DSACK
    69 congestion windows recovered without slow start after partial ack
    104272 TCP data loss events
    TCPLostRetransmit: 2032
    1123 timeouts after reno fast retransmit
    1346 timeouts after SACK recovery
    471 timeouts in loss state
    74485 fast retransmits
    382 forward retransmits
    11855 retransmits in slow start
    1779 other TCP timeouts
    1381 classic Reno fast retransmits failed
    1576 SACK retransmits failed
    5077 packets collapsed in receive queue due to low socket buffer
    10601 DSACKs sent for old packets
    46 DSACKs sent for out of order packets
    78 DSACKs received
    7 connections reset due to unexpected data
    5168 connections reset due to early user close
    29 connections aborted due to timeout
    TCPSACKDiscard: 1
    TCPDSACKIgnoredOld: 17
    TCPDSACKIgnoredNoUndo: 26
    TCPSpuriousRTOs: 120
    TCPSackShifted: 168234
    TCPSackMerged: 197911
    TCPSackShiftFallback: 80291
IpExt:
    InOctets: -251100887
    OutOctets: -101194893

Most imporantly though, one of the customer who had previously reported our webservice being virtually unusable has no problems via this reverse proxy. The only thing that is different is guest kernel + guest nic. So this seems to fix my (weird, right?) problem!

Is there any value in digging deeper?

I will observe a bit more of the next days, maybe increase the amount of traffic and then upgrade the kernel of the main proxies if everything remains sweet.

 

[dswartz]

Only thing I can think of is the virtual NIC on the other setup was dropping and/or corrupting segments...