「nat」- 性能问题排查

  CREATED BY JENKINSBOT

第一步、创建负载环境

性能正常的 Nginx 服务

# docker run --name nginx-hostnet --privileged --network=host -itd feisky/nginx:80

# curl http://10.10.50.199

# ulimit -n 65536
# ab -c 5000 -n 100000 -r -s 2 http://10.10.50.199/
// -c 表示并发请求数为5000,-n 表示总的请求数为10万
// -r 表示套接字接收错误时仍然继续执行,-s 表示设置每个请求的超时时间为 2s
...
Requests per second:    9531.80 [#/sec] (mean)
Time per request:       524.560 [ms] (mean)
Time per request:       0.105 [ms] (mean, across all concurrent requests)
Transfer rate:          7827.84 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0  220 676.8     56    7350
Processing:     8  174 514.5     58   10205
Waiting:        1  171 511.4     57   10205
Total:         10  394 894.1    114   10272
...

// 每秒请求数(Requests  per second)为 9531;
// 每个请求的平均延迟(Time per request)为 524ms;
// 建立连接的平均延迟(Connect)为 220ms。

运行端口映射的 Nginx 服务

# docker run --name nginx --privileged -p 8080:8080 -itd feisky/nginx:nat

// Nginx 启动后,可以执行 iptables 命令,确认 DNAT 规则已经创建:

# iptables -nL -t nat
Chain PREROUTING (policy ACCEPT)
target     prot opt source               destination
DOCKER     all  --  0.0.0.0/0            0.0.0.0/0            ADDRTYPE match dst-type LOCAL
...
Chain DOCKER (2 references)
target     prot opt source               destination
RETURN     all  --  0.0.0.0/0            0.0.0.0/0
DNAT       tcp  --  0.0.0.0/0            0.0.0.0/0            tcp dpt:8080 to:172.17.0.2:8080

// 确认 Nginx 已经正常启动

# curl http://10.10.50.199:8080/

// 再次执行上述的 ab 命令,请求 8080 端口

# ulimit -n 65536
# ab -c 5000 -n 100000 -r -s 2 http://10.10.50.199:8080/
...
Benchmarking 10.10.50.199 (be patient)
apr_pollset_poll: The timeout specified has expired (70007)
Total of 587 requests completed

// 从输出可以看到,这次只完成了 587 个请求,产生连接超时的错误

// 我们延长超时时间,并降低总测试次数

# ab -c 5000 -n 50000 -r -s 30 http://10.10.50.199:8080/

第二步、问题排查

在 Netfilter 中,根据网络包的流向以及 NAT 的原理,要保证 NAT 正常工作,就至少需要两个步骤:
1)利用 Netfilter 中的钩子函数(Hook),修改源地址或者目的地址。
2)利用连接跟踪模块 conntrack ,关联同一个连接的请求和响应。

使用 systemtap 定位

编写脚本:

#! /usr/bin/env stap

############################################################
# Dropwatch.stp
# Author: Neil Horman <nhorman@redhat.com>
# An example script to mimic the behavior of the dropwatch utility
# http://fedorahosted.org/dropwatch
############################################################

# Array to hold the list of drop points we find
global locations

# Note when we turn the monitor on and off
probe begin { printf("Monitoring for dropped packets\n") }
probe end { printf("Stopping dropped packet monitor\n") }

# increment a drop counter for every location we drop at
probe kernel.trace("kfree_skb") { locations[$location] <<< 1 }

# Every 5 seconds report our drop locations
probe timer.sec(5)
{
  printf("\n")
  foreach (l in locations-) {
    printf("%d packets dropped at %s\n",
           @count(locations[l]), symname(l))
  }
  delete locations
}

运行命令:

# stap --all-modules dropwatch.stp
Monitoring for dropped packets

// 如上输出 表明 SystemTap 已经将脚本编译为内核模块,并启动运行

运行 ab 命令,观察 stap 输出

// 再次运行 ab 命令进行测试

# ab -c 5000 -n 10000 -r -s 30 http://10.10.50.199:8080/

// 观察 stap 输出

10031 packets dropped at nf_hook_slow
676 packets dropped at tcp_v4_rcv

7284 packets dropped at nf_hook_slow
268 packets dropped at tcp_v4_rcv

丢包都发生在 nf_hook_slow 位置,这是 在 Netfilter Hook 的钩子函数。但是不是 NAT,还不能确定。接下来,我们还得再跟踪 nf_hook_slow 的执行过程。

perf record 和 perf report

// 再次运行 ab 命令进行测试

# ab -c 5000 -n 10000 -r -s 30 http://10.10.50.199:8080/


// 记录一会(比如30s)后按Ctrl+C结束

# perf record -a -g -- sleep 30

// 输出报告

# perf report -g graph,0
...

// 在 perf report 界面中,输入查找命令 / 然后,在弹出的对话框中,输入 nf_hook_slow;最后再展开调用栈

可以看到 nf_hook_slow 调用最多的有三个地方:ipv4_conntrack_in、br_nf_pre_routing、iptable_nat_ipv4_in。换言之 nf_hook_slow 主要在执行三个动作:
1)接收网络包时,在连接跟踪表中查找连接,并为新的连接分配跟踪对象(Bucket)。
2)在 Linux 网桥中转发包。这是因为案例 Nginx 是一个 Docker 容器,而容器的网络通过网桥来实现;
3)接收网络包时,执行 DNAT,即把 8080 端口收到的包转发给容器

