1 具體現(xiàn)象

在線上環(huán)境中的某個應用出現(xiàn)了接口緩慢的問題!!

就憑這個現(xiàn)象, 能列出來的原因數(shù)不勝數(shù). 本篇博客主要敘述一下幾次排查以及最后如何確定原因的過程, 可能不一定適用于其他集群, 就當是提供一個參考吧. 排查過程比較冗長, 過去太久了, 我也不太可能回憶出所有細節(jié), 希望大家見諒.

2 網絡拓撲結構

網絡請求流入集群時, 對于我們集群的結構:

用戶請求=>Nginx=>Ingress =>uwsgi 

不要問為什么有了 Ingress 還有 Nginx. 這是歷史原因, 有些工作暫時需要由 Nginx 承擔.

3 初次定位

請求變慢一般馬上就會考慮, 程序是不是變慢了, 所以在發(fā)現(xiàn)問題后, 首先在 uwsgi 中增加 簡單的小接口, 這個接口是處理快并且馬上返回數(shù)據, 然后定時請求該接口. 在運行幾天之后, 確認到該接口的訪問速度也很慢, 排除程序中的問題, 準備在鏈路中查找原因.

4 再次定位 – 簡單的全鏈路數(shù)據統(tǒng)計

由于我們的 Nginx 有 2 層, 需要針對它們分別確認, 看看究竟是哪一層慢了. 請求量是比較大的, 如果針對每個請求去查看, 效率不高, 而且有可能掩蓋真正原因, 所以這個過程采用統(tǒng)計的方式. 統(tǒng)計的方式是分別查看兩層 Nginx 的日志情況. 由于我們已經在 elk 上接入了日志. elk 中篩選數(shù)據的腳本簡單如下:

{ 
  "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ù)據處理方案

根據 trace_id 可以獲取到 Nignx 日志以及 Ingress 日志, 通過 elk 的 api 獲得.

# 這個數(shù)據結構用來記錄統(tǒng)計結果, 
# [[0, 0.1], 3]表示 落在 0~0.1區(qū)間的有3條記錄 
# 因為小數(shù)的比較和區(qū)間比較麻煩, 所以采用整數(shù), 這里的0~35其實是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是提前查找過, 那些響應時間比較久的請求所對應的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ù)據 
            continue 
        if 'request_time' not in ingress_data: 
            continue 
 
        def get_int_num(data):  # 數(shù)據統(tǒng)一做*10處理 
            return int(float(data) * 10) 
 
        # 針對每個區(qū)間段進行數(shù)據統(tǒng)計, 可能有點羅嗦和重復, 我當時做統(tǒng)計夠用了 
        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) ,做了統(tǒng)計.

最后的統(tǒng)計結果大概如下: 

結果分析

我們總共有約 3000 條數(shù)據!

• 圖一: 超過半數(shù)的請求落在 1 1.1s 區(qū)間, 1s 2s 的請求比較均勻, 之后越來越少了.
• 圖二: 大約 1/4 的請求其實已經在 0.1s 內返回了, 但是 1~1.1s 也有 1/4 的請求落上去了, 隨后的結果與圖一類似.

從圖 1 圖 2 結合來看, 部分請求在 Ingress 側處理的時間其實比較短的,

• 圖三: 比較明顯了, 2/3 的請求在響應時間方面能夠保持一致, 1/3 的請求會有 1s 左右的延遲.

總結

從統(tǒng)計結果來看, Nginx => Ingress 以及 Ingress => upstream, 都存在不同程度的延遲, 超過 1s 的應用, 大約有 2/3 的延遲來自 Ingress=>upstream, 1/3 的延遲來自 Nginx=>Ingress.

5 再深入調查 - 抓包處理

抓包調查主要針對 Ingress=>uwsgi , 由于數(shù)據包延遲的情況只是偶發(fā)性現(xiàn)象, 所以需要抓取所有的數(shù)據包再進行過濾… 這是一條請求時間較長的數(shù)據, 本身這個接口返回應該很快.

