### 背景

- 目前 [機器學習平臺](http://ml.intra.xiaojukeji.com/axe#/) 後端採用k8s架構進行GPU和CPU資源的排程和容器編排。總所周知，k8s的後端核心儲存使用etcd進行metadata持久化儲存。機器學習平臺採取[External etcd topology](http://way.xiaojukeji.com/article/External etcd topology)結構進行etcd的HA部署。
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_g1dg8HUH5mxX8cEeDIV6)
- etcd叢集的穩定性直接關係到k8s叢集和[機器學習平臺](http://ml.intra.xiaojukeji.com/axe#/)的穩定性。odin平臺直接接入etcd叢集的慢日誌(etcd請求操作>100ms)告警，實時監控etcd的穩定性。
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_mNEssaSb1JFbym7JPbtd)

### 問題記錄

- 2020-01-06 運維同學反饋2019年12月中旬etcd慢日誌監控出現大量的告警記錄，而且告警呈上升趨勢。
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_uPX7dCnbIhJAk5s5iTyf)
- 2020-01-20 運維同學繼續反饋etcd慢日誌告警數量繼續上漲，未呈現穩態趨勢。
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_NBSuEbj62aZ8L6vAFnVw)

### 問題分析

- 2020-01-06 運維同學反饋告警問題時，當時懷疑etcd 叢集磁碟latency效能問題，透過etcd metrics介面dump backend_commit_duration_seconds 和 wal_fsync_duration_seconds，latency區間在128ms。etcd官方文件

what-does-the-etcd-warning-apply-entries-took-too-long-mean

建議排查磁碟效能問題，保證 "p99 duration should be less than 25ms"。和運維同學討論，先將etcd設定的慢日誌閾值調整到100，繼續跟蹤告警問題。

```shell
  root@xxx-ser00:~$ curl -L -s http://localhost:2379/metrics | grep backend_commit_duration_seconds
  # HELP etcd_disk_backend_commit_duration_seconds The latency distributions of commit called by backend.
  # TYPE etcd_disk_backend_commit_duration_seconds histogram
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.001"} 28164
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.002"} 357239
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.004"} 1.9119004e+07
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.008"} 2.07783083e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.016"} 3.02929134e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.032"} 3.0395167e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.064"} 3.04047027e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.128"} 3.04051485e+08 # 大部分disk_backend_commit_duration <= 128ms
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.256"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="0.512"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="1.024"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="2.048"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="4.096"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="8.192"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_bucket{le="+Inf"} 3.04051486e+08
  etcd_disk_backend_commit_duration_seconds_sum 2.193424564702583e+06
  etcd_disk_backend_commit_duration_seconds_count 3.04051486e+08
  root@xxx-ser00:~$ curl -L -s http://localhost:2379/metrics | grep wal_fsync_duration_seconds
  # HELP etcd_disk_wal_fsync_duration_seconds The latency distributions of fsync called by wal.
  # TYPE etcd_disk_wal_fsync_duration_seconds histogram
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.001"} 9.661794e+06
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.002"} 1.134905564e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.004"} 1.638654117e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.008"} 1.64588859e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.016"} 1.646517588e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.032"} 1.646521494e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.064"} 1.646521531e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.128"} 1.646521634e+09 # 大部分disk_wal_fsync_duration <= 128ms
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.256"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="0.512"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="1.024"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="2.048"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="4.096"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="8.192"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_bucket{le="+Inf"} 1.646521635e+09
  etcd_disk_wal_fsync_duration_seconds_sum 3.2505764775865404e+06
  etcd_disk_wal_fsync_duration_seconds_count 1.646521635e+09
  ```

- 2020-01-20 運維同學繼續反饋慢日誌告警，調整到100個告警閾值，慢日誌告警數量還是呈上升趨勢。檢視每臺etcd服務的監控，發現告警集中在某一臺etcd服務上，當etcd服務重啟時，告警會發生遷移；告警值會繼上一個etcd服務重啟後的數，繼續上漲。
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_CRMDRKGZsqadgnJiZ5nG)

