Diagnosing packet loss / high latency in Ubuntu

Posted by Sam Gammon on Server Fault See other posts from Server Fault or by Sam Gammon
Published on 2013-10-28T22:39:37Z Indexed on 2013/10/29 3:57 UTC
Read the original article Hit count: 545

We have a Linux box (Ubuntu 12.04) running Nginx (1.5.2), which acts as a reverse proxy/load balancer to some Tornado and Apache hosts. The upstream servers are physically and logically close (same DC, sometimes same-rack) and show sub-millisecond latency between them:

 PING appserver (10.xx.xx.112) 56(84) bytes of data.
 64 bytes from appserver (10.xx.xx.112): icmp_req=1 ttl=64 time=0.180 ms
 64 bytes from appserver (10.xx.xx.112): icmp_req=2 ttl=64 time=0.165 ms
 64 bytes from appserver (10.xx.xx.112): icmp_req=3 ttl=64 time=0.153 ms

We receive a sustained load of about 500 requests per second, and are currently seeing regular packet loss / latency spikes from the Internet, even from basic pings:

sam@AM-KEEN ~> ping -c 1000 loadbalancer
PING 50.xx.xx.16 (50.xx.xx.16): 56 data bytes
64 bytes from loadbalancer: icmp_seq=0 ttl=56 time=11.624 ms
64 bytes from loadbalancer: icmp_seq=1 ttl=56 time=10.494 ms

... many packets later ...

Request timeout for icmp_seq 2
64 bytes from loadbalancer: icmp_seq=2 ttl=56 time=1536.516 ms
64 bytes from loadbalancer: icmp_seq=3 ttl=56 time=536.907 ms
64 bytes from loadbalancer: icmp_seq=4 ttl=56 time=9.389 ms

... many packets later ...

Request timeout for icmp_seq 919
64 bytes from loadbalancer: icmp_seq=918 ttl=56 time=2932.571 ms
64 bytes from loadbalancer: icmp_seq=919 ttl=56 time=1932.174 ms
64 bytes from loadbalancer: icmp_seq=920 ttl=56 time=932.018 ms
64 bytes from loadbalancer: icmp_seq=921 ttl=56 time=6.157 ms

--- 50.xx.xx.16 ping statistics ---
1000 packets transmitted, 997 packets received, 0.3% packet loss
round-trip min/avg/max/stddev = 5.119/52.712/2932.571/224.629 ms

The pattern is always the same: things operate fine for a while (<20ms), then a ping drops completely, then three or four high-latency pings (>1000ms), then it settles down again.

Traffic comes in through a bonded public interface (we will call it bond0) configured as such:

 bond0     Link encap:Ethernet  HWaddr 00:xx:xx:xx:xx:5d
           inet addr:50.xx.xx.16  Bcast:50.xx.xx.31  Mask:255.255.255.224
           inet6 addr: <ipv6 address> Scope:Global
           inet6 addr: <ipv6 address> Scope:Link
           UP BROADCAST RUNNING MASTER MULTICAST  MTU:1500  Metric:1
           RX packets:527181270 errors:1 dropped:4 overruns:0 frame:1
           TX packets:413335045 errors:0 dropped:0 overruns:0 carrier:0
           collisions:0 txqueuelen:0 
           RX bytes:240016223540 (240.0 GB)  TX bytes:104301759647 (104.3 GB)

Requests are then submitted via HTTP to upstream servers on the private network (we can call it bond1), which is configured like so:

  bond1     Link encap:Ethernet  HWaddr 00:xx:xx:xx:xx:5c  
            inet addr:10.xx.xx.70  Bcast:10.xx.xx.127  Mask:255.255.255.192
            inet6 addr: <ipv6 address> Scope:Link
            UP BROADCAST RUNNING MASTER MULTICAST  MTU:1500  Metric:1
            RX packets:430293342 errors:1 dropped:2 overruns:0 frame:1
            TX packets:466983986 errors:0 dropped:0 overruns:0 carrier:0
            collisions:0 txqueuelen:0 
            RX bytes:77714410892 (77.7 GB)  TX bytes:227349392334 (227.3 GB)

Output of uname -a:

Linux <hostname> 3.5.0-42-generic #65~precise1-Ubuntu SMP Wed Oct 2 20:57:18 UTC 2013 x86_64 GNU/Linux

We have customized sysctl.conf in an attempt to fix the problem, with no success. Output of /etc/sysctl.conf (with irrelevant configs omitted):

# net: core
net.core.netdev_max_backlog = 10000

# net: ipv4 stack
net.ipv4.tcp_ecn = 2
net.ipv4.tcp_sack = 1
net.ipv4.tcp_fack = 1
net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_tw_recycle = 0
net.ipv4.tcp_timestamps = 1
net.ipv4.tcp_window_scaling = 1
net.ipv4.tcp_no_metrics_save = 1
net.ipv4.tcp_max_syn_backlog = 10000
net.ipv4.tcp_congestion_control = cubic
net.ipv4.ip_local_port_range = 8000 65535

net.ipv4.tcp_syncookies = 1
net.ipv4.tcp_synack_retries = 2

net.ipv4.tcp_thin_dupack = 1
net.ipv4.tcp_thin_linear_timeouts = 1

net.netfilter.nf_conntrack_max = 99999999
net.netfilter.nf_conntrack_tcp_timeout_established = 300

Output of dmesg -d, with non-ICMP UFW messages suppressed:

[508315.349295 <   19.852453>] [UFW BLOCK] IN=bond1 OUT= MAC=<mac addresses> SRC=118.xx.xx.143 DST=50.xx.xx.16 LEN=68 TOS=0x00 PREC=0x00 TTL=51 ID=43221 PROTO=ICMP TYPE=3 CODE=1 [SRC=50.xx.xx.16 DST=118.xx.xx.143 LEN=40 TOS=0x00 PREC=0x00 TTL=249 ID=10220 DF PROTO=TCP SPT=80 DPT=53817 WINDOW=8190 RES=0x00 ACK FIN URGP=0 ] 

[517787.732242 <    0.443127>] Peer 190.xx.xx.131:59705/80 unexpectedly shrunk window 1155488866:1155489425 (repaired)

How can I go about diagnosing the cause of this problem, on a Debian-family Linux box?

© Server Fault or respective owner

Related posts about networking

Related posts about nginx