net rx drop

问题来源

接OP问题报告,监控到部分机器的net rx drop统计值异常,触发报警,
需排查具体原因,并确认是否影响业务。

问题分析

复现问题

跟OP同学确认,通过采集/proc/net/dev下的rx drop。
登录到出问题的机器上, 确认内核该统计值确实异常。

  • 异常报文个数不多,大约1s一个左右。
  • 不是所有机器都有异常,有部分机器drop统计为0.

相关内核代码

当一个数据报文经过对端设备(交换机或者网卡)传输到本机物理网卡时候,需要经过
网卡-- 网卡驱动-- 网络协议栈
这几个模块的处理。我们看到的drop统计值在增加,是在网络协议栈的入口处理部分产生异常导致。

内核网络协议栈(伪)入口代码:

注:本文里使用内核3.10.0-514.16.1代码

net/core/dev.c

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
3709 static int __netif_receive_skb_core(struct sk_buff *skb, bool pfmemalloc)
3710 {
....
3753
3754 list_for_each_entry_rcu(ptype, &ptype_all, list) {
3755 if (!ptype->dev || ptype->dev == skb->dev) {
3756 if (pt_prev)
3757 ret = deliver_skb(skb, pt_prev, orig_dev);
3758 pt_prev = ptype;
3759 }
3760 }
3761
....
3814
3815 /* deliver only exact match when indicated */
3816 null_or_dev = deliver_exact ? skb->dev : NULL;
3817
3818 type = skb->protocol;
3819 list_for_each_entry_rcu(ptype,
3820 &ptype_base[ntohs(type) & PTYPE_HASH_MASK], list) {
3821 if (ptype->type == type &&
3822 (ptype->dev == null_or_dev || ptype->dev == skb->dev ||
3823 ptype->dev == orig_dev)) {
3824 if (pt_prev)
3825 ret = deliver_skb(skb, pt_prev, orig_dev);
3826 pt_prev = ptype;
3827 }
3828 }
3829
3830 if (pt_prev) {
3831 if (unlikely(skb_orphan_frags(skb, GFP_ATOMIC)))
3832 goto drop;
3833 else
3834 ret = pt_prev->func(skb, skb->dev, pt_prev, orig_dev);
3835 } else {
3836 drop:
3837 if (!deliver_exact)
3838 atomic_long_inc(&skb->dev->rx_dropped);
3839 else
3840 atomic_long_inc(&skb->dev->rx_nohandler);
3841 kfree_skb(skb);
3842 /* Jamal, now you will not able to escape explaining
3843 * me how you were going to use this. :-)
3844 */
3845 ret = NET_RX_DROP;
3846 }
3847
3848 out:
3849 return ret;
3850 }

有同学可能质疑rx_dropped的统计值不止这一处在修改(增加), 内核里确实不止这一处在增加drop。
这里使用perf调试命令,可以确认3838行的增加跟总统计值匹配,而不是其他地方导致增加。
具体perf命令的使用见下一节。

IPv6报文定位

在使用perf命令查看统计值增长点的时候,我们搂草打兔子,捎带把skb的protocol给打印出来了。
截止到目前可以认为protocol的值就是我们收的网络报文的ethernet头里的protocol字段。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[root@testtest ~]# perf probe -a "__netif_receive_skb_core:129 skb->protocol"
Added new events:
probe:__netif_receive_skb_core (on __netif_receive_skb_core:129 with protocol=skb->protocol)
probe:__netif_receive_skb_core_1 (on __netif_receive_skb_core:129 with protocol=skb->protocol)

You can now use it in all perf tools, such as:

perf record -e probe:__netif_receive_skb_core_1 -aR sleep 1

[root@testtest ~]# perf record -e probe:__netif_receive_skb_core_1 -aR sleep 5
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.209 MB perf.data (5 samples) ]
[root@testtest ~]#
[root@testtest ~]#
[root@testtest ~]# perf script
swapper 0 [003] 596928.567038: probe:__netif_receive_skb_core_1: (ffffffff8152afb6) protocol=dd86
swapper 0 [011] 596929.277293: probe:__netif_receive_skb_core_1: (ffffffff8152afb6) protocol=400
swapper 0 [001] 596929.431077: probe:__netif_receive_skb_core_1: (ffffffff8152afb6) protocol=dd86
swapper 0 [008] 596930.073356: probe:__netif_receive_skb_core_1: (ffffffff8152afb6) protocol=dd86
swapper 0 [011] 596931.278891: probe:__netif_receive_skb_core_1: (ffffffff8152afb6) protocol=400
[root@testtest ~]#