- 登陸其中一臺慢日誌告警etcd伺服器，在/var/log/message 日誌中統計etcd 'took too long' 超過100ms的慢日誌，68%的range request，其中87%的job查詢。

```shell
  root@xxx-ser00:/var/log$ grep 'took too long' /var/log/messages | grep 'Jan 19' | wc -l
  176013
  root@xxx-ser00:/var/log$ grep 'took too long' /var/log/messages | grep 'Jan 19' | grep 'read-only range request' | wc -l
  120199
  root@xxx-ser00:/var/log$ echo 'ibase=10; obase=10; scale=2; 120199/176013' | bc
  .68
  root@xxx-ser00:/var/log$ grep 'took too long' /var/log/messages | grep 'Jan 19' | grep 'read-only range request' | grep '\/registry\/jobs' | wc -l
  104698
  root@xxx-ser00:/var/log$ echo 'ibase=10; obase=10; scale=2; 104698/120199' | bc
  .87
  ```

- 隨機抽取一條慢日誌，透過日誌，直接使用etcdctl 查詢，返回500條job資料。懷疑有服務透過kube-apiserver 進行大量的get job lists的請求。

```shell
  Jan 20 19:40:09 xxx-ser00 etcd: read-only range request "key:\"/registry/jobs/65-ns/k8s-job-tdc6eu-1576247407339\\000\" range_end:\"/registry/jobs0\" limit:500 revision:1712050719 " took too long (117.960324ms) to execute
  root@xxx-ser00:/home/xiaoju/etcd/bin$ cd /home/xiaoju/etcd/bin/
  root@xxx-ser00:/home/xiaoju/etcd/bin$ export ETCDCTL_API=3
  root@xxx-ser00:/home/xiaoju/etcd/bin$ ./etcdctl get /registry/jobs/65-ns/k8s-job-tdc6eu-1576247407339\\000 --limit=500 --keys-only /registry/jobs0 | sed '/^$/d' | wc -l
  500
  ```

- 在其中一臺apiserver和xxx-ser00伺服器上進行抓包

```shell
  root@kube-master-ser01:~$ tcpdump -v -i any -s 0 -w apiserver.pcap port 8080
  root@xxx-ser00:~$ tcpdump -v -i eth0 -s 0 -w etcd.pcap port 2379
  ```

- 將慢日誌中的job name k8s-job-tdc6eu-1576247407339 在etcd.pcap中查詢，看到源IP是xx.xx.128.58 kube-master-ser01，埠20994，就是kube-apiserver的發起的請求。

```shell
  root@kube-master-ser01:~$ netstat -antp | grep 20994
  tcp        0      0 xx.xx.128.58:20994      xx.xx.76.33:2379        ESTABLISHED 25969/kube-apiserve
  ```

- 將慢日誌中的job name k8s-job-tdc6eu-1576247407339 在apiserver.pcap中查詢，能查詢到job相關資訊，檢視wireshark http stream的上下文，發現kube-controller-manager中cronjob-controller呼叫了get jobs。解析url中的引數，發現和etcd中慢日誌告警類似，將apiserver.pcap中的url 另存為日誌。可以查詢到url請求，也是cronjob-controller呼叫了get jobs。

