摘要：一個(gè)前端開(kāi)發(fā)者介紹了他和他的數(shù)據(jù)庫(kù)朋友們是如何降低基于Ruby網(wǎng)站數(shù)據(jù)庫(kù)負(fù)載的故事。以下為譯文：

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

　　這是我的響應(yīng)時(shí)間圖，我希望移除這些異常峰值。

　　為了理解為什么這個(gè)（或這些）請(qǐng)求是如此的慢，我用了計(jì)量工具。在本例中，我使用了Heroku Scout 插件。我修改了比例來(lái)展示過(guò)去12小時(shí)內(nèi)的請(qǐng)求（默認(rèn)是3小時(shí)）。然后聚焦到這些巨大的峰值。這是我看到的

　　應(yīng)用或者數(shù)據(jù)庫(kù)肯定有些不對(duì)勁。在scout的輸出里，你可以看到一個(gè)查詢要38秒才能完成。我試著手工去訪問(wèn)這個(gè)頁(yè)面但是它很快就加載了。所以不會(huì)是頁(yè)面的問(wèn)題。

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

　　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

　　一般負(fù)載在0.2或以下是正常的，但我的應(yīng)用峰值到了2.15，呦呵！

　　我已經(jīng)花了不少時(shí)間來(lái)優(yōu)化我的查詢時(shí)間，所以我對(duì)此還是很意外的。一位數(shù)據(jù)工程師建議我使用 pg:outliers 命令（Heroku pg:extra CLI 擴(kuò)展）

　　如果你不使用Heroku，你可以通過(guò) _pg_stat_statements_ 表來(lái)得到同樣的數(shù)據(jù)

　　當(dāng)我安裝了這個(gè)擴(kuò)展并使用該命令我發(fā)現(xiàn)一條查詢語(yǔ)句占了高達(dá)（你猜對(duì)了）80%的執(zhí)行時(shí)間。

　　$ 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”?！皀ame”） = LOWER（$1） AND （“repos”?！癷d” ！= $2） AND “repos”?！皍ser_name” = $3 LIMIT $4

　　493:04:18.903353 | 10.4% | 101，625，003 | 52:09:48.599802 | SELECT COUNT（*） FROM “issues” WHERE “issues”?！皉epo_id” = $1 AND “issues”?！皊tate” = $2

　　這是那個(gè)查詢語(yǔ)句（方便較小的顯示屏幕）

　　SELECT ？

　　AS one

　　FROM “repos”

　　WHERE LOWER（“repos”?！皀ame”） = LOWER（$1） AND

　　（“repos”?！癷d” ！= $2） AND

　　“repos”?！皍ser_name” = $3

　　LIMIT $4

　　對(duì)此我感到很奇怪。因?yàn)槲也挥浀梦覍?xiě)過(guò)這樣的查詢語(yǔ)句。我搜索了我的代碼庫(kù)中含有 LOWER SQL函數(shù)的代碼但沒(méi)有找到任何一條。于是我求助于Papertrail來(lái)看看在現(xiàn)實(shí)生產(chǎn)環(huán)境中這個(gè)語(yǔ)句什么時(shí)候被調(diào)用的。我找到的第一條記錄在一個(gè)創(chuàng)建操作中：

　　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

　?。?.5ms） COMMIT

　?。?.8ms） BEGIN

　　RepoSubion Exists （4.3ms） SELECT 1 AS one FROM “repo_ns”?！皍ser_id” = $2 LIMIT $3

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

　?。?.1ms） COMMIT

　?。跘ctiveJob］ 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

　　為了簡(jiǎn)潔，日志的標(biāo)簽被移除了

　　這有點(diǎn)難讀，但你可以看 Repo Exists右邊的查詢語(yǔ)句。我查看了那個(gè)控制入口函數(shù)（ReposController#create）并檢查了一些可疑方法，但是結(jié)果都沒(méi)問(wèn)題（例如，都沒(méi)有調(diào)用 SQL LOWER 函數(shù)）。那么問(wèn)題來(lái)了，這些查詢語(yǔ)句是從哪里來(lái)的呢？

　　最終答案是來(lái)自于我的數(shù)據(jù)模型中的這一行代碼。這行貌似無(wú)害的代碼承擔(dān)了我數(shù)據(jù)庫(kù)80%的負(fù)載。這個(gè) Validate 調(diào)用是 Rails 試圖保證兩個(gè) Repo 記錄沒(méi)有相同的用戶名和用戶姓名。它沒(méi)有采用在數(shù)據(jù)庫(kù)中強(qiáng)制執(zhí)行一致性，而是在模型對(duì)象上加了一個(gè) before commit的鉤子，這樣在模型對(duì)象寫(xiě)入數(shù)據(jù)庫(kù)前，它會(huì)查詢數(shù)據(jù)庫(kù)來(lái)確保我們創(chuàng)建一個(gè)新 repo 記錄的時(shí)候沒(méi)有重復(fù)的記錄。

　　在我寫(xiě)這個(gè)驗(yàn)證邏輯的時(shí)候我沒(méi)有想太多。看這個(gè)驗(yàn)證代碼本身也很難相信它居然引發(fā)如此大的數(shù)據(jù)庫(kù)負(fù)載。畢竟我只有大概2000條repo記錄。理論上這個(gè)驗(yàn)證調(diào)用最多調(diào)用2000次，對(duì)吧？

　　為了回答這個(gè)問(wèn)題，我重新查找日志并找到另外一處這個(gè)SQL語(yǔ)句執(zhí)行的地方。

　　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

　?。?5.4ms） BEGIN

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

　　SQL （3.7ms） UPDATE “repos”

　?。?.5ms） COMMIT

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

　　為了簡(jiǎn)潔，日志的標(biāo)簽被移除了