这三个来源,都是 Linux 的内核机制,所以接下来的优化,自然也是要从内核入手。

第三步、性能优化

DNAT 的基础是 conntrack,所以我们可以先看看,内核提供了哪些 conntrack 的配置选项:

# sysctl -a | grep conntrack
net.netfilter.nf_conntrack_count = 180
net.netfilter.nf_conntrack_max = 1000
net.netfilter.nf_conntrack_buckets = 65536
net.netfilter.nf_conntrack_tcp_timeout_syn_recv = 60
net.netfilter.nf_conntrack_tcp_timeout_syn_sent = 120
net.netfilter.nf_conntrack_tcp_timeout_time_wait = 120
...

// net.netfilter.nf_conntrack_count,表示当前连接跟踪数;
// net.netfilter.nf_conntrack_max,表示最大连接跟踪数;
// net.netfilter.nf_conntrack_buckets,表示连接跟踪表的大小;

// ab 命令,并发请求数是 5000,而请求数是 100000。显然,跟踪表设置成,只记录 1000 个连接,是远远不够的

// 内核在工作异常时,会把异常信息记录到日志中。比如前面的 ab 测试,内核已经在日志中报出了 “nf_conntrack: table full” 的错误,执行 dmesg 命令可以看到
# dmesg | tail
[104235.156774] nf_conntrack: nf_conntrack: table full, dropping packet
[104243.800401] net_ratelimit: 3939 callbacks suppressed
[104243.800401] nf_conntrack: nf_conntrack: table full, dropping packet
[104262.962157] nf_conntrack: nf_conntrack: table full, dropping packet

调整连接跟踪表,如果连接跟踪数过大,也会耗费大量内存。上面看到的 nf_conntrack_buckets 是哈希表的大小。哈希表中的每一项都是一个链表(称为 Bucket),而链表长度,就等于 nf_conntrack_max 除以 nf_conntrack_buckets。

连接跟踪表占用的内存大小
= nf_conntrack_max * 连接跟踪对象大小 + nf_conntrack_buckets * 链表项大小
= 1000 * 376 + 65536 * 16 B = 1.4 MB

注意,连接跟踪对象大小为 376,链表项大小为 16,这是内核数据结构的大小,一般不会变化

我们将 nf_conntrack_max 改大一些,比如改成 131072(即 nf_conntrack_buckets 的 2 倍):

# sysctl -w net.netfilter.nf_conntrack_max=131072
# sysctl -w net.netfilter.nf_conntrack_buckets=65536

第四步、再次进行压力测试

# ab -c 5000 -n 100000 -r -s 2 http://10.10.50.199:8080/
...
Requests per second:    6315.99 [#/sec] (mean)
Time per request:       791.641 [ms] (mean)
Time per request:       0.158 [ms] (mean, across all concurrent requests)
Transfer rate:          4985.15 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0  355 793.7     29    7352
Processing:     8  311 855.9     51   14481
Waiting:        0  292 851.5     36   14481
Total:         15  666 1216.3    148   14645

// 这个结果,已经比刚才的测试好了很多,也很接近最初不用 NAT 时的基准结果

查看连接跟踪表的内容

// -L表示列表,-o表示以扩展格式显示

# conntrack -L -o extended | head
ipv4     2 tcp      6 7 TIME_WAIT src=192.168.0.2 dst=192.168.0.96 sport=51744 dport=8080 src=172.17.0.2 dst=192.168.0.2 sport=8080 dport=51744 [ASSURED] mark=0 use=1
ipv4     2 tcp      6 6 TIME_WAIT src=192.168.0.2 dst=192.168.0.96 sport=51524 dport=8080 src=172.17.0.2 dst=192.168.0.2 sport=8080 dport=51524 [ASSURED] mark=0 use=1

连接跟踪表里的对象,包括协议、连接状态、源 IP、源端口、目的 IP、目的端口、跟踪状态等。由于这个格式是固定的,所以我们可以用 awk、sort 等工具,对其进行统计分析。

使用 ab 测试

# 统计总的连接跟踪数
$ conntrack -L -o extended | wc -l
14289

# 统计TCP协议各个状态的连接跟踪数
$ conntrack -L -o extended | awk '/^.*tcp.*$/ {sum[$6]++} END {for(i in sum) print i, sum[i]}'
SYN_RECV 4
CLOSE_WAIT 9
ESTABLISHED 2877
FIN_WAIT 3
SYN_SENT 2113
TIME_WAIT 9283

# 统计各个源IP的连接跟踪数
$ conntrack -L -o extended | awk '{print $7}' | cut -d "=" -f 2 | sort | uniq -c | sort -nr | head -n 10
  14116 192.168.0.2
    172 192.168.0.96

可以看到大部分 TCP 的连接跟踪,都处于 TIME_WAIT 状态,并且它们大都来自于 192.168.0.2 这个地址。

处于 TIME_WAIT 的连接跟踪记录,会在超时后清理,而默认的超时时间是 120s,如果连接数非常大,确实也应该考虑适当减小超时时间:

# sysctl net.netfilter.nf_conntrack_tcp_timeout_time_wait
net.netfilter.nf_conntrack_tcp_timeout_time_wait = 120

相关链接

记一次Docker/Kubernetes上无法解释的连接超时原因探寻之旅

参考文献

42 | 案例篇:如何优化 NAT 性能?(下)