單機多網卡互通——問題跟蹤+工具分析

一、背景

想搭建soft ROCE(RXE)與實體ROCE設備互聯的測試環境，為了節省機器以及使用方便，預想在配備ROCE卡的主機上，用另一個網卡綁定soft ROCE，然后互通。

[ETH1?+ ROCE] <--------------------> [ETH2?+ RXE]

二、問題跟蹤

ROCE向RXE發送send only，兩端都沒有收到cqe。

1、tcpdump抓取ETH2網卡，抓獲了ROCE v2的send only報文，沒有ack報文。

也就是說數據包已經成功環回，外部鏈路正常；RXE的接受處理路徑出現異常，導致沒有響應。

2、使用funcgraph抓取，RXE注冊的隧道接收處理函數

perf-tools funcgraph rxe_udp_encap_recv

沒有捕獲到，這跟預想的不一樣，這說明：

數據包在進入RXE的處理之前，已經被丟掉了。需要看數據包的底層接收路徑。

3、然后開啟了將近一天的四處碰壁階段。

由于過往對網絡的內核處理路徑了解很少，理了一下rxe_udp_encap_recv的調用路徑，推測應該是通過udp_unicast_rcv_skb接口調用的，其余還有mcast/broadcast兩個接口，但我們這個數據包不應該是多播和廣播。

然后trace了一下udp_unicast_rcv_skb接口，還是沒有捕獲到！

這段代碼是這個樣子的：

int __udp4_lib_rcv(struct sk_buff *skb, struct udp_table *udptable,int proto)
{/* .............*/sk = __udp4_lib_lookup_skb(skb, uh->source, uh->dest, udptable);if (sk)return udp_unicast_rcv_skb(sk, skb, uh);/* .............*/
}

4、本著就近原則，trace了一下udp4_lib_lookup接口，發現可以trace 到！！！那問題不就出在這里了么？？？

所以接下來用bpftrace跟蹤了下udp4_lib_lookup的返回值，確實是0，沒有拿到socket，所以報文被丟了！

5、為什么拿不到socket

用bpftrace跟蹤了upd4_lib_lookup中的入參，源目端口，源目地址，數值都是正確的！那為啥拿不到socket？RXE里監聽這個端口的socket創建有問題？？？

試圖梳理一下socket的創建、查找，短時間不好搞定，未果。

6、udp_rcv沒有執行

這時候想要么funcgraph抓一下udp報文的處理入口，udp_rcv，看一下他的執行路徑，在哪個環節跟正常的報文不一樣？也可能前置出錯，引發的問題。

結果發現，udp_rcv沒有捕獲到！！！離了個大譜！！

7、bpftrace跟蹤udp_lib_lookup的調用棧

那誰調用了udp_lib_lookup呢？把它的調用棧打印出來看一下。

咦，是在udp_gro_receive接口中調用的。

#!/usr/bin/env bpftrace#include <linux/netdevice.h>
#include <linux/udp.h>
#include <linux/skbuff.h>
#include <linux/netdev_features.h>kprobe:__udp4_lib_lookup {printf("saddr=0x%x,sport=0x%x,daddr=0x%x,dport=0x%x\n",arg1, arg2, arg3, arg4);@[kstack]=count();
}kretprobe:udp4_lib_lookup2 {printf("sock=0x%x\n",retval);if(retval != 0) {printf("encap_recv = 0x%x, gro_receive= 0x%x, gro_enabled=%d\n", ((struct udp_sock *)retval)->encap_rcv, ((struct udp_sock *)retval)->gro_receive, ((struct udp_sock *)retval)->gro_enabled);}
}

看到是udp4_gro_receive接口調用了udp4_lib_lookup，然后沒有查詢到socket。

