記一次 Kubernetes 機器內核問題排查
此次排查發生在 2020-11 月份，一直沒時間寫博客描述事情經過，本次正好一起寫了吧。
具體現象
在線上環境中的某個應用出現了接口緩慢的問題!
就憑這個現象，能列出來的原因數不勝數。本篇博客主要敘述一下幾次排查以及最后如何確定原因的過程，可能不一定適用于其他集群，就當是提供一個參考吧。排查過程比較冗長，過去太久了，我也不太可能回憶出所有細節，希望大家見諒。
網絡拓撲結構
網絡請求流入集群時，對于我們集群的結構：
- 用戶請求=> Nginx => Ingress => uwsgi
不要問為什么有了 Ingress 還有 Nginx，這是歷史原因，有些工作暫時需要由 Nginx 承擔。
初次定位
請求變慢一般馬上就會考慮，程序是不是變慢了，所以在發現問題后，首先在 uwsgi 中增加簡單的小接口，這個接口是處理快并且馬上返回數據，然后定時請求該接口。在運行幾天之后，確認到該接口的訪問速度也很慢，排除程序中的問題，準備在鏈路中查找原因。
再次定位 – 簡單的全鏈路數據統計
由于我們的 Nginx 有 2 層，需要針對它們分別確認，看看究竟是哪一層慢了。請求量是比較大的，如果針對每個請求去查看，效率不高，而且有可能掩蓋真正原因，所以這個過程采用統計的方式。統計的方式是分別查看兩層 Nginx 的日志情況。由于我們已經在 ELK 上接入了日志，ELK 中篩選數據的腳本簡單如下：
- {
- "bool": {
- "must": [
- {
- "match_all": {}
- },
- {
- "match_phrase": {
- "app_name": {
- "query": "xxxx"
- }
- }
- },
- {
- "match_phrase": {
- "path": {
- "query": "/app/v1/user/ping"
- }
- }
- },
- {
- "range": {
- "request_time": {
- "gte": 1,
- "lt": 10
- }
- }
- },
- {
- "range": {
- "@timestamp": {
- "gt": "2020-11-09 00:00:00",
- "lte": "2020-11-12 00:00:00",
- "format": "yyyy-MM-dd HH:mm:ss",
- "time_zone": "+08:00"
- }
- }
- }
- ]
- }
- }
數據處理方案
根據 trace_id 可以獲取到 Nignx 日志以及 Ingress 日志，通過 ELK 的 API 獲得。
- # 這個數據結構用來記錄統計結果，
- # [[0, 0.1], 3]表示落在 0~0.1 區間的有 3 條記錄
- # 因為小數的比較和區間比較麻煩，所以采用整數，這里的 0~35 其實是 0~3.5s 區間
- # ingress_cal_map = [
- # [[0, 0.1], 0],
- # [[0.1, 0.2], 0],
- # [[0.2, 0.3], 0],
- # [[0.3, 0.4], 0],
- # [[0.4, 0.5], 0],
- # [[0.5, 1], 0],
- # ]
- ingress_cal_map = []
- for x in range(0, 35, 1):
- ingress_cal_map.append(
- [[x, (x+1)], 0]
- )
- nginx_cal_map = copy.deepcopy(ingress_cal_map)
- nginx_ingress_gap = copy.deepcopy(ingress_cal_map)
- ingress_upstream_gap = copy.deepcopy(ingress_cal_map)
- def trace_statisics():
- trace_ids = []
- # 這里的 trace_id 是提前查找過，那些響應時間比較久的請求所對應的 trace_id
- with open(trace_id_file) as f:
- data = f.readlines()
- for d in data:
- trace_ids.append(d.strip())
- cnt = 0
- for trace_id in trace_ids:
- try:
- access_data, ingress_data = get_igor_trace(trace_id)
- except TypeError as e:
- # 繼續嘗試一次
- try:
- access_data, ingress_data = get_igor_trace.force_refresh(trace_id)
- except TypeError as e:
- print("Can't process trace {}: {}".format(trace_id, e))
- continue
- if access_data['path'] != "/app/v1/user/ping": # 過濾臟數據
- continue
- if 'request_time' not in ingress_data:
- continue
- def get_int_num(data): # 數據統一做 *10 處理
- return int(float(data) * 10)
- # 針對每個區間段進行數據統計，可能有點羅嗦和重復，我當時做統計夠用了
- ingress_req_time = get_int_num(ingress_data['request_time'])
- ingress_upstream_time = get_int_num(ingress_data['upstream_response_time'])
- for cal in ingress_cal_map:
- if ingress_req_time >= cal[0][0] and ingress_req_time < cal[0][1]:
- cal[1] += 1
- break
- nginx_req_time = get_int_num(access_data['request_time'])
- for cal in nginx_cal_map:
- if nginx_req_time >= cal[0][0] and nginx_req_time < cal[0][1]:
- cal[1] += 1
- break
- gap = nginx_req_time - ingress_req_time
- for cal in nginx_ingress_gap:
- if gap >= cal[0][0] and gap <= cal[0][1]:
- cal[1] += 1
- break
- gap = ingress_req_time - ingress_upstream_time
- for cal in ingress_upstream_gap:
- if gap >= cal[0][0] and gap <= cal[0][1]:
- cal[1] += 1
- break
我分別針對 request_time(Nginx)，request_time(Ingress)以及 requet_time(nginx) - request_time(Ingress)做了統計。
最后的統計結果大概如下：
結果分析
我們總共有約 3000 條數據!
圖一：超過半數的請求落在 1 ~ 1.1s 區間，1s ~ 2s 的請求比較均勻，之后越來越少了。
圖二：大約 1/4 的請求其實已經在 0.1s 內返回了，但是 1 ~ 1.1s 也有 1/4 的請求落上去了，隨后的結果與圖一類似。
從圖 1 圖 2 結合來看，部分請求在 Ingress 側處理的時間其實比較短的。
圖三：比較明顯了，2/3 的請求在響應時間方面能夠保持一致，1/3 的請求會有 1s 左右的延遲。
小結
從統計結果來看，Nginx => Ingress 以及 Ingress => upstream，都存在不同程度的延遲，超過 1s 的應用，大約有 2/3 的延遲來自 Ingress => upstream，1/3 的延遲來自 Nginx => Ingress。
再深入調查 - 抓包處理
抓包調查主要針對 Ingress => uwsgi，由于數據包延遲的情況只是偶發性現象，所以需要抓取所有的數據包再進行過濾……這是一條請求時間較長的數據，本身這個接口返回應該很快。
- {
- "_source": {
- "INDEX": "51",
- "path": "/app/v1/media/",
- "referer": "",
- "user_agent": "okhttp/4.8.1",
- "upstream_connect_time": "1.288",
- "upstream_response_time": "1.400",
- "TIMESTAMP": "1605776490465",
- "request": "POST /app/v1/media/ HTTP/1.0",
- "status": "200",
- "proxy_upstream_name": "default-prod-XXX-80",
- "response_size": "68",
- "client_ip": "XXXXX",
- "upstream_addr": "172.32.18.194:6000",
- "request_size": "1661",
- "@source": "XXXX",
- "domain": "XXX",
- "upstream_status": "200",
- "@version": "1",
- "request_time": "1.403",
- "protocol": "HTTP/1.0",
- "tags": ["_dateparsefailure"],
- "@timestamp": "2020-11-19T09:01:29.000Z",
- "request_method": "POST",
- "trace_id": "87bad3cf9d184df0:87bad3cf9d184df0:0:1"
- }
- }
Ingress 側數據包
uwsgi 側數據包
數據包流轉情況
回顧一下 TCP 三次握手：
首先從 Ingress 側查看，連接在 21.585446 開始，22.588023 時，進行了數據包重新發送的操作。
從 Node 側查看，Node 在 Ingress 數據包發出后不久馬上就收到了 syn，也立刻進行了 syn 的返回，但是不知為何 1s 后才出現在 Ingress 處。
有一點比較令人在意，即便是數據包發生了重傳，但是也沒有出現丟包的問題，從兩臺機器數據包的流轉來看，此次請求中，大部分的時間是因為數據包的延遲到達造成的，重傳只是表面現象，真正的問題是發生了數據包的延遲。
不止是 ACK 數據包發生了延遲
從隨機抓包的情況來看，不止是 SYN ACK 發生了重傳：
有些 FIN ACK 也會，數據包的延遲是有概率的行為!
小結
單單看這個抓包可能只能確認是發生了丟包，但是如果結合 Ingress 與 Nginx 的日志請求來看，如果丟包發生在 TCP 連接階段，那么在 Ingress 中，我們就可以查看 upstream_connect_time 這個值來大致估計下超時情況。當時是這么整理的記錄：
我初步猜測這部分時間主要消耗在了 TCP 連接建立時，因為建立連接的操作在兩次 Nginx 轉發時都存在，而我們的鏈路全部使用了短連接，下一步我準備增加 $upstream_connect_time 變量，記錄建立連接花費的時間。http://nginx.org/en/docs/http/ ... .html
后續工作
既然可以了解到 TCP 連接的建立時間比較久，我們可以用它來作為一個衡量指標，我把 wrk 也修改了下，增加了對于連接時間的測量，具體的PR見這里，我們可以利用這一項指標衡量后端的服務情況。
尋找大佬，看看是否遇到類似問題
上面的工作前前后后我進行了幾次，也沒有什么頭緒，遂找到公司的其他 Kubernetes 大佬咨詢問題，大佬提供了一個思路：
宿主機延遲也高的話，那就暫時排除宿主機到容器這條路徑。我們這邊此前排查過一個延遲問題， 是由于 Kubernetes 的監控工具定期 cat proc 系統下的 cgroup 統計信息， 但由于 Docker 頻繁銷毀重建以及內核 cache 機制，使得每次 cat 時間很長占用內核導致網絡延遲， 可否排查一下你們的宿主機是否有類似情形? 不一定是 cgroup，其他需要頻繁陷入到內核的操作都可能導致延遲很高。
這個跟我們排查的 cgroup 太像了，宿主機上有一些周期性任務，隨著執行次數增多，占用的內核資源越來越多，達到一定程度就影響了網絡延遲。
大佬們也提供了一個內核檢查工具(可以追蹤和定位中斷或者軟中斷關閉的時間)：https://github.com/bytedance/trace-irqoff
有問題的 Ingress 機器的 latency 特別多，好多都是這樣的報錯，其他機器沒有這個日志：
而后，我針對機器中的 kubelet 進行了一次追蹤，從火焰圖中可以確認，大量的時間耗費在了讀取內核信息中。
其中具體的代碼如下：
小結
根據大佬所給的方向，基本能夠確定問題發生的真正原因：機器上定時任務的執行過多，內核緩存一直增加，導致內核速度變慢了。它一變慢，引發了 TCP 握手時間變長，最后造成用戶體驗下降。既然發現了問題，解決方案也比較容易搜索到了，增加任務，檢查內核是否變慢，慢了的話就清理一次：
sync && echo 3 > /proc/sys/vm/drop_caches
總結
這次的排查過程是由于應用層出現了影響用戶體驗的問題后，進一步延伸到了網絡層，其中經歷了漫長的抓包過程，也增加了自己的腳本用于指標衡量，隨后又通過內核工具定位到了具體應用，最后再根據應用的 pprof 工具制作出的火焰圖定位到了更加精確的異常位置，期間自己一個人沒法處理問題，遂請其他大佬來幫忙，大佬們見多識廣，可以給出一些可能性的猜想，還是很有幫助的。
當你發現某臺機器無論做什么都慢，而 CPU 和內核卻不是瓶頸的時候，那有可能是內核慢了。
希望本文能對大家未來排查集群問題時有所幫助。
