天天看點

【譯】AWS RDS性能降低 - 複盤 - Honeycomb概要影響發生了什麼?根因分析經驗時間線 (2018-05-03 UTC)

原文: https://www.honeycomb.io/blog/rds-performance-degradation-postmortem/ 譯:時序

概要

注:除非特别說明,所有時間都是UTC。

5月3号周四, 從00:39:08 UTC(周三 17:39 PDT)我們經曆了一次Honeycomb服務的大約24分鐘的徹底停機。大部分服務恢複時間是2018-05-03 01:02:49,所有面向客戶的服務恢複是在01:07:00。

影響

  • 在停機期間,客戶不能登入或檢視Honeycomb服務的圖表。
  • 停機期間發送給Honeycomb API的事件被大量拒絕;大約86%的API不能服務,而且大約81%的應該已經送出的事件在停機期間沒有被記錄。(百分比的差距是由于一個單獨的API可以處理不同的事件并且停機沒有平均影響到所有資料集)
  • 由于Honeycomb API沒有報告成功,一些仍存儲在客戶服務上的事件在Honeycomb API恢複正常後又被重新送出。
  • 停機期間大約有15%的事件成功儲存

我們對這次停機影響的每一個客戶都十分抱歉。我們對于資料的管理十分認真,并通過對系統的多項改進措施來確定未來這類的停機事件不會造成資料丢失,并確定我們在類似的失敗中可以更快的恢複。

發生了什麼?

事後看,故障鍊隻有4點連通:

  1. 我們産品使用的RDS MySQL資料庫執行個體經曆了一次突然的和大規模的性能減低; P95(query_time)從11毫秒變成>1000毫秒,同時寫操作吞吐在20秒内從 780/秒降到 5/秒。
  2. RDS沒有識别到故障,是以 Mutil-AZ feature沒有激活故障轉移。
  3. 由于增加的query_time導緻的延遲, Go的MySQL用戶端連接配接池被等待慢查詢結果的連接配接填滿了并且作為補償又打開了更多的連接配接。
  4. MySQL伺服器的max_connections設定達到了上限,導緻定時任務和新啟動的背景程序不能連接配接到資料庫并導緻“Error 1040:Too many connections”的日志資訊。

恢複部分很快:

  1. RDS資料庫的延遲和吞吐突然出現改善;在20秒内P95(query_time)寫從>600ms 掉到 <200ms, 同時總吞吐從<500OPS 變成>2500OPS。
  2. 排隊的事件快速完成,資料庫在70秒内的OPS大于3000, 并在回到正常狀态時變成: 300-500OPS,<10ms 寫。

我們如何得到答案的故事是一個如何使用Honeycomb來debug生産系統的有趣的例子。

根因分析

在之後第二天早上我們的複盤會議上,兩個理論擺在桌上:

  1. 大量的連接配接數導緻停機,并引起了資料庫運作緩慢,或
  2. 資料庫由于一些原因運作緩慢,導緻大量的連接配接數。

我們擔心一些bug隐藏在我們的應用裡(或我們使用的其中一個Go庫)導緻我們的應用在不能連接配接資料庫時關機,這樣在同樣情況再發生時又會導緻一樣的停機故障。

每個人都同意這很像是下層資料庫的問題(存儲,CPU或連接配接)是根因,但我們也同意如果我們以抱怨網絡的方式忽略一個潛在應用級的bug會更有危險。

作為開發者的責任:這可能不是資料庫,而可能是你的代碼問題。

為了降低風險,我們決定在受控環境來重制Error 1040場景并觀察系統表現。在我們的實驗叢集上重制連接配接池溢出清楚的表明了連接配接滿确實會影響應用并導緻定時任務失敗,它不會導緻失控的CPU或延遲升高。

我們現在有兩個資料集:生産的停機和實驗用的。由于我們使用Honeycomb來觀察Honeycomb,是以在這個例子對比A和B很容易

實驗生産停機

【譯】AWS RDS性能降低 - 複盤 - Honeycomb概要影響發生了什麼?根因分析經驗時間線 (2018-05-03 UTC)
【譯】AWS RDS性能降低 - 複盤 - Honeycomb概要影響發生了什麼?根因分析經驗時間線 (2018-05-03 UTC)

左邊,實驗叢集從12:30到13:23(除了一些失敗的定時任務很難看出證據)運作,而在右邊,生産的停機很清楚地顯示着。實驗有個空結果:我們沒有發現 Error 1040導緻了停機。看起來像是系統的一些底層問題導緻的。

有了這個資訊,我們需要在生産資料上挖掘的更深入了。由于Honeycomb資料集是高保真的(我們不做任何聚合或預先的計算),可以将資料調整到每秒級别并調整資料來抽取模式。這裡是從rdslogs裡記錄的性能資料。

【譯】AWS RDS性能降低 - 複盤 - Honeycomb概要影響發生了什麼?根因分析經驗時間線 (2018-05-03 UTC)

有15秒沒有活動,然後有一批query_time值達到了15秒的完成動作,看起來很明顯。在結束時的性能異常也有一個有意思的熱力圖模式:

【譯】AWS RDS性能降低 - 複盤 - Honeycomb概要影響發生了什麼?根因分析經驗時間線 (2018-05-03 UTC)

概括下,資料展示了高于23分鐘的低吞吐,高延遲行為,并持續了少于30秒切換區域,之前是正常的高吞吐,低延遲,尖峰應用驅動的行為,接着是大量的追趕事件,最後切換到正常的高吞吐模式。

由于這不是一個全面的根因分析,但對于我們明确問題在資料庫系統而不是我們的應用代碼已經夠了;我們的應用看起來運作正常。我們之後再SQL的normalized_query字元串上驗證了我們的代碼在恢複過程中工作符合預期。

得到這些資訊後我們重新調查了我們的RDS配置并确認

  • Multi-AZ是打開的。
  • 執行個體監視面闆沒有顯示任何健康事件。
  • AWS文檔指出Multi-AZ不會考慮性能作為健康檢查的内容

經驗

  • 受管理的資料庫很好,除非他們沒托管。
  • 我們會優先考慮在“game day”運作我們的實驗RDS做故障轉移來重新驗證在硬體故障時我們對于我們系統運作的了解。雖然我們不認為RDS會有很多硬體故障,但當我們需要處理RDS AZ故障轉移時我們需要一個準備好的手冊來執行。
  • 我們在改進我們的管道來保證在基礎設施不能連接配接到資料庫時接受的使用者事件我們可以緩存它們而不是失敗。硬體問題發生,這就是生活;丢失資料不需要發生。

時間線 (2018-05-03 UTC)

00:39 – outage starts

00:40 – first alert

00:42 – engineers start investigation

00:50 – escalation, multiple investigators looking at several potential avenues

00:55 – status.honeycomb.io updated to keep our customers informed

00:58 – first engineering interventions to attempt to heal system, minimal impact

01:03 – outage resolution starts

01:04:23 – resolution completes, system stabilized

01:15 – engineers conclude that outage is resolved, update status.honeycomb.io