[root@localhost leiyanjie]# bpftrace udp.bt
Attaching 3 probes...
saddr=0x3231a8c0,sport=0x8,daddr=0x7e33a8c0,dport=0xb712
sock=0x0
sock=0xa7ef9b00
encap_recv = 0xc071a520, gro_receive= 0x0, gro_enabled=0
skb->dev=0xffff9280187d7000, skb->dev->features = 0x10000134829, GRO_FEATURE_BIT=57
^C@[__udp4_lib_lookup+1udp4_gro_receive+402inet_gro_receive+675dev_gro_receive+1574napi_gro_receive+96receive_buf+911virtnet_poll+331net_rx_action+309__softirqentry_text_start+188asm_call_sysvec_on_stack+15do_softirq_own_stack+55irq_exit_rcu+208common_interrupt+120asm_common_interrupt+30cpuidle_enter_state+214cpuidle_enter+41do_idle+452cpu_startup_entry+25start_secondary+276secondary_startup_64_no_verify+176
]: 1

8、跟蹤udp4_gro_receive的執行路徑

發現，怎么這個接口接口這么簡單就退出了呀，是不是沒有接收完，把報文丟掉了？！！

# ad perf-tools funcgraph udp4_gro_receive
Tracing "udp4_gro_receive"... Ctrl-C to end.1)               |  udp4_gro_receive() {1)   0.197 us    |    irq_enter_rcu();1)               |    __sysvec_irq_work() {1)               |      __wake_up() {1)               |        __wake_up_common_lock() {1)   0.644 us    |          _raw_spin_lock_irqsave();1)               |          __wake_up_common() {1)               |            autoremove_wake_function() {1)               |              default_wake_function() {1)               |                try_to_wake_up() {1)   0.801 us    |                  _raw_spin_lock_irqsave();1)               |                  select_task_rq_fair() {1)   0.365 us    |                    available_idle_cpu();1)   0.364 us    |                    cpus_share_cache();1)   1.268 us    |                    update_cfs_rq_h_load();1)               |                    select_idle_sibling() {1)   0.374 us    |                      available_idle_cpu();1)   0.560 us    |                    }1)   0.086 us    |                    rcu_read_unlock_strict();1)   3.776 us    |                  }1)               |                  ttwu_queue_wakelist() {1)               |                    __smp_call_single_queue() {1)   0.569 us    |                      send_call_function_single_ipi();1)   1.396 us    |                    }1)   1.776 us    |                  }1)   0.097 us    |                  _raw_spin_unlock_irqrestore();1)   7.576 us    |                }1)   8.340 us    |              }1)   8.544 us    |            }1)   9.832 us    |          }1)   0.094 us    |          _raw_spin_unlock_irqrestore();1) + 11.127 us   |        }1) + 11.301 us   |      }1) + 12.007 us   |    }1)               |    irq_exit_rcu() {1)   0.087 us    |      idle_cpu();1)               |      tick_nohz_irq_exit() {1)   0.102 us    |        ktime_get();1)   0.287 us    |      }1)   0.647 us    |    }1)               |    __udp4_lib_lookup() {1)   0.700 us    |      udp4_lib_lookup2();1)               |      udp4_lib_lookup2() {1)   0.227 us    |        compute_score();1)   0.252 us    |        compute_score();1)   1.306 us    |      }1)   2.482 us    |    }1)   0.243 us    |    udp_gro_receive();1)   0.086 us    |    rcu_read_unlock_strict();1) + 20.713 us   |  }
^C
Ending tracing...

然后掉進了一個大坑，查看udp_gro_receive的代碼如下：

	if (!sk || !udp_sk(sk)->gro_receive) {if (skb->dev->features & NETIF_F_GRO_FRAGLIST)NAPI_GRO_CB(skb)->is_flist = sk ? !udp_sk(sk)->gro_enabled : 1;if ((!sk && (skb->dev->features & NETIF_F_GRO_UDP_FWD)) ||(sk && udp_sk(sk)->gro_enabled) || NAPI_GRO_CB(skb)->is_flist)return call_gro_receive(udp_gro_receive_segment, head, skb);/* no GRO, be sure flush the current packet */goto out;}

那么udp_gro_receive_segment應該是要被執行的，可實際沒有執行。為什么？

因為我們的網卡使能了GRO，而RXE只提供了encap_rcv接口，實際也需要注冊自己的gro_receive么？！

	tnl_cfg.encap_type = 1;tnl_cfg.encap_rcv = rxe_udp_encap_recv;/* Setup UDP tunnel */setup_udp_tunnel_sock(net, sock, &tnl_cfg);