```shell
  root@kube-master-ser01:~$ echo eyJ2IjoibWV0YS5rOHMuaW8vdjEiLCJydiI6MTcxMjA1MDcxOSwic3RhcnQiOiI2NS1ucy9rOHMtam9iLXN2Z2Q5NC0xNTczNzQyNDAyNDMyXHUwMDAwIn0 | base64 -d
  {"v":"meta.k8s.io/v1","rv":1712050719,"start":"65-ns/k8s-job-svgd94-1573742402432\u0000"}base64: invalid input
  Jan 20 19:40:09 xxx-ser00 etcd: read-only range request "key:\"/registry/jobs/65-ns/k8s-job-tdc6eu-1576247407339\\000\" range_end:\"/registry/jobs0\" limit:500 revision:1712050719 " took too long (117.960324ms) to execute
  root@kube-master-ser01:~$ grep limit=500 apiserver.log | cut -d '=' -f2 | cut -d '&' -f1 | while read line; do echo $line | base64 -D | grep k8s-job-tdc6eu-1576247407339 && echo $line; done
  {"v":"meta.k8s.io/v1","rv":1712050719,"start":"65-ns/k8s-job-tdc6eu-1576247407339\u0000
  eyJ2IjoibWV0YS5rOHMuaW8vdjEiLCJydiI6MTcxMjA1MDcxOSwic3RhcnQiOiI2NS1ucy9rOHMtam9iLXRkYzZldS0xNTc2MjQ3NDA3MzM5XHUwMDAwIn0
  ```

- 檢視cronjob_controller的程式碼，發現不是使用的 JobInformer 而是透過clientset list了所有namespace下的job。當前

機器學習平臺

k8s叢集，全部namespace下的job,一次list 分頁查詢會返回慢日誌。

```shell
    root@kube-master-ser01:~$ time kubectl get jobs -A | wc -l
    xxxx
    real    2m1.287s
    user    0m32.263s
    sys 0m8.845s
  ```

### 解決方案

- 平臺job需要配置ttlSecondsAfterFinished，執行完成的job可以自動過期。防止大資料量的任務查詢，造成etcd庫查詢壓力。
- 平臺未使用cronjob，可以禁止cronjob_controller的功能。
- 之前k8s社群有相關issue跟蹤[CronJob controller should use shared informers](https://github.com/kubernetes/kubernetes/issues/17130)已提交相關資訊給Contributor，重新修改問題。
- Cronjob後續GA版本[KEP for Graduating CronJob to GA](https://github.com/kubernetes/enhancements/pull/978)

### 實施方案

- 生產環境歷史job資料透過patch ttlSecondsAfterFinished，更新job過期時間
- 生產環境新建job透過增加ttlSecondsAfterFinished，配置job過期時間
- 變更後的etcd慢查詢告警曲線
  ![avatar](http://img-hxy021.didistatic.com/static/way/do1_wa7k7c7exY5ktSvS3Zkf)

### 參考資料

- [Options for Highly Available topology](https://kubernetes.io/docs/setup/production-environment/tools/kubeadm/ha-topology/#external-etcd-topology)
- [Set up a High Availability etcd cluster with kubeadm](https://kubernetes.io/docs/setup/production-environment/tools/kubeadm/setup-ha-etcd-with-kubeadm/)
- [etcdserver: read-only range request took too long with etcd 3.2.24](https://github.com/kubernetes/kubernetes/issues/70082)
- [etcd namespace metrics](https://github.com/etcd-io/etcd/blob/master/Documentation/metrics.md#disk)
- [what-does-the-etcd-warning-apply-entries-took-too-long-mean]((https://github.com/etcd-io/etcd/blob/master/Documentation/faq.md#what-does-the-etcd-warning-apply-entries-took-too-long-mean)

### 作者：童超【 滴滴出行資深軟體開發工程師】

- [	現在註冊滴滴雲，得8888元立減紅包](https://app.didiyun.com/#/auth/signup?channel=14816)
- [7月特惠，1C2G1M雲伺服器 9.9元/月限時搶](https://www.didiyun.com/?channel=14816)
- [滴滴雲使者專屬特惠，包年雲伺服器低至68元/年](https://www.didiyun.com/envoy/e-index.html?channel=14816)
- [輸入大師碼【7886】，GPU全線產品9折優惠](https://www.didiyun.com/production/gpu.html?channel=14816)

【k8s】etcd叢集took too long to execute慢日誌告警問題分析

相關文章