摘要：一個前端開發者介紹了他和他的數據庫朋友們是如何降低基于Ruby網站數據庫負載的故事。以下為譯文：

　　數據庫負載可能是個沉默的性能殺手。我一直都在優化我的一個網站應用，用來吸引人們參與到開放代碼社區，但我注意到一些隨機的查詢時間異常，有時會長達15s或更長。雖然我注意到這個現象有些時候了，我直到最近才開始優化我的數據庫查詢。我首先通過建立索引優化了我的主頁（并且使用Rack Mini Profiler工具），然后我追蹤并刪除掉了一些代價高昂的查詢。在這些重要的提升后，平均響應時間在50ms左右，95%在1s以內。但是，我遇到一個討厭的問題，在24小時內，95%響應時間可能急升到15s或30s并在短時間內超時。本文將介紹我如何查找并解決這個問題。這最終使我的數據庫降低了80%的負載。

　　這是我的響應時間圖，我希望移除這些異常峰值。

　　為了理解為什么這個（或這些）請求是如此的慢，我用了計量工具。在本例中，我使用了Heroku Scout 插件。我修改了比例來展示過去12小時內的請求（默認是3小時）。然后聚焦到這些巨大的峰值。這是我看到的

　　應用或者數據庫肯定有些不對勁。在scout的輸出里，你可以看到一個查詢要38秒才能完成。我試著手工去訪問這個頁面但是它很快就加載了。所以不會是頁面的問題。

　　很幸運的是我在Heroku工作，我立即在我們數據庫工程師的Slack聊天室里問他們是什么可能的原因引起了性能的下降。他們問我數據庫的平均負載。我用的是一個standard-o 數據庫Heroku聲稱它可以承受0.2 負載。我打開了Papertrail 日志 并尋找 load-avg。 我在那條慢請求時間附件發現這條記錄

　　Jun 29 01:01:01 issuetriage app/heroku-postgres： source=DATABASE sample#current_transaction=271694354

　　sample#db_size=4469950648bytes sample#tables=14 sample#active-connections=35

　　sample#waiting-connections=0 sample#index-cache-hit-rate=0.87073 sample#table-cache-hit-rate=0.47657

　　sample#load-avg-1m=2.15 sample#load-avg-5m=1.635 sample#load-avg-15m=0.915

　　sample#read-iops=16.325 sample#write-iops=0 sample#memory-total=15664468kB

　　sample#memory-free=255628kB sample#memory-cached=14213308kB sample#memory-postgres=549408kB

　　一般負載在0.2或以下是正常的，但我的應用峰值到了2.15，呦呵！

　　我已經花了不少時間來優化我的查詢時間，所以我對此還是很意外的。一位數據工程師建議我使用 pg:outliers 命令（Heroku pg:extra CLI 擴展）

　　如果你不使用Heroku，你可以通過 _pg_stat_statements_ 表來得到同樣的數據

　　當我安裝了這個擴展并使用該命令我發現一條查詢語句占了高達（你猜對了）80%的執行時間。

　　$ heroku pg:outliers

　　total_exec_time | prop_exec_time | ncalls | sync_io_time | query

　　------------------+----------------+-------------+------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

　　3790:50:52.62102 | 80.2% | 100，727，265 | 727:08:40.969477 | SELECT ？ AS one FROM “repos” WHERE LOWER（“repos”。“name”） = LOWER（$1） AND （“repos”。“id” ！= $2） AND “repos”。“user_name” = $3 LIMIT $4

　　493:04:18.903353 | 10.4% | 101，625，003 | 52:09:48.599802 | SELECT COUNT（*） FROM “issues” WHERE “issues”。“repo_id” = $1 AND “issues”。“state” = $2

　　這是那個查詢語句（方便較小的顯示屏幕）

　　SELECT ？

　　AS one

　　FROM “repos”

　　WHERE LOWER（“repos”。“name”） = LOWER（$1） AND

　　（“repos”。“id” ！= $2） AND

　　“repos”。“user_name” = $3

　　LIMIT $4