看到protocol=dd86,drop增加的触发原因就找到了(一个)。

因为我们公司是把内核的IPv6功能禁止的,网络协议栈收到IPv6报文的时候是不做任何处理并丢弃的。

1
2
[root@testtest ~]# cat /proc/cmdline
BOOT_IMAGE=/vmlinuz-3.10.0-327.36.3.el7.x86_64 root=UUID=7918e921-db4e-4652-9938-a38607100a96 ro crashkernel=128M selinux=0 ipv6.disable=1

为了进一步验证分析结果,上一个tcpdump的结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
[root@testtest ~]# tcpdump -i eth0 ip6 -c 10
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
14:15:40.663327 IP6 fe80::6e0b:84ff:fe81:b4d3.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:15:45.334814 IP6 fe80::6e0b:84ff:fed6:c323.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:15:45.403538 IP6 fe80::6e0b:84ff:febd:aef8.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:15:52.542434 IP6 fe80::6e0b:84ff:fe81:b935.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:00.186710 IP6 fe80::6e0b:84ff:febd:b27c.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:06.397437 IP6 fe80::6e0b:84ff:fe81:ba03.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:07.834059 IP6 fe80::6e0b:84ff:febd:b602.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:22.138601 IP6 fe80::6e92:bfff:fe2e:616f.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:31.827770 IP6 fe80::6e0b:84ff:fed6:c053.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
14:16:31.882039 IP6 fe80::6e0b:84ff:febd:b798.dhcpv6-client > ff02::1:2.dhcpv6-server: dhcp6 solicit
10 packets captured
10 packets received by filter
0 packets dropped by kernel
[root@testtest ~]#

注:

  1. 这里的截屏是写文章时候去线上测试机抓取的,部分机器上的IPv6问题被修复过一部分。
    所以,我们看到的IPv6报文个数比当初分析问题的时候,相对要偏少。

IPv6报文的来源:服务器同学定位是浪潮服务器的网卡主动发出的。

STP报文定位

异常报文统计有出入

在使用perf工具定位IPv6报文后,人肉查看,发现IPv6的个数大约占drop统计值的60%左右,
也就是说,还有其他类型的报文导致drop统计值在增加。
在硬件厂商修复网卡问题后,观察到大幅降低了drop的增长速度,但没有彻底消除drop的异常统计增长。

正如perf结果显示还有部分protocol=400的报文,这是些啥报文?

我们搜集到了如下一些信息:

  • tcpdump全量抓包,也没有看到400的报文。
  • 查询RFC相关定义,可以发现他们是802.2 LLC
  • 在内核代码里,被网桥的llc模块处理的。
内核代码

net/llc/llc_core.c

1
2
3
4
5
6
110 #define ETH_P_802_2     0x0004          /* 802.2 frames                 */

135 static struct packet_type llc_packet_type __read_mostly = {
136 .type = cpu_to_be16(ETH_P_802_2),
137 .func = llc_rcv,
138 };

做一个试验:
手动加载llc模块,加载后drop统计值不再增张了。
这个实验侧面验证了,有部分网桥相关的报文被传递到内核网络协议栈了。

802.2 LLC

LLC对应了一大家族的链路协议类型,我们需要定位具体是哪一种类型的报文引起的。
这就需要把protocol=400的报文被统计异常的时候,把它当时对应的ethernet头信息打印出来。
针对这样的需求,下一节的centos7上的核弹(热补丁)派上用场了。

注:
LLC对应一大坨的链路层协议,网卡驱动(以ixgbe为例)会借助eth_type_trans函数,
把这些ethernet 协议汇总为802.2 LLC,并存放在skb->protocol里的。

drivers/net/ethernet/intel/ixgbe/ixgbe_main.c

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
1665 static void ixgbe_process_skb_fields(struct ixgbe_ring *rx_ring,
1666 union ixgbe_adv_rx_desc *rx_desc,
1667 struct sk_buff *skb)
1668 {
1669 struct net_device *dev = rx_ring->netdev;
1670 u32 flags = rx_ring->q_vector->adapter->flags;
1671
1672 ixgbe_update_rsc_stats(rx_ring, skb);
1673
1674 ixgbe_rx_hash(rx_ring, rx_desc, skb);
1675
1676 ixgbe_rx_checksum(rx_ring, rx_desc, skb);
1677
1678 if (unlikely(flags & IXGBE_FLAG_RX_HWTSTAMP_ENABLED))
1679 ixgbe_ptp_rx_hwtstamp(rx_ring, rx_desc, skb);
1680
1681 if ((dev->features & NETIF_F_HW_VLAN_CTAG_RX) &&
1682 ixgbe_test_staterr(rx_desc, IXGBE_RXD_STAT_VP)) {
1683 u16 vid = le16_to_cpu(rx_desc->wb.upper.vlan);
1684 __vlan_hwaccel_put_tag(skb, htons(ETH_P_8021Q), vid);
1685 }
1686
1687 skb_record_rx_queue(skb, rx_ring->queue_index);
1688
1689 skb->protocol = eth_type_trans(skb, dev);
1690 }

