追蹤將服務器CPU耗光的兇手-魔扣目錄

前面我們討論系統調用的時候結論是耗時200ns-15us不等。不過我今天說的我的這個遭遇可能會讓你進一步認識系統調用的真正開銷。在本節里你會看到一個耗時2.5ms的connect系統調用，注意是毫秒,相當于2500us！

問題描述

當時是我的一個線上云控接口，是Nginx+lua寫的。正常情況下，單虛機8核8G可以抗每秒2000左右的QPS，負載還比較健康。但是該服務近期開始出現一些500狀態的請求了，監控時不時會出現報警。通過sar -u查看峰值時cpu余量只剩下了20-30%。

圖3.jpg

第一步、迅速鎖定嫌疑人

top命令查看cpu使用，通過top命令發現峰值的時候cpu確實消耗的比較多，idle只有20-30%左右。在使用的cpu里，軟中斷的占比也比較高，1/3左右。

再通過cat /proc/softirqs查看到軟中斷是都是網絡IO產生的NET_TX，NET_RX，和時鐘TIMER。

既然軟中斷這個賊人吃掉了我這么多的CPU時間，所以案件的嫌疑人就這么初步被我鎖定了。

處理，那既然是NET_TX，NET_RX和TIMER都高，那咱就挑可以削減的功能砍一砍唄。

1.砍掉多余的gettimeofday系統調用
2.每個請求砍掉一次非必須redis訪問，只留了必要的。

結果：峰值的cpu余量從確實多出來一些了。報警頻率確實下來了，但是還是偶爾會有零星的報警。可見該嫌疑人并非主犯。。

第二步、干掉一大片，真兇在其中

接著查看網絡連接的情況ss -n -t -a發現，ESTABLISH狀態的鏈接不是很多，但是TIME-WAIT有11W多。繼續研究發現針對..*.122:6390的TIME-WAIT已經超過了3W。所以端口有限。原來呀，上一步執行時只干掉了連接上的數據請求，但是tcp握手請求仍然存在。

處理：徹底干掉了針對..*.122:6390的網絡連接請求，只保留了必須保留的邏輯。

結果：問題徹底解決。sar -u查看cpu的idle余量竟然達到了90%多。

Tips：單臺機器如果作為TCP的客戶端，有如下限制

ESTABLISH狀態的連接只能有ip_local_port_range范圍內的個數。
只有針對特定ip，特定port的TIME-WAIT過多，超過或接近ip_local_port_range，再新建立連接可能會出現無端口可用的情況。（總的TIME-WAIT過多并不一定有問題）

沒想到一個簡單砍掉一個對redis server的tcp連接，能把cpu優化到這么多。大大出乎意料，而且也想不明白。根據我之前的性能測試經驗，每個tcp連接的建立大約只需要消耗36usec的cpu時間。我們來估算一下：

當時server的qps大約在2000左右，假設是均勻分布的，則8個核每個核每秒只需要處理250個請求。也就是說每秒一條tcp連接需要消耗的cpu時間為：250*36usec = 9ms.

也就是說，正常來講砍掉這些握手開銷只能節約1%左右的cpu，不至于有這么大的提升。（即使我上面的估算只考慮了建立連接，沒有統計釋放連接的cpu開銷，但是連接釋放cpu開銷也和建立連接差不多。）

總之，這一步確實解決了問題，但是代價是犧牲了一個業務邏輯。

最終、審出真兇，真相大白于天下

我在某一臺機器上把老的有問題的代碼回滾了回來，恢復問題現場。然后只修改一下ip_local_port_range。然后請出了strace這個命令。

通過strace -c 統計到對于所有系統調用的開銷匯總。結果我們發現了connect系統調用這個二貨，在正常的機器上只需要22us左右，在有問題的機器上竟然花掉來 2500us，上漲了100倍。我們用strace -c $PID查看一下出問題時和正常時的connect系統調用耗時對比：

圖1.png

<centor>圖1：正常情況下</centor>

圖2.png

然后回想起了..*.122:6390的TIME-WAIT已經超過了3W，會不會TIME_WAIT占用了太多端口導致端口不足呢。因此查看端口內核參數配置：

# sysctl -a | grep ip_local_port_range

net.ipv4.ip_local_port_range = 32768 65000

果然發現該機器上的端口范圍只開了3W多個，也就是說端口已經幾乎快用滿了。那就提高端口可用數量：

# vim /etc/sysctl.conf
net.ipv4.ip_local_port_range = 10000 65000

connect系統調用恢復理性狀態，整體服務器的CPU使用率非常健康。

問題的根本原因是建立TCP連接使用的端口數量上（ip_local_port_range）不充裕，導致connect系統調用開銷上漲了將近100倍！

后來我們的一位開發同學幫忙翻到了connect系統調用里的一段源碼

int inet_hash_connect(struct inet_timewait_death_row *death_row,

struct sock *sk)

{

return __inet_hash_connect(death_row, sk, inet_sk_port_offset(sk),

__inet_check_established, __inet_hash_nolisten);

}

int __inet_hash_connect(struct inet_timewait_death_row *death_row,

struct sock *sk, u32 port_offset,

int (*check_established)(struct inet_timewait_death_row *,

struct sock *, __u16, struct inet_timewait_sock **),

int (*hash)(struct sock *sk, struct inet_timewait_sock *twp))

{

struct inet_hashinfo *hinfo = death_row->hashinfo;

const unsigned short snum = inet_sk(sk)->inet_num;

struct inet_bind_hashbucket *head;

struct inet_bind_bucket *tb;

int ret;

struct net *net = sock_net(sk);

int twrefcnt = 1;

if (!snum) {

int i, remaining, low, high, port;

static u32 hint;

u32 offset = hint + port_offset;

struct inet_timewait_sock *tw = NULL;

inet_get_local_port_range(&low, &high);

remaining = (high - low) + 1;

local_bh_disable();

for (i = 1; i <= remaining; i++) {

port = low + (i + offset) % remaining;

if (inet_is_reserved_local_port(port))

continue;

......

}

static inline u32 inet_sk_port_offset(const struct sock *sk)

{

const struct inet_sock *inet = inet_sk(sk);

return secure_ipv4_port_ephemeral(inet->inet_rcv_saddr,

inet->inet_daddr,

inet->inet_dport);

}

從上面源代碼可見，臨時端口選擇過程是生成一個隨機數，利用隨機數在ip_local_port_range范圍內取值，如果取到的值在ip_local_reserved_ports范圍內，那就再依次取下一個值，直到不在ip_local_reserved_ports范圍內為止。原來臨時端口竟然是隨機撞。出。來。的。。也就是說假如就有range里配置了5W個端口可以用，已經使用掉了49999個。那么新建立連接的時候，可能需要調用這個隨機函數5W次才能撞到這個沒用的端口身上。

所以請記得要保證你可用臨時端口的充裕，避免你的connect系統調用進入SB模式。正常端口充足的時候，只需要22usec。但是一旦出現端口緊張，則一次系統調用耗時會上升到2.5ms，整整多出100倍。這個開銷比正常tcp連接的建立吃掉的cpu時間（每個30usec左右）的開銷要大的多。