void setup_udp_tunnel_sock(struct net *net, struct socket *sock,struct udp_tunnel_sock_cfg *cfg)
{struct sock *sk = sock->sk;/* Disable multicast loopback */inet_sk(sk)->mc_loop = 0;/* Enable CHECKSUM_UNNECESSARY to CHECKSUM_COMPLETE conversion */inet_inc_convert_csum(sk);rcu_assign_sk_user_data(sk, cfg->sk_user_data);udp_sk(sk)->encap_type = cfg->encap_type;udp_sk(sk)->encap_rcv = cfg->encap_rcv;udp_sk(sk)->encap_err_rcv = cfg->encap_err_rcv;udp_sk(sk)->encap_err_lookup = cfg->encap_err_lookup;udp_sk(sk)->encap_destroy = cfg->encap_destroy;udp_sk(sk)->gro_receive = cfg->gro_receive;udp_sk(sk)->gro_complete = cfg->gro_complete;udp_tunnel_encap_enable(sock);
}

RXE是標準內核驅動隨著內核版本更新升級的，理論上不應該不支持開啟了GRO的網卡？

9、bpfrrace跟蹤這段代碼的參數

因為不熟悉，所以全都靠猜：是不是我們的網卡置位NETIF_F_GRO_FRAGLIST這個標識，就可以執行后續的call_gro_receive？

# bpftrace udp.bt
Attaching 3 probes...
saddr=0x3231a8c0,sport=0x8,daddr=0x7e33a8c0,dport=0xb712
sock=0x0
sock=0xa7ef9b00
encap_recv = 0xc071a520, gro_receive= 0x0, gro_enabled=0
skb->dev=0xffff9280187d7000, skb->dev->features = 0x10000134829, GRO_FEATURE_BIT=57

10、增加GRO_FRAGLIST屬性

man ethtool

ethtool -k eth2 查詢網卡屬性

ethtool -K eth2 **** on/off 設置網卡屬性

# ethtool -k eth2 | grep gro
rx-gro-hw: off [fixed]
rx-gro-list: off# thtool -K eth2 rx-gro-list on

然后bpftrace發現，這個標識確實在netdev->features開啟成功了，但并還是沒有進入后續的segment收包流程。

再次進入死胡同。

三、問題跟蹤2

網絡搜索了一下udp_gro_receive的相關流程，也不能夠幫助在短時間內建立非常清晰的理解。

比較幸運的是，udp的報文并不多，所以我們在udp_gro_receive接口中輕易的抓到了報文，而且從sk_buff結構中拿到了netdev的地址。

1、bpftrace根據參數過濾eth2的ip_rcv接口

所以，嘗試抓取ip_rcv接口，數據有沒有進入ip_rcv接口呢？

eth0的IP報文是很多的，咋篩選出eth2的報文呢？既然我們拿到了netdev的地址，就可以根據netdev精確過濾出eth2的報文。

kprobe:ip_rcv {if(arg1 == 0xffff9ab4a371a000) {printf("get eth2 packet\n");@[kstack]=count();}
}

捕獲到了get eth2 packet！

這說明之前推測的GRO丟包是錯誤的，其實報文已經送到了IP層，沒有進入UDP層。是在IP層丟掉的。

saddr=0x3231a8c0,sport=0x8,daddr=0x8734a8c0,dport=0xb712
sock=0x0
sock=0x1680bf00
encap_recv = 0xc055d520, gro_receive= 0x0, gro_enabled=0
skb->dev=0xffff9ab4a371a000, skb->dev->features = 0x200010000134829, GRO_FEATURE_BIT=57
get eth2 packet

本來用funcgraph跟蹤一下ip_rcv接口會更直觀，看報文丟棄在了哪個環節，但因為funcgraph無法傳入參數過濾，eth0的IP報文也比較多，就沒有采用這種方式。

2、ip_rcv_finish接口返回失敗

ip_rcv接口比較簡單，很容易就跟蹤到是ip_rcv_finish接口返回失敗，導致報文沒有進一步上送。

