29丨案例:如何應對因網路引數導致的TPS%08呈鋸齒狀
並且不是每一個專案都能讓你有分析效能瓶頸的機會,因為有很多問題都是重複的。
所以效能分析是一個需要不斷總結出自己的分析邏輯的工作,有了這些分析邏輯,才能在新專案中無往不利。請注意我的描述,我強調的是要有自己分析的邏輯,而不是經歷多少個性能問題。因為問題可能會遇到新的,但是分析邏輯卻是可以複用的。
在今天的文章中,我仍然用一個之前專案中出現過的案例給你講一講效能分析的思路。
案例問題描述
這個專案是我調優過兩次的專案。我介入這個專案之後,和同事們一起從100TPS調到1000TPS。
但是調到這個階段,也只是在測試環境中調的,並沒有按生產的架構調優。從測試部署架構上來說,就是Tomcat+Redis+MySQL,負載均衡的Nginx部分還沒有加進去。
本來想著如果只是加個Nginx,也複雜不到哪裡去。於是,我就撤了。但是當我離開一週之後,那個專案組同事又給我打電話,說這個專案仍然有問題,加了Nginx之後,TPS達不到1000了。啊,這還得了,要砸我招牌呀。
於是我又介入這個專案了,直到再次解決這個新的效能問題。
在今天的內容裡,我會將記憶中所有的細節都記錄下來,有些是同事調的步驟,有些是我調的步驟。在這個久遠的專案中,希望我能寫的完整。
下面來看這個具體的問題分析過程。
這個系統的簡單架構圖如下所示:
壓力工具圖
照例,我們先看壓力工具中給出來的重要曲線。
使用者遞增圖:
TPS圖:
響應時間圖:
從上面的曲線可以看到,TPS在上升到一個量級的時候就會掉下來,然後再上到同樣的量級再掉下來,非常規律。而響應時間呢,在第一次TPS掉下來之後,就變得亂七八糟了。響應時間不僅上升了,而且抖動也很明顯。
這是什麼情況?從來沒見過呀。
分析過程
我們需要經過一系列的工作——看作業系統的CPU、I/O、Memory、NET等資源;看資料庫、Tomcat、Nginx監控資料等等。
經過分析,我們覺得其他資料顯示正常,網路連線狀態是有問題的。如下所示:
tcp 0 0 ::ffff:192.168.1.12:59103 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59085 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59331 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:46381 ::ffff:192.168.1.104:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59034 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59383 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59138 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59407 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59288 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58905 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58867 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:58891 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59334 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:46129 ::ffff:192.168.1.100:3306 TIME_WAIT timewait (0.00/0/0) tcp 0 0 ::ffff:192.168.1.12:59143 ::ffff:192.168.1.11:3306 TIME_WAIT timewait (0.00/0/0)
從這裡我們可以看到,網路中有大量的timewait存在,這是有價值的資訊了,但也只是現象。
嘗試優化
嘗試一:為TIME_WAIT修改TCP引數
通過檢查sysctl.conf,我們看到所有的配置均為預設,於是嘗試如下修改。
其實這個修改,應該說是在分析得不夠精準的情況下做的判斷。
因為在服務端出現大量的timewait,說明是服務端主動斷開的TCP連線。而我們處理這樣的連線,無非就是釋放服務端的控制代碼和記憶體資源,但是不能釋放埠,因為服務端只開了一個listen埠。
net.ipv4.tcp_tw_recycle = 1
net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_fin_timeout = 3
net.ipv4.tcp_keepalive_time = 3
迴歸測試,問題依舊。
嘗試二:修改Nginx的proxy_ignore_client_abort
考慮到當客戶端主動斷開時,伺服器上也會出現大量的timewait,所以我們開啟proxy_ignore_client_abort,讓Nginx忽略客戶端主動中斷時出現的錯誤。
proxy_ignore_client_abort on;
修改後,重啟Nginx,問題依舊。
這個操作純屬根據經驗做的猜測。因為是加了Nginx之後才出現的問題。但是這個調整並沒有起到作用,可見不是壓力端主動斷開連線而導致的問題,也就是說,和壓力機無關了。
嘗試三:換Nginx和Nginx所在的伺服器
因為這個案例是通過Nginx伺服器才看到TPS上到300就會下降,所以我們考慮是Nginx的問題。但是查來查去,也沒看到Nginx有什麼明顯的問題,於是我們就下載了Nginx的原始碼,重新編譯一下,什麼模組都不加,只做轉發。
通過迴歸測試發現,並沒有解決問題。
到這裡,那就顯然和Nginx本身沒什麼關係了,那麼我們就換個伺服器吧。於是我們在另一臺機器上重新編譯了Nginx,但是問題依舊。
伺服器和Nginx都換了,但還是沒有解決問題,那麼問題會在哪呢?想來想去,還是在作業系統層面,因為Nginx實在是沒啥可調的,只做轉發還能複雜到哪去。
但是作業系統層面又有什麼東西會影響TPS到如此規律的狀態呢?在考慮了應用傳送資料的邏輯之後(請參考《18丨CentOS:作業系統級監控及常用計數器解析(下)》中的網路部分中的“資料傳送過程”和“資料接收過程”),我覺得作業系統本身應該不會存在這樣的限制,網路配置引數我也看過,不會導致這樣的問題。
那麼在作業系統傳送和接收資料的過程中,只有一個大模組我們還完全沒有涉及到,那就是防火牆。於是我查了一下系統的防火牆狀態。
啟用狀態的防火牆是如下這樣的:
[root@node-1 zee]# systemctl status firewalld.service
● firewalld.service - firewalld - dynamic firewall daemon
Loaded: loaded (/usr/lib/systemd/system/firewalld.service; disabled; vendor preset: enabled)
Active: active (running) since Mon 2015-02-17 23:34:55 CST; 2s ago
Docs: man:firewalld(1)
Main PID: 32052 (firewalld)
Tasks: 2
Memory: 32.4M
CGroup: /system.slice/firewalld.service
└─32052 /usr/bin/python -Es /usr/sbin/firewalld --nofork --nopid
從上面的“active (running)”可以看到防火牆確實是開著的。那怎麼辦?果斷地先停掉再說。
嘗試四:停掉防火牆
和網路連線有關的內容,剩下的就只有防火牆了。於是執行如下命令:
Service iptables stop
之後我們就會看到TPS立即就上去了,這就明顯和防火牆相關了。
dmesg查下系統日誌,可以看到如下的大量資訊:
Nov 4 11:35:48 localhost kernel: __ratelimit: 108 callbacks suppressed
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:48 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:53 localhost kernel: __ratelimit: 592 callbacks suppressed
Nov 4 11:35:53 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:53 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:57 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: __ratelimit: 281 callbacks suppressed
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:35:58 localhost kernel: nf_conntrack: table full, dropping packet.
Nov 4 11:36:14 localhost kernel: __ratelimit: 7 callbacks suppressed
這個資訊很明顯,那就是nf_conntrack的表滿了,於是把包給丟了。可是看到這裡的時候,我還不知道nf_conntrack是個啥玩意。
後來通過查資料才知道,nf_conntrack(以前叫ip_conntrack)是Linux中一個跟蹤TCP連線條目的模組,它會用一個雜湊表記錄TCP的連線資訊。當這個雜湊表滿了之後,就會報nf_conntrack: table full,dropping packet
這樣的錯誤。
__ratelimit: N callbacks suppressed
的意思是系統中這樣重複的日誌太多了,達到了核心引數中的net_ratelimit()的上限。Linux中也是用這個引數來避免DDos的。
可是,為啥要丟掉這些包呢?滿就滿了唄,你可以報錯呀。丟人家的包,這一招不是很地道呀。
原理分析
下面來看一下nf_conn的資料結構:
struct nf_conn {
/ Usage count in here is 1 for hash table/destruct timer, 1 per skb, plus 1 for any connection(s) we are `master' for /
struct nf_conntrack ct_general; / 連線跟蹤的引用計數 /
spinlock_t lock;
/* Connection tracking(連結跟蹤)用來跟蹤、記錄每個連結的資訊(目前僅支援IP協議的連線跟蹤)。每個連結由“tuple”來唯一標識,這裡的“tuple”對不同的協議會有不同的含義,例如對TCP,UDP來說就是五元組: (源IP,源埠,目的IP, 目的埠,協議號),對ICMP協議來說是: (源IP, 目的IP, id, type, code), 其中id,type與code都是icmp協議的資訊。連結跟蹤是防火牆實現狀態檢測的基礎,很多功能都需要藉助連結跟蹤才能實現,例如NAT、快速轉發、等等。*/
struct nf_conntrack_tuple_hash tuplehash[IP_CT_DIR_MAX];
unsigned long status; / 可以設定由enum ip_conntrack_status中描述的狀態 /
struct nf_conn master; / 如果該連線是某個連線的子連線,則master指向它的主連線 */
/ Timer function; drops refcnt when it goes off. /
struct timer_list timeout;
union nf_conntrack_proto proto; / 用於儲存不同協議的私有資料 /
/ Extensions /
struct nf_ct_ext ext; / 用於擴充套件結構 */
}
上面的nf_conn有最大個數限制,它是通過nf_conntrack_max來限制的,預設值是65535。
通過查詢資料,我發現nf_conn的主要作用,如下描述:
在nf_conntrack模組中,實現了對連線跟蹤。它利用netfilter框架中的nf_register_hook/nf_unregister_hook函式來註冊鉤子項,呼叫nf_conntrack_in來建立相應連線,ipv4_conntrack_in掛載在NF_IP_PRE_ROUTEING點上(該函式主要實現了建立連線),從而實現連線跟蹤。
從上面的描述我們就可以看到,原來這個模組並不是防火牆必須的模組,並且從實現手法上來說,是通過註冊hook函式實現的功能。有黑客經驗的人應該經常聽到hook函式,很多病毒軟體都用這個思路往其他的應用中插入自己的程式碼模組的。
引數調整
知道了是什麼模組之後,就很容易找到和它相關的引數了,這個資訊你可以直接在作業系統的官網資訊中找得到。
那麼nf_conntrack的引數是什麼呢?
net.netfilter.nf_conntrack_max
//是允許的最大跟蹤連線條目,是在核心記憶體中netfilter可以同時處理的“任務”。
net.netfilter.nf_conntrack_tcp_timeout_established
//是TCP連線建立時的超時時間。
其實還有其他引數,只是這兩個和效能相關,所以我在這裡單獨列了出來。
根據官方的公式,nf_conntrack_max的最大值是CONNTRACK_MAX = RAMSIZE(in bytes)/16384/(ARCH/32)
。
其中,RAMSIZE是實體記憶體大小,ARCH是作業系統位數,16384是netfilter框架中hash桶引數nf_conntrack_buckets的預設大小。
以32G記憶體,64位作業系統為例:
CONNTRACK_MAX = 32*10241024*1024/16384/2 = 1048576條
也就是說,如果你有記憶體,就可以把這個值調大點。
我在這裡就直接往後面加了個0,改為:
net.netfilter.nf_conntrack_max=655350
知道了原理,就不止一個調優方案了,下面我們就來看看。
其他解決方案
關閉防火牆
chkconfig iptables off
chkconfig ip6tables off
service iptables stop
service ip6tables stop
禁用在這個埠上跟蹤(也稱為使用裸表)
在防火牆規則中這樣配置:
-A PREROUTING -p tcp -m tcp --dport 80 -j NOTRACK
你也可以直接對TCP禁用跟蹤,至於規則配置,就看你的想像力了(這也是我比較不喜歡弄防火牆的原因,配置也太靈活了,容易亂)。
刪除跟蹤模組
你還可以直接刪除跟蹤模組。首先,檢視有哪些模組:
lsmod | grep nf_conntrack
再用rmmod刪除它們。
總之,不管你用什麼方式,都需要再你的應用可以安全並能正常提供服務的前提下使用。
知道了解決方案之後,我們就來看下解決之後的TPS是怎樣的。
解決問題後的TPS圖
上圖中有兩次TPS下降的過程,這是因為我又嘗試修改了防火牆的禁用引數配置,重啟了兩次防火牆。並不是出現了新的問題,所以不要緊張。
後來在這個專案中又調優了一些其他的引數,下面是最終達到的調優效果。
藍色是調優前的,紅色是調優後的。
我們可以看到響應時間下降了很多,TPS也上去了,客戶非常滿意,還請我吃了頓忘不了的牛肉火鍋。哈。
總結
效能問題總是層出不窮,不管你以前多有經驗,都可能會遇到不懂的效能問題。
如果建立了分析問題的思路邏輯,並且又善於學習和查詢各種資料,找到根本原因,最後都會給出完整的解決方案。
這個案例應該說是個比較偏門的效能問題了,解決問題的思路就是我上面說的那樣。
其實你也可以看到,有很多時候,我們的效能問題和程式碼並沒有關係,所以這裡也提醒那些一玩效能就想看程式碼的人,眼光要放開闊一些。還有就是遇到效能問題時,一定要記住,不要慌!