「nat」- 性能问题排查

0

第一步、创建负载环境

性能正常的 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 性能？（下）
networking – How to list all network connections Centos 7 (Connection tracking)