kubelet CPU 使用率過高問題排查
kubelet CPU 使用率過高問題排查
問題背景
客戶的k8s叢集環境，發現所有的worker節點的kubelet程序的CPU使用率長時間佔用過高，通過pidstat可以看到CPU使用率高達100%。針對此問題對kubelet程序的異常進行問題排查。
叢集環境
| 軟體 | 版本 |
|---|---|
| kubernetes | v1.18.8 |
| docker | 18.09.9 |
| rancher | v2.4.8-ent |
| CentOS | 7.6 |
| kernel | 4.4.227-1.el7.elrepo.x86_64 |
排查過程
使用strace工具對kubelet程序進行跟蹤
- 由於kubelet程序CPU使用率異常，可以使用strace工具對kubelet程序動態跟蹤程序的呼叫情況，首先使用
strace -cp <PID>命令統計kubelet程序在某段時間內的每個系統呼叫的時間、呼叫和錯誤情況.
從上圖可以看到，執行系統呼叫過程中，futex丟擲了五千多個errors，這肯定是不正常的，而且這個函式佔用的時間也達到了99%，所以需要更深層次的檢視kubelet程序相關的呼叫。
- 由於
strace -cp命令只能檢視程序的整體呼叫情況，所以我們可以通過strace -tt -p <PID>命令列印每個系統呼叫的時間戳，如下：
從strace輸出的結果來看，在執行futex相關的系統呼叫時，有大量的Connect timed out，並返回了-1 和ETIMEDOUT的error，所以才會在strace -cp
futex是一種使用者態和核心態混合的同步機制，當futex變數告訴程序有競爭發生時，會執行系統呼叫去完成相應的處理，例如wait或者wake up，從官方的文件瞭解到，futex有這麼幾個引數：
futex(uint32_t *uaddr, int futex_op, uint32_t val,
const struct timespec *timeout, /* or: uint32_t val2 */
uint32_t *uaddr2, uint32_t val3);
官方文件給出ETIMEDOUT
ETIMEDOUT
The operation in futex_op employed the timeout specified in
timeout, and the timeout expired before the operation
completed.
意思就是在指定的timeout時間中，未能完成相應的操作，其中futex_op對應上述輸出結果的FUTEX_WAIT_PRIVATE和FUTEX_WAIT_PRIVATE，可以看到基本都是發生在FUTEX_WAIT_PRIVATE時發生的超時。
從目前的系統呼叫層面可以判斷，futex無法順利進入睡眠狀態，但是futex做了哪些操作還是不清楚，還無法判斷kubeletCPU飆高的原因，所以我們需要進一步從kubelet的函式呼叫中去看到底是執行了卡在了哪個地方。
FUTEX_PRIVATE_FLAG：這個引數告訴核心futex是程序專用的，不與其他程序共享，這裡的FUTEX_WAIT_PRIVATE和FUTEX_WAKE_PRIVATE就是其中的兩種FLAG；
futex相關說明1：https://man7.org/linux/man-pages/man7/futex.7.html
fuex相關說明2： https://man7.org/linux/man-pages/man2/futex.2.html
使用go pprof工具對kubelet函式呼叫進行分析
早期的k8s版本，可以直接通過debug/pprof 介面獲取debug資料，後面考慮到相關安全性的問題，取消了這個介面，參考CVE-2019-11248，我們可以通過kubectl開啟proxy進行相關資料指標的獲取
- 首先使用
kubectl proxy命令啟動API server代理
kubectl proxy --address='0.0.0.0' --accept-hosts='^*$'
這裡需要注意，如果使用的是Rancher UI上copy的kubeconfig檔案，則需要使用指定了master IP的context，如果是RKE或者其他工具安裝則可以忽略
- 構建golang環境。go pprof需要在golang環境下使用，本地如果沒有安裝golang，則可以通過docker快速構建golang環境
docker run -itd --name golang-env --net host golang bash
- 使用go pprof工具匯出採集的指標，這裡替換127.0.0.1為apiserver節點的IP，預設埠是8001，如果docker run的環境跑在apiserver所在的節點上，可以使用127.0.0.1。另外，還要替換NODENAME為對應的節點名稱。
docker exec -it golang-env bash
go tool pprof -seconds=60 -raw -output=kubelet.pprof http://127.0.0.1:8001/api/v1/nodes/${NODENAME}/proxy/debug/pprof/profile
這裡等待60s後，會將這60s內相關的函式呼叫輸出到當前目錄的kubelet.pprof檔案中。
- 輸出好的pprof檔案不方便檢視，需要轉換成火焰圖，推薦使用FlameGraph工具生成svg圖
git clone https://github.com/brendangregg/FlameGraph.git
cd FlameGraph/
./stackcollapse-go.pl kubelet.pprof > kubelet.out
./flamegraph.pl kubelet.out > kubelet.svg
轉換成火焰圖後，就可以在瀏覽器很直觀的看到函式相關呼叫和具體呼叫時間比了。
- 分析火焰圖
從kubelet的火焰圖可以看到，呼叫時間最長的函式是k8s.io/kubernetes/vendor/github.com/google/cadvisor/manager.(*containerData).housekeeping，其中cAdvisor是kubelet內建的指標採集工具，主要是負責對節點機器上的資源及容器進行實時監控和效能資料採集，包括CPU使用情況、記憶體使用情況、網路吞吐量及檔案系統使用情況。
深入函式呼叫可以發現k8s.io/kubernetes/vendor/github.com/opencontainers/runc/libcontainer/cgroups/fs.(*Manager).GetStats這個函式佔用k8s.io/kubernetes/vendor/github.com/google/cadvisor/manager.(*containerData).housekeeping這個函式的時間是最長的，說明在獲取容器CGroup相關狀態時佔用了較多的時間。
- 既然這個函式佔用時間長，那麼我們就分析一下這個函式具體幹了什麼事兒
func (s *MemoryGroup) GetStats(path string, stats *cgroups.Stats) error {
// Set stats from memory.stat.
statsFile, err := os.Open(filepath.Join(path, "memory.stat"))
if err != nil {
if os.IsNotExist(err) {
return nil
}
return err
}
defer statsFile.Close()
sc := bufio.NewScanner(statsFile)
for sc.Scan() {
t, v, err := fscommon.GetCgroupParamKeyValue(sc.Text())
if err != nil {
return fmt.Errorf("failed to parse memory.stat (%q) - %v", sc.Text(), err)
}
stats.MemoryStats.Stats[t] = v
}
stats.MemoryStats.Cache = stats.MemoryStats.Stats["cache"]
memoryUsage, err := getMemoryData(path, "")
if err != nil {
return err
}
stats.MemoryStats.Usage = memoryUsage
swapUsage, err := getMemoryData(path, "memsw")
if err != nil {
return err
}
stats.MemoryStats.SwapUsage = swapUsage
kernelUsage, err := getMemoryData(path, "kmem")
if err != nil {
return err
}
stats.MemoryStats.KernelUsage = kernelUsage
kernelTCPUsage, err := getMemoryData(path, "kmem.tcp")
if err != nil {
return err
}
stats.MemoryStats.KernelTCPUsage = kernelTCPUsage
useHierarchy := strings.Join([]string{"memory", "use_hierarchy"}, ".")
value, err := fscommon.GetCgroupParamUint(path, useHierarchy)
if err != nil {
return err
}
if value == 1 {
stats.MemoryStats.UseHierarchy = true
}
pagesByNUMA, err := getPageUsageByNUMA(path)
if err != nil {
return err
}
stats.MemoryStats.PageUsageByNUMA = pagesByNUMA
return nil
}
從程式碼中可以看到，程序會去讀取memory.stat這個檔案，這個檔案存放了cgroup記憶體使用情況。也就是說，在讀取這個檔案花費了大量的時間。這時候，如果我們手動去檢視這個檔案，會是什麼效果？
# time cat /sys/fs/cgroup/memory/memory.stat >/dev/null
real 0m9.065s
user 0m0.000s
sys 0m9.064s
從這裡可以看出端倪了，讀取這個檔案花費了9s，顯然是不正常的，難怪kubeletCPU使用飆高，原來是堵在這裡了。
基於上述結果，我們在cAdvisor的GitHub上查詢到一個issue，從該issue中可以得知，該問題跟slab memory 快取有一定的關係。從該issue中得知，受影響的機器的記憶體會逐漸被使用，通過/proc/meminfo看到使用的記憶體是slab memory，該記憶體是核心快取的記憶體頁，並且其中絕大部分都是dentry快取。從這裡我們可以判斷出，當CGroup中的程序生命週期結束後，由於快取的原因，還存留在slab memory中，導致其類似殭屍CGroup一樣無法被釋放。
也就是每當建立一個memory CGroup，在核心記憶體空間中，就會為其建立分配一份記憶體空間，該記憶體包含當前CGroup相關的cache（dentry、inode），也就是目錄和檔案索引的快取，該快取本質上是為了提高讀取的效率。但是當CGroup中的所有程序都退出時，存在核心記憶體空間的快取並沒有清理掉。
核心通過夥伴演算法進行記憶體分配，每當有程序申請記憶體空間時，會為其分配至少一個記憶體頁面，也就是最少會分配4k記憶體，每次釋放記憶體，也是按照最少一個頁面來進行釋放。當請求分配的記憶體大小為幾十個位元組或幾百個位元組時，4k對其來說是一個巨大的記憶體空間，在Linux中，為了解決這個問題，引入了slab記憶體分配管理機制，用來處理這種小量的記憶體請求，這就會導致，當CGroup中的所有程序都退出時，不會輕易回收這部分的記憶體，而這部分記憶體中的快取資料，還會被讀取到stats中，從而導致影響讀取的效能。
解決方法
- 清理節點快取，這是一個臨時的解決方法，暫時清空節點記憶體快取，能夠緩解kubelet CPU使用率，但是後面快取上來了，CPU使用率又會升上來。
echo 2 > /proc/sys/vm/drop_caches
-
升級核心版本
2.1. 其實這個主要還是核心的問題，在GitHub上這個commit中有提到，在5.2+以上的核心版本中，優化了CGroup stats相關的查詢效能，如果想要更好的解決該問題，建議可以參考自己作業系統和環境，合理的升級核心版本。
2.2. 另外Redhat在kernel-4.18.0-176版本中也優化了相關CGroup的效能問題，而CentOS 8/RHEL 8預設使用的核心版本就是4.18，如果目前您使用的作業系統是RHEL7/CentOS7，則可以嘗試逐漸替換新的作業系統，使用這個4.18.0-176版本以上的核心，畢竟新版本核心總歸是對容器相關的體驗會好很多。
kernel相關commit：https://github.com/torvalds/linux/commit/205b20cc5a99cdf197c32f4dbee2b09c699477f0
redhat kernel bug fix：https://bugzilla.redhat.com/show_bug.cgi?id=1795049