　　對此我感到很奇怪。因為我不記得我寫過這樣的查詢語句。我搜索了我的代碼庫中含有 LOWER SQL函數的代碼但沒有找到任何一條。于是我求助于Papertrail來看看在現實生產環境中這個語句什么時候被調用的。我找到的第一條記錄在一個創建操作中：

　　Started POST “/repos” for 131.228.216.131 at 2017-06-29 09:34:59

　　Processing by ReposController#create as HTML

　　Parameters： {“utf8”=》“?”， “authenticity_token”=》lIR3ayNog==“， ”url“=》”https://github.com/styleguidist/react-

　　User Load （0.9ms） SELECT “users”.* FROM “users” WHERE “users”。

　　Repo Load （1.1ms） SELECT “repos”.* FROM “repos” WHERE “repos”。

　　（0.9ms） BEGIN

　　Repo Exists （1.9ms） SELECT 1 AS one FROM “repos” WHERE LOWER（ $3 LIMIT $4

　　（0.5ms） COMMIT

　　（0.8ms） BEGIN

　　RepoSubion Exists （4.3ms） SELECT 1 AS one FROM “repo_ns”。“user_id” = $2 LIMIT $3

　　SQL （5.6ms） INSERT INTO “repo_subions” （“created_at”，

　　（6.1ms） COMMIT

　　［ActiveJob］ Enqueued SendSingleTriageEmailJob （Job ID： cbe2b04a-d271

　　Redirected to https://www.codetriage.com/styleguidist/react-

　　Completed 302 Found in 39ms （ActiveRecord： 21.9ms）

　　Jun 29 02:35:00 issuetriage heroku/router： at=info method=POST path=“/repos” host=www.codetriage.com request_id=5e706722-7668-4980-ab5e-9a9853feffc9 fwd=“131.228.216.131” dyno=web.3 connect=1ms service=542ms status=302 bytes=1224 protocol=https

　　為了簡潔，日志的標簽被移除了

　　這有點難讀，但你可以看 Repo Exists右邊的查詢語句。我查看了那個控制入口函數（ReposController#create）并檢查了一些可疑方法，但是結果都沒問題（例如，都沒有調用 SQL LOWER 函數）。那么問題來了，這些查詢語句是從哪里來的呢？

　　最終答案是來自于我的數據模型中的這一行代碼。這行貌似無害的代碼承擔了我數據庫80%的負載。這個 Validate 調用是 Rails 試圖保證兩個 Repo 記錄沒有相同的用戶名和用戶姓名。它沒有采用在數據庫中強制執行一致性，而是在模型對象上加了一個 before commit的鉤子，這樣在模型對象寫入數據庫前，它會查詢數據庫來確保我們創建一個新 repo 記錄的時候沒有重復的記錄。

　　在我寫這個驗證邏輯的時候我沒有想太多。看這個驗證代碼本身也很難相信它居然引發如此大的數據庫負載。畢竟我只有大概2000條repo記錄。理論上這個驗證調用最多調用2000次，對吧？

　　為了回答這個問題，我重新查找日志并找到另外一處這個SQL語句執行的地方。

　　Jun 29 07:00:32 issuetriage app/scheduler.8183： ［ActiveJob］ Enqueued PopulateIssuesJob （Job ID： 9e04e63f-a515-4dcd-947f-0f777e56dd1b） to Sidekiq（default） with arguments： #《GlobalID:0x00000004f98a68 @uri=#《URI：：GID gid://code-triage/Repo/1008》》

　　Performing PopulateIssuesJob （uri=#《URI：：GID gid://code-

　　User Load （10.4ms） SELECT

　　（35.4ms） BEGIN

　　Repo Exists （352.9ms） SELECT $3 LIMIT $4

　　SQL （3.7ms） UPDATE “repos”

　　（4.5ms） COMMIT

　　Performed PopulatessuesJob （Job ID： 9e04e63f-a515-4dcd-947f-0f777e56dd1b） from Sidekiq（default） in 629.22ms

　　為了簡潔，日志的標簽被移除了

　　這一次這個查詢語句不是來自網頁動作，而是一個后臺作業。當我檢查它時我意識到這個驗證不止在創建時執行，它還在_任何_記錄的修改時執行。即使用戶名或用戶姓名沒有改動，它還是會查詢數據庫來確保沒有重復。

　　我有一個晚間任務來遍歷所有的代碼庫并且有時會更新他們的記錄。事實是我的后臺任務和這個慢網絡請求發生在幾乎相同的時間。基本上，我自己就是那個討厭的鄰居。我自己的后臺任務使得數據庫負載急升，遠超一般負載容量。其他普通的對時間敏感的網絡請求就因為沒有數據CPU時間而被迫等待并超時。

　　我立刻刪除了這個驗證并用一個單一索引代替，同時在數據庫上加了限制。

　　class AddUniqueIndexToRepos 《 ActiveRecord：：Migration［5.1］

　　def change

　　add_index ：repos， ［：name， ：user_name］， ：unique =》 true

　　end

　　end

　　現在我們可以確定在數據庫里沒有兩個記錄會有相同的用戶名/用戶名字組合，Rails程序也不需要在每次修改記錄時去查詢數據庫。

　　更不用提Rails程序驗證存在競爭并且實際上并不保證一致性，最好是在數據庫層面確保這些（一致性）事情。

　　你可能注意到 SQL LOWER 函數并沒有在我的單一性索引中出現。在我的應用中，我已經對存儲的數據做了規范化處理，所以這個邏輯是多余的。

　　在刪除驗證代碼并增加單一性索引后，我的應用再也沒有出現過30秒以上的請求延時。數據庫一直都在0.2 load-avg 或以下 運行。

　　當我們面對數據庫運行變慢時，我們傾向于考慮一個單獨的查詢語句的性能。我們很少考慮一個或幾個查詢語句可能相互影響并拖慢整個網站。

　　在看到 pg:outliers 結果后，我可以在其他幾個合適的位置加上索引來減少負載。 例如：

　　issuetriage：：DATABASE=》 EXPLAIN ANALYZE SELECT “repos”.* FROM “repos” WHERE “repos”。”full_name” = ‘schneems/wicked’ LIMIT 1;

　　QUERY PLAN

　　Limit （cost=0.00..39297.60 rows=1 width=1585） （actual time=57.885..57.885 rows=1 loops=1）

　　-》 Seq Scan on repos （cost=0.00..39297.60 rows=1 width=1585） （actual time=57.884..57.884 rows=1 loops=1）

　　Filter： （（full_name）：：text = ‘schneems/wicked’：：text）

　　Rows Removed by Filter： 823

　　Total runtime： 57.912 ms

　　（5 rows）

　　這里整體執行時間并不是在幾秒內，這個并不算好。那個串行化的掃描很快，但并非沒有代價。我對 _full_name 加了一個索引，現在它快的要飛起來。同樣的查詢可以在 1ms 內返回。針對這些調用的所以也幫助我減少了數據庫負載。

　　總結一下：

　　一個高的 load-avg 會拖慢所有的查詢語句，不僅僅是那些慢查詢語句。

　　使用pg:outlier 來發現那些占用了更多CPU時間的查詢語句（如果你使用Heroko），如果你使用其他平臺，你也可以使用 _pg_stat_statements

　　使用日志來定位查詢語句發生的時間并用 EXPLAIN ANALYZE 來分析為什么一個查詢如此耗時。

　　你的查詢語句的輸入很重要并且可能嚴重影響到查詢性能

　　添加索引，改變數據的存儲或者改變程序邏輯來避免異常的查詢

　　如果可能的話，利用數據庫來保證數據一致性而不是使用程序代碼

　　事后來看，這是個很簡單的錯誤并且很容易定位和修復，只是要花點時間和使用正確的工具。我注意到那個30s+的請求延時峰值有幾個月了，甚至幾年。我從沒有想去深挖原因，因為我原以為這會很麻煩。它也只是每天發生一次，對用戶的影響很小。利用正確的工具和我們數據庫工程師的建議，我很快就解決了。我不認為我掌握了數據庫優化，但至少現在我達到了我的目標。謝謝你閱讀我的數據庫負載之旅。

相關電子資料下載