丨延時你的etcd求會出現(xiàn)超時

首先，當(dāng)我們面對一個高延時的請求案例后，如何梳理問題定位思路知彼知己，方能百戰(zhàn)不殆，定位問題也是類似。首先我們得弄清楚產(chǎn)生問題的原程，在02、03、04中我已為你介紹過讀寫請求的鏈路。其次是熟掌相關(guān)工具，借助它們，可以幫助我們快速攻破疑難雜癥這里我們再回顧下3中介紹的，dr一請求一個條目到集多數(shù)節(jié)點并應(yīng)用到狀態(tài)機的流程（如下圖所示），通過此圖我們看看寫流程上哪些地方可能會導(dǎo)致請求超時呢？首先是流程四，一方面，Leader需要并行將消息通過網(wǎng)絡(luò)發(fā)送給各Follower節(jié)點，依賴網(wǎng)絡(luò)性能。另一方面，Leader需持久化日志條目到WAL，依賴磁盤I/O順序?qū)懭胄阅芷浯问橇鞒贪耍瑧?yīng)用日志條目到狀態(tài)機時，etcd后端key-value引擎 10所介紹的，它是一個基于B+tree實現(xiàn)的引擎，當(dāng)你寫入數(shù)據(jù)，提交事務(wù)時，它會將dirtypage持久化到磁盤中。在這過程中bo b會產(chǎn)生磁盤隨機I/O寫入，因此事務(wù)提交性能依賴磁盤I/O隨機寫入性能最后，在整個寫流程處理過程中，etcd點的CPU、內(nèi)存、網(wǎng)絡(luò)帶寬資源應(yīng)充足，否則肯初步了解完可能導(dǎo)致延時抖動的瓶頸處之后，我給你總結(jié)了etcd題定位過程中常用的工圖的右邊是常用的工具，分別是metrics、trace日志、etcd其他日志、WAL及 分析工具分析etcd延時抖動的定位方法和原因。首先我們來看看流程圖中第一個提到可能瓶頸點，網(wǎng)在d，各個節(jié)點之間需要通過0端口相互通信，以完成eader步等功能，因此底層網(wǎng)絡(luò)質(zhì)量（吞吐量、延時、穩(wěn)定性）對上層d一方面，我們可以使用常規(guī)的/traceroute/mtr、ethtool、ifconfig/ip、netstat、tcpdump絡(luò)分析工具等命令，測試網(wǎng)絡(luò)的連通性、延時，查看網(wǎng)卡的速率是否存在丟包等錯誤，確認etcd進程的連接狀態(tài)及數(shù)量是否合理，抓取etcd報文分析等。另一方面，etcd應(yīng)用層提供了節(jié)點之間網(wǎng)絡(luò)統(tǒng)計的metrics指標(biāo)，分別如etcd_network_active_peer，表示peer之間活躍的連接數(shù)；etcd_network_peer_round_trip_time_seconds，表示peer之間RTT延時；etcd_network_peer_sent_failures_total，表示發(fā)送給peer消息數(shù)；etcd_network__grpc_sent_bytes_total，表示server發(fā)送給 數(shù)，通過這個指標(biāo)我們可以etcd出流量；etcd_network__grpc_received_bytes_total，表示server收到 字節(jié)數(shù)，通過這個指標(biāo)可以etcd入流量。入流量如下圖所示出流量如下圖所示。從圖中你可以看到，峰值接近140MB/s(1.12Gbps)，這是非常不合理的，說明業(yè)務(wù)中肯定有大量expensivereadrequest操作。若etcd集群讀寫請求開始出現(xiàn)超時，你可以用ifconfig等命令查看是否出現(xiàn)丟包等錯誤。etcdmetrics標(biāo)名namespacesubsystem、name成。namespaceetcd，subsystem是模塊名（比如network、name具體的指標(biāo)名）。你可以在Prometheus里搜索etcd_network找到所有network相關(guān)的metrics指標(biāo)名。下面是一個集群中某節(jié)點異常后的metrics指標(biāo)代代1234_grpc_sent_bytes_total從以上metrics，你可以91bc3c398fb3c146點出現(xiàn)了異常。在etcd景中，網(wǎng)絡(luò)質(zhì)量導(dǎo)致etcd性能下降主要源自兩個方面：一方面，expensiverequest的大包查詢會使網(wǎng)卡出現(xiàn)瓶頸，產(chǎn)生丟包等錯誤，從而導(dǎo)致etcd吐量下降、高延時。expensiverequest致網(wǎng)卡丟包，出現(xiàn)超時，這在etcd中是非常典型且易發(fā)生的問題，它主要是因為業(yè)務(wù)沒有遵循最佳實踐，查詢了大量key-越高，但各個節(jié)點之間的RTT越高，請求的延時更高。磁盤了解完網(wǎng)絡(luò)問題的定位方法和導(dǎo)致網(wǎng)絡(luò)性能下降的因素后，我們再看看最的磁I/O正如我在開頭的Raft日志整體流程圖中和你介紹的，在etcd中無論是Raft日志持久化還是bo b事務(wù)提交，都依賴于磁盤I/O的性能。當(dāng)etcd請求延時出現(xiàn)波動時，我們往往首先關(guān)注disk相關(guān)指標(biāo)是否正常。我們可以通etcd磁盤相關(guān)的metrics(etcd_disk_wal_fsync_duration_seconds mit_duration_seconds)來觀測應(yīng)用層數(shù)據(jù)寫入磁盤的性能etcd_disk_wal_fsync_duration_seconds（簡稱disk_wal_fsync）WAL持久化的fsync系統(tǒng)調(diào)用延時數(shù)據(jù)。一般本地SSD盤P99延時在10ms內(nèi)，如下圖所示。 端bo b事務(wù)提交的延時，一般P99在120ms內(nèi)。這里你需要注意的是，一般顯示的磁盤延時都是P99，但實際上etcd對磁盤特別敏感，一次磁盤I/O動就可能產(chǎn)生Leader。如果你遇到集群Leader現(xiàn)切換、請求超時，但是磁盤指標(biāo)顯示正常，你可以查看P100確認下是不是由于磁盤I/O波動導(dǎo)同時etcdWAL塊在fdatasync超過1時，也etcd打印如下的日志，代代iftook>warnSyncDurationifw.lg!=nil"slowzap.Duration("took",zap.Duration("expected-duration", }elseplog.Warningf("syncdurationof%v,expectedlessthan%v",took, 11disk_wal_fsync標(biāo)異常的時候，一般是底層硬件出現(xiàn)瓶頸或異常導(dǎo)致。當(dāng)然也有可能是CPU高負載、cgroupblkio限制導(dǎo)致的，我們具體應(yīng)該如何區(qū)分呢？你可以通過iostat、blktrace工具分析瓶頸是在應(yīng)用層還是內(nèi)核層、硬件層。其中blktraceblkio的磁盤I/O分析利器，它可記錄IO入通用塊層、IO求生成插入請求隊列、IO分發(fā)到設(shè)備驅(qū)動、設(shè)備驅(qū)動處理完成這一系列操作的時間，幫助你發(fā)現(xiàn)磁盤I/O瓶頸發(fā)生的階段。 mit指標(biāo)的異常時候，說明事務(wù)提交過程中的B+tree樹重平衡、、持久化dirtypage、持久化metapage等操作耗費了大量時間。mit指標(biāo)異常，能說明是磁盤I/O發(fā)生了異常嗎 mit較高、disk_wal_fsync卻正常，說明瓶頸可能并非來自磁I/O性能，也許是B+tree的重平衡、過程中的較高時間復(fù)雜度邏輯操作導(dǎo)致。比etcd目前所有stable版本（etcd3.2到3.4）， list中申請和回收若干連續(xù)空閑的時間復(fù)雜度是O(N)，當(dāng)db件較大、空閑頁碎片化分布的時候，則可能導(dǎo)致事務(wù)提交那如何區(qū)分事務(wù)提交過程中各個階段的耗時etcd還提供 mit_spill_duration個metrics，分別表示事務(wù)提交過B的重平衡和操作耗時分布區(qū)間最后，你需要注意disk_wal_fsync記錄的是WAL文件順序?qū)懭氲某志没瘯rmit錄的是整個事務(wù)提交的耗時。后者涉及的磁盤I/O隨機的，為了保證你etcd集群的穩(wěn)定性，建議使用SSD磁盤以確保事務(wù)提交的穩(wěn)定性。expensive若磁盤和網(wǎng)絡(luò)指標(biāo)都很正常，那么延時高還有可能是什么原因引起的從02介紹的讀請求鏈路我們可知，一個讀寫請求經(jīng)過Raft模塊處理后，最終會走到MVCC模塊。那么在MVCC模塊會有哪些場景導(dǎo)致延時抖動呢？時間耗在哪個處理流程etcd3.4版本之前，在應(yīng)用put/txn等請求到狀態(tài)機的apply和處理讀請求range流程時，若一個請求執(zhí)行超過100ms時，默認會在etcdlog中打印一條"applyrequesttooktoolong"的警告日志。通過此日志我們可以知道集群中apply流程產(chǎn)生了較慢的請求，但比如在Kubernetes，當(dāng)Pod多的時候，若你頻繁執(zhí)行ListPod，可能會導(dǎo)致etcd出現(xiàn)大量的"applyrequesttooktoolong"警告日志。因為對etcd言，ListPod求涉及到大量的key詢，會消耗較CPU、內(nèi)存、網(wǎng)絡(luò)資源，此類expensiverequest的QPS若較大，則很可能導(dǎo)致OOM、丟包。當(dāng)然，除了業(yè)務(wù)發(fā)起的expensiverequest導(dǎo)致延時抖動以外，也有可能是etcd比如在etcd3.2和3.3版本寫請求完成之前，需要更新MVCC的buffer，進行升級鎖操作。然而此時若集群中出現(xiàn)了一個longexpensivereadrequest，則會導(dǎo)致寫請求執(zhí)行延時抖動。因為expensivereadrequest事務(wù)會一直持有MVCC的buffer讀鎖，導(dǎo)致寫請在了解完expensiverequest請求延時的影響后，接下來要如何解決請求延時較高問題為了提高請求延時分布的可觀測性、延時問題的定位效率，etcd區(qū)在3.4本后中實現(xiàn)了trace特性，詳細記錄了一個請求在各個階段的耗時。若某階段耗時流程超過默認的100ms，則會打印一條trace日志。下面是trace志打印的閾值1秒后讀請求執(zhí)行過程中的trace志。從日志中你可以看到，trace日志記錄了以下階段耗時：agreementamongraftnodesbeforelinearizedreading，此階段讀請求向Leader發(fā)起readIndex查詢并等待本地appliedindex>=Leader的committedindex，但是你無法區(qū)分是readIndex慢還是等待本地appliedindex>Leader的committedindex慢。在etcd3.5中新增了trace，區(qū)分了以上階段；getauthenticationmetadata，獲取鑒權(quán)元數(shù)rangekeysfromin-memoryindextree，從內(nèi)存索引B-tree查找key表對應(yīng)的rangekeysfromboltdb，根據(jù)版本號列表從bo b遍歷，獲得用戶的key-value信filterandsortthekey-valuepairs，過濾、排序key-value表assembletheresponse，聚合結(jié)果代代1234567{"ts":"2020-12-]"detail":"{range_begin:a;range_end:;response_count:1;889 ]'agreementamongraftnodesbeforelinearized]'getauthenticationmetadata'(duration:]'rangekeysfromin-memoryindextree'(duration:]'rangekeysfromboltdb'(duration:]'filterandsortthekey-valuepairs'(duration:]'assembletheresponse'(duration:]}那么寫請求流程會記錄哪些階段耗時呢下面是put寫請求的執(zhí)行trace日志，記錄了以下階段耗processraftrequest，寫請求提交到Raft模塊處理完成耗時getkey'spreviouscreated_revisionandleaseID，獲取key上一個創(chuàng)建版本號marshalmvb.KeyValue，序列化KeyValue結(jié)構(gòu)體耗時；storekvpairintoboltdb，kv數(shù)據(jù)到bob的耗時；attachleasetokvpair，將leaseid關(guān)聯(lián)到kv上所用時間。代代123456789{"ts":"2020-12-]"detail":"{key:16;req_size:8;response_revision:32030;}"，]'processraft(duration:]'getkey'spreviouscreated_revisionand]'marshalb.KeyValue'(duration:]'storekvpairintobolt(duration:]'attachleasetokv(duration:]}通過以上介紹的trace特性，你就可以快速定位到高延時讀寫請求的原因。比如當(dāng)你向etcd了一個涉及到大量keyvalue大的expensiverequest求的時候，它會產(chǎn)生如下的warn和trace日志。從以下日志中我們可以看到，此請求查詢的vip前綴下所有的kv數(shù)據(jù)總共是250條，但是涉及的數(shù)據(jù)包大小有250MB，總耗時約1.85秒，其中從bob遍歷key消耗了1.63代代123456789{"ts":"2020-12-"msg":"applyrequesttooktoolong"，"prefix":"read-onlyrange"，"request":"key:"vip"range_end:"viq""，"response":"range_response_count:250"}{"ts":"2020-12-]"detail":"{range_begin:vip;range_end:viq;response_count:250;]'rangekeysfrombolt(duration:]}最后，有兩個注意事項第一，在etcd3.4中，logger默認為c log，trace特性只有在當(dāng)logger為zap時才開啟，因此你需要設(shè)置--logger=zap。第二，trace特性并不能記錄所有類型的請求，它目前只覆蓋了MVCC模塊range/put/txn用接口Authenticate權(quán)請求，涉及到CPU算，延非常高的，在trace日志中目前沒有相關(guān)記錄如果你開啟了鑒權(quán)，在連接數(shù)增多、QPS增大后，若突然出現(xiàn)請求超時，如何確定是etcd默認參數(shù)并不會各個接口的延時數(shù)據(jù)，我們可以通過設(shè)置etcd的啟動參數(shù)--metricsextensive開啟，獲得每個gRPC的延時數(shù)據(jù)。同時可結(jié)合gRPC接口的請求數(shù)，獲得QPS。如下是某節(jié)點的metrics據(jù)，251Put求，返回碼OK，其中有240請毫秒內(nèi)完代代123456789grpc_type="unary"}集群容量、節(jié)點CPU/Memory介紹完網(wǎng)絡(luò)、磁盤I/O、expensiverequest致etcd延時較高的原因和分析方法若網(wǎng)絡(luò)、磁盤I/O常expensiverequest，那此時高延時請求是怎么產(chǎn)生的呢？它的trace日志會輸出怎樣的耗時結(jié)果？下面是一個社區(qū)用戶反饋的一個讀接口高延時案例的trace志。從第一條日志中我們可以知道瓶頸在于線性讀的準備步驟，readIndex和waitappliedindex。那么是其中具體哪個步驟導(dǎo)致的高延時呢？通過在etcd3.5本中細化此流程，我們獲得了第二條日志，發(fā)現(xiàn)瓶頸在于等待appliedindex>=Leader的committedindex。代代123456789{"level":"ts":"2020-08-"caller":"msg":]"detail":"{range_begin:/...redacted...;range_end:;response_count:1;"duration":"start":"2020-08-12T08:24:54.628Z"，"end":"2020-08-12T08:24:56.181Z"，"steps":]}]'agreementamongraftnodesbeforelinearized{"level":"ts":"2020-09-"caller":"msg":"detail":]"duration":"start":"2020-09-22T12:54:00.166Z"，"end":"2020-09-22T12:54:01.021Z"，"steps":]readindexreceived(duration:]appliedindexisnowlowerthan]}為什么會發(fā)生這樣的現(xiàn)象首先你可以通過etcd_server_slow_apply_total標(biāo)，觀查其值快速增長的時間點與高延其次檢查是否存在大量寫請求。線性讀需確保本節(jié)點數(shù)據(jù)與Leader數(shù)據(jù)一樣新，若本節(jié)點的數(shù)Leader異較大，本節(jié)點追趕Leader據(jù)過程會花費一定時間，最終導(dǎo)致高e