{ 
  "_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側數(shù)據包

uwsgi側數(shù)據包

數(shù)據包流轉情況

回顧一下TCP三次握手:

首先從Ingress側查看, 連接在21.585446開始, 22.588023時, 進行了數(shù)據包重新發(fā)送的操作。

從Node側查看, node在ingress數(shù)據包發(fā)出后不久馬上就收到了syn, 也立刻進行了syn的返回, 但是不知為何1s后才出現(xiàn)在ingress處。 

有一點比較令人在意, 即便是數(shù)據包發(fā)生了重傳, 但是也沒有出現(xiàn)丟包的問題, 從兩臺機器數(shù)據包的流轉來看, 此次請求中, 大部分的時間是因為數(shù)據包的延遲到達造成的, 重傳只是表面現(xiàn)象, 真正的問題是發(fā)生了數(shù)據包的延遲.

不止是ack數(shù)據包發(fā)生了延遲

從隨機抓包的情況來看, 不止是 SYN ACK 發(fā)生了重傳:

有些 FIN ACK 也會, 數(shù)據包的延遲是有概率的行為!!!

總結

單單看這個抓包可能只能確認是發(fā)生了丟包, 但是如果結合Ingress與Nginx的日志請求來看, 如果丟包發(fā)生在tcp連接階段, 那么在Ingress中, 我們就可以查看 upstream_connect_time 這個值來大致估計下超時情況. 當時是這么整理的記錄:

我初步猜測這部分時間主要消耗在了 TCP 連接建立時, 因為建立連接的操作在兩次 Nginx 轉發(fā)時都存在, 而我們的鏈路全部使用了短連接, 下一步我準備增加 $upstream_connect_time 變量, 記錄建立連接花費的時間. http://nginx.org/en/docs/http/ngx_http_upstream_module.html

后續(xù)工作

既然可以了解到tcp連接的建立時間比較久, 我們可以用它來作為一個衡量指標, 我把wrk也修改了下, 增加了對于連接時間的測量, 具體的PR見這里(https://github.com/wg/wrk/pull/447), 我們可以利用這一項指標衡量后端的服務情況.

6 尋找大佬, 看看是否遇到類似問題

上面的工作前前后后我進行了幾次, 也沒有什么頭緒, 遂找到公司的其他K8S大佬咨詢問題, 大佬提供了一個思路:

宿主機延遲也高的話，那就暫時排除宿主機到容器這條路徑。我們這邊此前排查過一個延遲問題， 是由于 k8s 的監(jiān)控工具定期 cat proc 系統(tǒng)下的 cgroup 統(tǒng)計信息， 但由于 docker 頻繁銷毀重建以及內核 cache 機制，使得每次 cat 時間很長占用內核導致網絡延遲， 可否排查一下你們的宿主機是否有類似情形?不一定是 cgroup，其他需要頻繁陷入到內核的操作都可能導致延遲很高

這個跟我們排查的 cgroup 太像了，宿主機上有一些周期性任務，隨著執(zhí)行次數(shù)增多，占用的內核資源越來越多，達到一定程度就影響了網絡延遲

大佬們也提供了一個內核檢查工具(可以追蹤和定位中斷或者軟中斷關閉的時間):

https://github.com/bytedance/trace-irqoff

有問題的ingress機器 的latency特別多，好多都是這樣的報錯， 其他機器沒有這個日志: 

而后, 我針對機器中的kubelet進行了一次追蹤, 從火焰圖中可以確認, 大量的時間耗費在了讀取內核信息中。

其中具體的代碼如下:

總結

根據大佬所給的方向, 基本能夠確定問題發(fā)生的真正原因: 機器上定時任務的執(zhí)行過多, 內核緩存一直增加, 導致內核速度變慢了. 它一變慢, 引發(fā)了tcp握手時間變長, 最后造成用戶體驗下降. 既然發(fā)現(xiàn)了問題, 解決方案也比較容易搜索到了, 增加任務, 檢查內核是否變慢, 慢了的話就清理一次:

sync && echo 3 > /proc/sys/vm/drop_caches 

7 總結

這次的排查過程是由于應用層出現(xiàn)了影響用戶體驗的問題后, 進一步延伸到了網絡層, 其中經歷了漫長的抓包過程, 也增加了自己的腳本用于指標衡量, 隨后又通過內核工具定位到了具體應用, 最后再根據應用的 pprof 工具制作出的火焰圖定位到了更加精確的異常位置, 期間自己一個人沒法處理問題, 遂請其他大佬來幫忙, 大佬們見多識廣, 可以給出一些可能性的猜想, 還是很有幫助的.

當你發(fā)現(xiàn)某臺機器無論做什么都慢, 而cpu和內核卻不是瓶頸的時候, 那有可能是內核慢了.

希望本文能對大家未來排查集群問題時有所幫助.

本文轉載自：「k8s技術圈」，原文：https://tinyurl.com/y5wx3m5x，版權歸原作者所有。