　　這一次這個(gè)查詢語(yǔ)句不是來(lái)自網(wǎng)頁(yè)動(dòng)作，而是一個(gè)后臺(tái)作業(yè)。當(dāng)我檢查它時(shí)我意識(shí)到這個(gè)驗(yàn)證不止在創(chuàng)建時(shí)執(zhí)行，它還在_任何_記錄的修改時(shí)執(zhí)行。即使用戶名或用戶姓名沒(méi)有改動(dòng)，它還是會(huì)查詢數(shù)據(jù)庫(kù)來(lái)確保沒(méi)有重復(fù)。

　　我有一個(gè)晚間任務(wù)來(lái)遍歷所有的代碼庫(kù)并且有時(shí)會(huì)更新他們的記錄。事實(shí)是我的后臺(tái)任務(wù)和這個(gè)慢網(wǎng)絡(luò)請(qǐng)求發(fā)生在幾乎相同的時(shí)間?；旧?，我自己就是那個(gè)討厭的鄰居。我自己的后臺(tái)任務(wù)使得數(shù)據(jù)庫(kù)負(fù)載急升，遠(yuǎn)超一般負(fù)載容量。其他普通的對(duì)時(shí)間敏感的網(wǎng)絡(luò)請(qǐng)求就因?yàn)闆](méi)有數(shù)據(jù)CPU時(shí)間而被迫等待并超時(shí)。

　　我立刻刪除了這個(gè)驗(yàn)證并用一個(gè)單一索引代替，同時(shí)在數(shù)據(jù)庫(kù)上加了限制。

　　class AddUniqueIndexToRepos 《 ActiveRecord：：Migration［5.1］

　　def change

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

　　end

　　end

　　現(xiàn)在我們可以確定在數(shù)據(jù)庫(kù)里沒(méi)有兩個(gè)記錄會(huì)有相同的用戶名/用戶名字組合，Rails程序也不需要在每次修改記錄時(shí)去查詢數(shù)據(jù)庫(kù)。

　　更不用提Rails程序驗(yàn)證存在競(jìng)爭(zhēng)并且實(shí)際上并不保證一致性，最好是在數(shù)據(jù)庫(kù)層面確保這些（一致性）事情。

　　你可能注意到 SQL LOWER 函數(shù)并沒(méi)有在我的單一性索引中出現(xiàn)。在我的應(yīng)用中，我已經(jīng)對(duì)存儲(chǔ)的數(shù)據(jù)做了規(guī)范化處理，所以這個(gè)邏輯是多余的。

　　在刪除驗(yàn)證代碼并增加單一性索引后，我的應(yīng)用再也沒(méi)有出現(xiàn)過(guò)30秒以上的請(qǐng)求延時(shí)。數(shù)據(jù)庫(kù)一直都在0.2 load-avg 或以下 運(yùn)行。

　　當(dāng)我們面對(duì)數(shù)據(jù)庫(kù)運(yùn)行變慢時(shí)，我們傾向于考慮一個(gè)單獨(dú)的查詢語(yǔ)句的性能。我們很少考慮一個(gè)或幾個(gè)查詢語(yǔ)句可能相互影響并拖慢整個(gè)網(wǎng)站。

　　在看到 pg:outliers 結(jié)果后，我可以在其他幾個(gè)合適的位置加上索引來(lái)減少負(fù)載。 例如：

　　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

　?。? rows）

　　這里整體執(zhí)行時(shí)間并不是在幾秒內(nèi)，這個(gè)并不算好。那個(gè)串行化的掃描很快，但并非沒(méi)有代價(jià)。我對(duì) _full_name 加了一個(gè)索引，現(xiàn)在它快的要飛起來(lái)。同樣的查詢可以在 1ms 內(nèi)返回。針對(duì)這些調(diào)用的所以也幫助我減少了數(shù)據(jù)庫(kù)負(fù)載。

　　總結(jié)一下：

　　一個(gè)高的 load-avg 會(huì)拖慢所有的查詢語(yǔ)句，不僅僅是那些慢查詢語(yǔ)句。

　　使用pg:outlier 來(lái)發(fā)現(xiàn)那些占用了更多CPU時(shí)間的查詢語(yǔ)句（如果你使用Heroko），如果你使用其他平臺(tái)，你也可以使用 _pg_stat_statements

　　使用日志來(lái)定位查詢語(yǔ)句發(fā)生的時(shí)間并用 EXPLAIN ANALYZE 來(lái)分析為什么一個(gè)查詢?nèi)绱撕臅r(shí)。

　　你的查詢語(yǔ)句的輸入很重要并且可能?chē)?yán)重影響到查詢性能

　　添加索引，改變數(shù)據(jù)的存儲(chǔ)或者改變程序邏輯來(lái)避免異常的查詢

　　如果可能的話，利用數(shù)據(jù)庫(kù)來(lái)保證數(shù)據(jù)一致性而不是使用程序代碼

　　事后來(lái)看，這是個(gè)很簡(jiǎn)單的錯(cuò)誤并且很容易定位和修復(fù)，只是要花點(diǎn)時(shí)間和使用正確的工具。我注意到那個(gè)30s+的請(qǐng)求延時(shí)峰值有幾個(gè)月了，甚至幾年。我從沒(méi)有想去深挖原因，因?yàn)槲以詾檫@會(huì)很麻煩。它也只是每天發(fā)生一次，對(duì)用戶的影響很小。利用正確的工具和我們數(shù)據(jù)庫(kù)工程師的建議，我很快就解決了。我不認(rèn)為我掌握了數(shù)據(jù)庫(kù)優(yōu)化，但至少現(xiàn)在我達(dá)到了我的目標(biāo)。謝謝你閱讀我的數(shù)據(jù)庫(kù)負(fù)載之旅。