kretprobe:ip_rcv_finish {printf("ret=0x%x\n",retval);
}

3、tracepoint跟蹤kfree_skb_reason

分析了ip_rcv_finish_core接口，看到有多個位置可能導致異常返回，異常返回都會調用kfree_skb_reason這個接口傳遞釋放sk_buff，而且會把錯誤碼（drop_reason）傳入。

kfree_skb_reason在我安裝的5.10內核版本上實際測試，沒有查詢到bpftrace入口。

但是在我5.15的內核代碼中，是有trace點的，可以把reason打印出來。

void kfree_skb_reason(struct sk_buff *skb, enum skb_drop_reason reason)
{if (!skb_unref(skb))return;trace_kfree_skb(skb, __builtin_return_address(0), reason);__kfree_skb(skb);
}

所以開始研究使用tracepoint。/sys/kernel/debug/tracing/available_events中記錄了所有的可trace事件。可以看到

/sys/kernel/debug/tracing # cat available_events | grep kfree_skb
skb:kfree_skb

那么如何使能這個事件？進入events/skb/kfree_skb目錄，有如下接口文件：

/sys/kernel/debug/tracing/events/skb/kfree_skb # ls
enable  filter  format  id  trigger

enable輸入1，就可以使能trace，不需要其他開關。

filter是可以輸入過濾條件的，比如過濾eth2的報文？這個需要后面學習一下。

format是顯示trace日志格式的。

實際的trace日志，還可以顯示pid、cpu和時間，挺好的。結果如下：

因為我的機器上的內核版本是5.10，所以看不到reason，這是個讓人傷心的故事。從某個patch來看，確實是后面的版本合入的kfree_skb_reason。原來正常的skb釋放也是走這個路徑，所以trace kfree_skb有特別多的日志，無法區分。

4、tracepoint跟蹤kfree_skb_reason和consume_skb

在高版本內核中，正常的skb釋放走consume_skb路徑，drop的skb釋放走kfree_skb_reason路徑，就可以區分出來了。

5、bpftrace打樁跟蹤執行路徑

既然看不出來drop reason，那其實直接用bpftrace在ip_recv_finish_core的各個接口中打樁是可以看到執行路徑的。

因為我們也不是大流量的環境，網絡報文的密度比較小。所以抓到udp報文后，緊跟著的打印可以認為是同一條報文的處理路徑中的。

最終確認是在ip_route_input_slow接口，路由失敗引發丟包的。

kprobe:ip_rcv {if(arg1 == 0xffff9ab4a371a000) {printf("get eth2 packet\n");@[kstack]=count();}
}kprobe:ip_rcv_finish {if(((struct sk_buff *)arg2)->dev == 0xffff9ab4a371a000) {printf("get eth2 packet\n");@[kstack]=count();}
}kretprobe:ip_route_use_hint {printf("ip_route_use_hind, ret=0x%x\n", retval);
}kretprobe:udp_v4_early_demux {printf("udp_v4_early_demux, ret=0x%x\n", retval);
}kretprobe:ip_route_input_noref {printf("ip_route_input_noref, ret=%d\n", retval);
}kretprobe:ip_rcv_finish {printf("ret=0x%x\n",retval);
}kretprobe:ip_route_input_slow {printf("ip_route_input_slow, ret=%d\n", retval);
}

6、為什么會路由失敗？？

我簡單嘗試了一下，用eth1 ping eth2，發現也是無法ping通的。這臺機器上的3個網卡都無法互相ping通。

所以此時意識到，同一臺機器上的兩個網卡之間是不是就是不能通信的？

然后開始資料查詢，重點針對一臺機器上的多個網卡。

有幾篇文章都作了說明，但原理又都不清楚，只是說linux對此的支持不友好。

反而是最終在自己瘋狂的嘗試中，誤打誤撞解決了問題。

sysctl -w /proc/sys/net/ipv4/conf/all/accep_local=1
sysctl -w /proc/sys/net/ipv4/conf/all/rp_filter=2

IP路由的相關知識后續學習補充。