記一次 Kubernetes 節(jié)點(diǎn)內(nèi)核問題排查
此次排查發(fā)生在 2020-11 月份, 一直沒時(shí)間寫博客描述事情經(jīng)過, 本次正好一起寫了吧.
1具體現(xiàn)象
在線上環(huán)境中的某個(gè)應(yīng)用出現(xiàn)了接口緩慢的問題!!
就憑這個(gè)現(xiàn)象, 能列出來的原因數(shù)不勝數(shù). 本篇博客主要敘述一下幾次排查以及最后如何確定原因的過程, 可能不一定適用于其他集群, 就當(dāng)是提供一個(gè)參考吧. 排查過程比較冗長(zhǎng), 過去太久了, 我也不太可能回憶出所有細(xì)節(jié), 希望大家見諒.
2網(wǎng)絡(luò)拓?fù)浣Y(jié)構(gòu)
網(wǎng)絡(luò)請(qǐng)求流入集群時(shí), 對(duì)于我們集群的結(jié)構(gòu):
用戶請(qǐng)求=>Nginx=>Ingress =>uwsgi
不要問為什么有了 Ingress 還有 Nginx. 這是歷史原因, 有些工作暫時(shí)需要由 Nginx 承擔(dān).
3初次定位
請(qǐng)求變慢一般馬上就會(huì)考慮, 程序是不是變慢了, 所以在發(fā)現(xiàn)問題后, 首先在 uwsgi 中增加 簡(jiǎn)單的小接口, 這個(gè)接口是處理快并且馬上返回?cái)?shù)據(jù), 然后定時(shí)請(qǐng)求該接口. 在運(yùn)行幾天之后, 確認(rèn)到該接口的訪問速度也很慢, 排除程序中的問題, 準(zhǔn)備在鏈路中查找原因.
4再次定位 – 簡(jiǎn)單的全鏈路數(shù)據(jù)統(tǒng)計(jì)
由于我們的 Nginx 有 2 層, 需要針對(duì)它們分別確認(rèn), 看看究竟是哪一層慢了. 請(qǐng)求量是比較大的, 如果針對(duì)每個(gè)請(qǐng)求去查看, 效率不高, 而且有可能掩蓋真正原因, 所以這個(gè)過程采用統(tǒng)計(jì)的方式. 統(tǒng)計(jì)的方式是分別查看兩層 Nginx 的日志情況. 由于我們已經(jīng)在 elk 上接入了日志. elk 中篩選數(shù)據(jù)的腳本簡(jiǎn)單如下:
{
"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"
}
}
}
]
}
}
數(shù)據(jù)處理方案
根據(jù) trace_id 可以獲取到 Nignx 日志以及 Ingress 日志, 通過 elk 的 api 獲得.
# 這個(gè)數(shù)據(jù)結(jié)構(gòu)用來記錄統(tǒng)計(jì)結(jié)果,
# [[0, 0.1], 3]表示 落在 0~0.1區(qū)間的有3條記錄
# 因?yàn)樾?shù)的比較和區(qū)間比較麻煩, 所以采用整數(shù), 這里的0~35其實(shí)是0~3.5s區(qū)間
# 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是提前查找過, 那些響應(yīng)時(shí)間比較久的請(qǐng)求所對(duì)應(yīng)的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:
# 繼續(xù)嘗試一次
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": # 過濾臟數(shù)據(jù)
continue
if 'request_time' not in ingress_data:
continue
def get_int_num(data): # 數(shù)據(jù)統(tǒng)一做*10處理
return int(float(data) * 10)
# 針對(duì)每個(gè)區(qū)間段進(jìn)行數(shù)據(jù)統(tǒng)計(jì), 可能有點(diǎn)羅嗦和重復(fù), 我當(dāng)時(shí)做統(tǒng)計(jì)夠用了
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
我分別針對(duì)request_time(nginx), request_time(ingress), 以及requet_time(nginx) - request_time(ingress),做了統(tǒng)計(jì).
最后的統(tǒng)計(jì)結(jié)果大概如下:
結(jié)果分析
我們總共有約 3000 條數(shù)據(jù)!
圖一: 超過半數(shù)的請(qǐng)求落在 11.1s 區(qū)間, 1s2s 的請(qǐng)求比較均勻, 之后越來越少了.
圖二: 大約 1/4 的請(qǐng)求其實(shí)已經(jīng)在 0.1s 內(nèi)返回了, 但是 1~1.1s 也有 1/4 的請(qǐng)求落上去了, 隨后的結(jié)果與圖一類似.
從圖 1 圖 2 結(jié)合來看, 部分請(qǐng)求在 Ingress 側(cè)處理的時(shí)間其實(shí)比較短的,
圖三: 比較明顯了, 2/3 的請(qǐng)求在響應(yīng)時(shí)間方面能夠保持一致, 1/3 的請(qǐng)求會(huì)有 1s 左右的延遲.
總結(jié)
從統(tǒng)計(jì)結(jié)果來看, Nginx => Ingress 以及 Ingress => upstream, 都存在不同程度的延遲, 超過 1s 的應(yīng)用, 大約有 2/3 的延遲來自 Ingress=>upstream, 1/3 的延遲來自 Nginx=>Ingress.
5再深入調(diào)查 - 抓包處理
抓包調(diào)查主要針對(duì)Ingress=>uwsgi, 由于數(shù)據(jù)包延遲的情況只是偶發(fā)性現(xiàn)象, 所以需要抓取所有的數(shù)據(jù)包再進(jìn)行過濾… 這是一條請(qǐng)求時(shí)間較長(zhǎng)的數(shù)據(jù), 本身這個(gè)接口返回應(yīng)該很快.
{
"_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側(cè)數(shù)據(jù)包
uwsgi側(cè)數(shù)據(jù)包
數(shù)據(jù)包流轉(zhuǎn)情況
回顧一下TCP三次握手:
首先從Ingress側(cè)查看, 連接在 21.585446開始,22.588023時(shí), 進(jìn)行了數(shù)據(jù)包重新發(fā)送的操作.從Node側(cè)查看, node在ingress數(shù)據(jù)包發(fā)出后不久馬上就收到了syn, 也立刻進(jìn)行了syn的返回, 但是不知為何1s后才出現(xiàn)在ingress處.
有一點(diǎn)比較令人在意, 即便是數(shù)據(jù)包發(fā)生了重傳, 但是也沒有出現(xiàn)丟包的問題, 從兩臺(tái)機(jī)器數(shù)據(jù)包的流轉(zhuǎn)來看, 此次請(qǐng)求中, 大部分的時(shí)間是因?yàn)閿?shù)據(jù)包的延遲到達(dá)造成的, 重傳只是表面現(xiàn)象, 真正的問題是發(fā)生了數(shù)據(jù)包的延遲.
不止是ack數(shù)據(jù)包發(fā)生了延遲
從隨機(jī)抓包的情況來看, 不止是SYN ACK發(fā)生了重傳:
有些FIN ACK也會(huì), 數(shù)據(jù)包的延遲是有概率的行為!!!
總結(jié)
單單看這個(gè)抓包可能只能確認(rèn)是發(fā)生了丟包, 但是如果結(jié)合Ingress與Nginx的日志請(qǐng)求來看, 如果丟包發(fā)生在tcp連接階段, 那么在Ingress中, 我們就可以查看upstream_connect_time 這個(gè)值來大致估計(jì)下超時(shí)情況. 當(dāng)時(shí)是這么整理的記錄:
我初步猜測(cè)這部分時(shí)間主要消耗在了 TCP 連接建立時(shí), 因?yàn)榻⑦B接的操作在兩次 Nginx 轉(zhuǎn)發(fā)時(shí)都存在, 而我們的鏈路全部使用了短連接, 下一步我準(zhǔn)備增加
$upstream_connect_time變量, 記錄建立連接花費(fèi)的時(shí)間. http://nginx.org/en/docs/http/ngx_http_upstream_module.html
后續(xù)工作
既然可以了解到tcp連接的建立時(shí)間比較久, 我們可以用它來作為一個(gè)衡量指標(biāo), 我把wrk也修改了下, 增加了對(duì)于連接時(shí)間的測(cè)量, 具體的PR見這里(https://github.com/wg/wrk/pull/447), 我們可以利用這一項(xiàng)指標(biāo)衡量后端的服務(wù)情況.
6尋找大佬, 看看是否遇到類似問題
上面的工作前前后后我進(jìn)行了幾次, 也沒有什么頭緒, 遂找到公司的其他K8S大佬咨詢問題, 大佬提供了一個(gè)思路:
宿主機(jī)延遲也高的話，那就暫時(shí)排除宿主機(jī)到容器這條路徑。我們這邊此前排查過一個(gè)延遲問題， 是由于 k8s 的監(jiān)控工具定期 cat proc 系統(tǒng)下的 cgroup 統(tǒng)計(jì)信息， 但由于 docker 頻繁銷毀重建以及內(nèi)核 cache 機(jī)制，使得每次 cat 時(shí)間很長(zhǎng)占用內(nèi)核導(dǎo)致網(wǎng)絡(luò)延遲， 可否排查一下你們的宿主機(jī)是否有類似情形？不一定是 cgroup，其他需要頻繁陷入到內(nèi)核的操作都可能導(dǎo)致延遲很高
這個(gè)跟我們排查的 cgroup 太像了，宿主機(jī)上有一些周期性任務(wù)，隨著執(zhí)行次數(shù)增多，占用的內(nèi)核資源越來越多，達(dá)到一定程度就影響了網(wǎng)絡(luò)延遲
大佬們也提供了一個(gè)內(nèi)核檢查工具(可以追蹤和定位中斷或者軟中斷關(guān)閉的時(shí)間):
https://github.com/bytedance/trace-irqoff
有問題的ingress機(jī)器 的latency特別多，好多都是這樣的報(bào)錯(cuò)， 其他機(jī)器沒有這個(gè)日志:
而后, 我針對(duì)機(jī)器中的kubelet進(jìn)行了一次追蹤, 從火焰圖中可以確認(rèn), 大量的時(shí)間耗費(fèi)在了讀取內(nèi)核信息中.
其中具體的代碼如下:
總結(jié)
根據(jù)大佬所給的方向, 基本能夠確定問題發(fā)生的真正原因: 機(jī)器上定時(shí)任務(wù)的執(zhí)行過多, 內(nèi)核緩存一直增加, 導(dǎo)致內(nèi)核速度變慢了. 它一變慢, 引發(fā)了tcp握手時(shí)間變長(zhǎng), 最后造成用戶體驗(yàn)下降. 既然發(fā)現(xiàn)了問題, 解決方案也比較容易搜索到了, 增加任務(wù), 檢查內(nèi)核是否變慢, 慢了的話就清理一次:
sync && echo 3 > /proc/sys/vm/drop_caches
7總結(jié)
這次的排查過程是由于應(yīng)用層出現(xiàn)了影響用戶體驗(yàn)的問題后, 進(jìn)一步延伸到了網(wǎng)絡(luò)層, 其中經(jīng)歷了漫長(zhǎng)的抓包過程, 也增加了自己的腳本用于指標(biāo)衡量, 隨后又通過內(nèi)核工具定位到了具體應(yīng)用, 最后再根據(jù)應(yīng)用的pprof工具制作出的火焰圖定位到了更加精確的異常位置, 期間自己一個(gè)人沒法處理問題, 遂請(qǐng)其他大佬來幫忙, 大佬們見多識(shí)廣, 可以給出一些可能性的猜想, 還是很有幫助的.
當(dāng)你發(fā)現(xiàn)某臺(tái)機(jī)器無論做什么都慢, 而cpu和內(nèi)核卻不是瓶頸的時(shí)候, 那有可能是內(nèi)核慢了.
希望本文能對(duì)大家未來排查集群?jiǎn)栴}時(shí)有所幫助.
原文鏈接：https://corvo.myseu.cn/2021/03/21/2021-03-21-%E8%AE%B0%E4%B8%80%E6%AC%A1kubernetes%E6%9C%BA%E5%99%A8%E5%86%85%E6%A0%B8%E9%97%AE%E9%A2%98%E7%9A%84%E6%8E%92%E6%9F%A5/