net/ethernet/eth.c

1
2
3
4
5
6
7
8
9
10
11
12
188 __be16 eth_type_trans(struct sk_buff *skb, struct net_device *dev)
189 {
...
230 if (likely(eth_proto_is_802_3(eth->h_proto)))
231 return eth->h_proto;
...
242 /*
243 * Real 802.2 LLC
244 */
245 return htons(ETH_P_802_2);
246 }
247 EXPORT_SYMBOL(eth_type_trans);

centos7上的核弹 内核热升级工具

centos7(3.10内核)开始,内核组已经部署了一个叫centos-kpatch-modules的rpm包,
它可以做到业务不感知的情况下,加载调试模块,调试完就可卸载。

刚好出问题的机器内核版本是3.10.0-514.16.1.el7.x86_64
于是编写了一个调试模块(后续会集成到centos-kpatch-modules),其功能是:
当drop掉异常报文的时候,把报文的内容(ethernet头)打印出来。

通过kpatch命令加载调试模块,就能把被drop的报文头信息打印出来,

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
[root@testtest xfile]# uname -a
Linux testtest 3.10.0-327.36.3.el7.x86_64 #1 SMP Mon Oct 24 16:09:20 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
[root@testtest xfile]# rpm -q centos-kpatch-modules
centos-kpatch-modules-1.6-1.x86_64
[root@testtest xfile]# kpatch load /root/martin/xfile/net_rx_drop/327/kpatch-dev.ko
loading patch module: /root/martin/xfile/net_rx_drop/327/kpatch-dev.ko
[root@testtest xfile]# dmesg
[606774.224447] kpatch: loaded patch module 'kpatch_dev'
[606775.135343] __netif_receive_skb_core: skb len:105 protocol:0004
[606775.135348] skb_mac_head:ffff88003625c440 skb data:ffff88003625c44e, mac hdr offset:14
[606775.135350] mac hdr dest:01:80:c2:00:00:00 <=== 50:da:00:ef:54:0a proto: 0069
[606775.337246] __netif_receive_skb_core: skb len:96 protocol:86dd
[606775.337252] skb_mac_head:ffff880850046c40 skb data:ffff880850046c4e, mac hdr offset:14
[606775.337255] mac hdr dest:33:33:00:01:00:02 <=== 6c:0b:84:81:ba:03 proto: 86dd
[root@testtest xfile]#

通过日志我们看到被drop的报文ethernet头里protocol字段是0069, 其转化后存在skb里的protocol字段是0004

tcpdump命令也显示有报文进入(此处说法不严谨,后续会被打脸)。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
[root@localhost ~]# tcpdump -i em1 not ip -c 8
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on em1, link-type EN10MB (Ethernet), capture size 65535 bytes
04:55:07.868905 IP6 fe80::303b:6dff:fe6a:20c4 > ff02::16: HBH ICMP6, multicast listener report v2, 1 group record(s), length 28
04:55:08.183959 STP 802.1d, Config, Flags [none], bridge-id 812c.38:1c:1a:7a:c1:80.8036, length 42
04:55:08.738143 STP 802.1s, Rapid STP, CIST Flags [Learn, Forward, Agreement], length 102
04:55:08.790157 IP6 fe80::5c11:3ff:fe55:9037 > ff02::2: ICMP6, router solicitation, length 8
04:55:08.914911 IP6 :: > ff02::16: HBH ICMP6, multicast listener report v2, 1 group record(s), length 28
04:55:09.033921 IP6 :: > ff02::16: HBH ICMP6, multicast listener report v2, 1 group record(s), length 28
04:55:09.185917 IP6 :: > ff02::1:ffab:f174: ICMP6, neighbor solicitation, who has fe80::18cc:d5ff:feab:f174, length 24
04:55:09.773337 IP6 fe80::e818:a4ff:fe30:c522 > ff02::2: ICMP6, router solicitation, length 8
8 packets captured
14 packets received by filter
0 packets dropped by kernel
[root@localhost ~]#

至此,我们锁定STP报文是drop统计增加的另一个来源。

综合多台机器测试结果,被丢弃的报文有三类

  • IPv6
  • STP
  • LLDP

至此问题上半部分析清楚。