數(shù)據(jù)庫連接池引起的FullGC問題纤壁,看我如何一步步排查左刽、分析、解決

問題現(xiàn)象
在某個工作日酌媒,突然收到線上的服務(wù)告警欠痴,有大量的請求延時產(chǎn)生,查看線上服務(wù)發(fā)現(xiàn)基本上都是獲取數(shù)據(jù)庫連接超時秒咨,而且影響時間只有34秒鐘喇辽,服務(wù)又恢復(fù)了正常。隔了幾分鐘之后雨席,又出現(xiàn)了大量的告警菩咨,還是影響34秒后又恢復(fù)正常。由于我們是底層服務(wù)陡厘,被重多的上層服務(wù)所依賴旦委,這么頻繁的異常波動已經(jīng)嚴(yán)重影響到了業(yè)務(wù)使用。開始排查問題

排查過程
DB的影響雏亚?

當(dāng)?shù)谝淮胃婢a(chǎn)生時缨硝,第一反應(yīng)是可能上層服務(wù)有大量的接口調(diào)用,并且涉及到一些復(fù)雜的SQL查詢導(dǎo)致數(shù)據(jù)庫連接數(shù)不夠用罢低,但是在分析了接口調(diào)用情況后發(fā)現(xiàn)異常前后的請求并沒有明顯的變化查辩,排除突發(fā)流量造成的影響
查詢DB情況,負(fù)載良好网持,無慢查詢宜岛,排除DB造成的影響
容器或JVM的影響?

排除了DB的影響之后功舀,再往上排查容器的影響 我們再次回過頭看異常告警萍倡,發(fā)現(xiàn)在每一波告警的時間段內(nèi),基本上都是同一個容器IP所產(chǎn)生辟汰,這個時候基本上已經(jīng)有80%的概率是GC的問題了列敲。查詢告警時間段內(nèi)的容器CPU負(fù)載正常阱佛。再看JVM的內(nèi)存和GC情況,發(fā)現(xiàn)整個內(nèi)存使用曲線是像下面這樣:

Heap


image.png

Old Gen


image.png

從上圖可以發(fā)現(xiàn)內(nèi)存中存在長時間被引用戴而,無法被YongGC所回收的對象凑术,并且對象大小一直在增長。直到Old Gen被堆滿之后觸發(fā)Full GC后對象才會回收所意。

臨時措施

現(xiàn)在問題已經(jīng)找到了淮逊,到目前為止只是3臺實例觸發(fā)了FullGC,但是在查看其它實例內(nèi)存使用情況時扶踊,發(fā)現(xiàn)基本上所有的實例Old Gen都快到達(dá)臨界點了泄鹏。所以臨時解決方案是保留一臺實例現(xiàn)場,滾動重啟其它所有的實例秧耗,避免大量的實例同時進(jìn)行FullGC备籽。否則很可能導(dǎo)致服務(wù)雪崩。

原本服務(wù)是有設(shè)置jvm監(jiān)控告警的绣版,理論上來說當(dāng)內(nèi)存使用率達(dá)到一定值時會有告警通知,但是由于一次服務(wù)遷移導(dǎo)致告警配置失效歼疮,沒有提前發(fā)現(xiàn)問題杂抽。
問題分析
什么對象沒有被回收?

目前了解到的情況:內(nèi)存無法被YoungGC回收韩脏,且無限增加缩麸,只有FullGC才能夠回收這批對象


image.png

先簡單在線上觀察了一波,排第2的HashMap$Node看起來比較異常赡矢,但是看不出更詳細(xì)的情況了杭朱。最好的辦法還是將內(nèi)存快照dump出來,使用MAT分析一波


image.png

使用MAT打開之后吹散,可以發(fā)現(xiàn)很明顯的問題:
image.png

這個類占用了80%以上的內(nèi)存弧械,那么這個類是干嘛的呢?看類名就知道空民,應(yīng)該是MySQL Driver中用來清理過期連接的一個線程刃唐。讓我們看一下源碼:
image.png

這個類是一個單例,會且僅會開一個線程界轩,用來清理那些沒有被顯式的關(guān)閉的數(shù)據(jù)庫連接画饥。
可以看到這個類里面維護了一個Set
image.png

對應(yīng)我們上面看到的內(nèi)存占用率排第二的HashMapNode基本上可以確定大概率是這里存在內(nèi)存泄露了。在MAT上使用list_object確認(rèn)一發(fā):
image.png

果然沒錯浊猾,罪魁禍?zhǔn)渍业搅硕陡剩∧敲此锩娲娴氖巧稏|西呢?為什么一直增長且無法被YoungGC回收葫慎?看名字
ConnectionFinalizerPhantomReference 我們可以猜到它里面保存的應(yīng)該是數(shù)據(jù)庫連接的phantom引用

什么是phantom reference? 當(dāng)一個對象只有phantom reference引用時衔彻,則會在虛擬機GC時被回收薇宠,同時會將phantom reference的對象放入一個referenceQueue中。

讓我們來跟蹤源碼確認(rèn)一下
image.png

image.png

果然是PhantomReference米奸,里面存放的是創(chuàng)建的MySQL連接昼接,看一下是在哪里被放進(jìn)來的:
image.png

image.png

可以看到,每次創(chuàng)建一個新的數(shù)據(jù)庫連接時悴晰,都會將創(chuàng)建的連接包裝成PhantomReference后放入
connectionFinalizerPhantomRefs中慢睡,然后這個清理線程會在一個無限循環(huán)中,獲取referenceQueue中的連接并關(guān)閉铡溪。

只有在 connection對象 沒有其它的引用漂辐,僅存在phantom reference時,才能夠被GC棕硫,并且放入referenceQueue中
為什么Connection會無限增長髓涯?

現(xiàn)在問題找到了,數(shù)據(jù)庫連接被創(chuàng)建之后哈扮,則會放入
connectionFinalizerPhantomRefs中纬纪,但是由于某種原因,連接前期正常使用滑肉,經(jīng)過了多次minor GC都沒有被回收包各,晉升到了老年代。但是一段時間過后靶庙,由于某種原因連接失效问畅,導(dǎo)致連接池又新建了連接。

我們項目用的數(shù)據(jù)庫連接池是Druid六荒,以下為連接池配置:


image.png

可以看到是設(shè)置了keepAlive护姆,且

minEvictableIdleTimeMillis設(shè)置的是5分鐘,連接初始化之后掏击,在DB請求數(shù)沒有頻繁的波動時卵皂,連接池應(yīng)該都是維護著最小的30個連接,且會在連接空閑時間超過5分鐘時進(jìn)行一次keepAlive操作:
image.png

image.png

理論上來說砚亭,連接池是不會頻繁的創(chuàng)建連接的渐裂,除非有活躍連接很少,且存在波動钠惩,并且keepAlive操作沒有生效柒凉,在連接池進(jìn)行keepAlive操作時,MySQL連接就已經(jīng)失效篓跛,那么則會丟棄這個無效連接膝捞,下次再重建。

下面就是驗證這個猜想,我們首先查看我們的活躍連接數(shù)蔬咬,發(fā)現(xiàn)在大部分時候鲤遥,單實例的數(shù)據(jù)庫的活躍連接數(shù)都在320個左右波動,并且業(yè)務(wù)上還存在定時任務(wù)林艘,每隔30分鐘1個小時會有大量的DB請求盖奈。Druid既然有每隔5分鐘有心跳行為,那為什么連接還會失效狐援?最大的可能是MySQL服務(wù)端的操作钢坦,MySQL默認(rèn)服務(wù)端的wait_timeout是8小時,難道是有變更對應(yīng)的配置啥酱?

image.png

果然爹凹,數(shù)據(jù)庫的超時時間被設(shè)置成了5分鐘!那么問題就很明顯了镶殷。
結(jié)論
空閑連接依賴于Druid的keepAlive定時任務(wù)來進(jìn)行心跳檢測和keepAlive禾酱,定時任務(wù)默認(rèn)每60秒檢測一次,并且只有當(dāng)連接的空閑時間大于minEvictableIdleTimeMillis時才會進(jìn)行心跳檢測绘趋。
由于minEvictableIdleTimeMillis被設(shè)置為了5分鐘颤陶,理論上空閑連接會在5分鐘±60秒的時間區(qū)間內(nèi)進(jìn)行心跳檢測。但是由于MySQL服務(wù)端的超時時間只有5分鐘陷遮,所以大概率當(dāng)Druid進(jìn)行keepAlive操作時連接已經(jīng)失效了滓走。
由于數(shù)據(jù)庫的活躍連接是波動的,且min-idle設(shè)置的是30拷呆,活躍連接處于波峰時闲坎,需要創(chuàng)建大量的連接疫粥,并且維護在連接池中茬斧。但是當(dāng)活躍降到低谷時,大量的連接由于keepAlive失敗梗逮,從連接池中被移除项秉。周而復(fù)始。
每次創(chuàng)建連接時慷彤,又會將Connection對象放入入connectionFinalizerPhantomRefs中娄蔼,并且由于創(chuàng)建完之后連接是處于活躍狀態(tài),短時間內(nèi)不會被miniorGC所回收底哗,直至?xí)x升到老年代岁诉。導(dǎo)致這個SET越來越大。
解決
知道問題的產(chǎn)生原因跋选,要解決就很簡單了涕癣,將
minEvictableIdleTimeMillis設(shè)置為3分鐘,保證keepAlive的有效性前标,避免一直重建連接即可坠韩。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末距潘,一起剝皮案震驚了整個濱河市,隨后出現(xiàn)的幾起案子只搁,更是在濱河造成了極大的恐慌音比,老刑警劉巖,帶你破解...
    沈念sama閱讀 218,755評論 6 507
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件氢惋,死亡現(xiàn)場離奇詭異洞翩,居然都是意外死亡,警方通過查閱死者的電腦和手機明肮,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,305評論 3 395
  • 文/潘曉璐 我一進(jìn)店門菱农,熙熙樓的掌柜王于貴愁眉苦臉地迎上來,“玉大人柿估,你說我怎么就攤上這事循未。” “怎么了秫舌?”我有些...
    開封第一講書人閱讀 165,138評論 0 355
  • 文/不壞的土叔 我叫張陵的妖,是天一觀的道長。 經(jīng)常有香客問我足陨,道長嫂粟,這世上最難降的妖魔是什么? 我笑而不...
    開封第一講書人閱讀 58,791評論 1 295
  • 正文 為了忘掉前任墨缘,我火速辦了婚禮星虹,結(jié)果婚禮上,老公的妹妹穿的比我還像新娘镊讼。我一直安慰自己宽涌,他們只是感情好,可當(dāng)我...
    茶點故事閱讀 67,794評論 6 392
  • 文/花漫 我一把揭開白布蝶棋。 她就那樣靜靜地躺著卸亮,像睡著了一般。 火紅的嫁衣襯著肌膚如雪玩裙。 梳的紋絲不亂的頭發(fā)上兼贸,一...
    開封第一講書人閱讀 51,631評論 1 305
  • 那天,我揣著相機與錄音吃溅,去河邊找鬼溶诞。 笑死,一個胖子當(dāng)著我的面吹牛决侈,可吹牛的內(nèi)容都是我干的螺垢。 我是一名探鬼主播,決...
    沈念sama閱讀 40,362評論 3 418
  • 文/蒼蘭香墨 我猛地睜開眼,長吁一口氣:“原來是場噩夢啊……” “哼甩苛!你這毒婦竟也來了蹂楣?” 一聲冷哼從身側(cè)響起,我...
    開封第一講書人閱讀 39,264評論 0 276
  • 序言:老撾萬榮一對情侶失蹤讯蒲,失蹤者是張志新(化名)和其女友劉穎痊土,沒想到半個月后,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體墨林,經(jīng)...
    沈念sama閱讀 45,724評論 1 315
  • 正文 獨居荒郊野嶺守林人離奇死亡赁酝,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,900評論 3 336
  • 正文 我和宋清朗相戀三年,在試婚紗的時候發(fā)現(xiàn)自己被綠了旭等。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片酌呆。...
    茶點故事閱讀 40,040評論 1 350
  • 序言:一個原本活蹦亂跳的男人離奇死亡,死狀恐怖搔耕,靈堂內(nèi)的尸體忽然破棺而出隙袁,到底是詐尸還是另有隱情,我是刑警寧澤弃榨,帶...
    沈念sama閱讀 35,742評論 5 346
  • 正文 年R本政府宣布菩收,位于F島的核電站,受9級特大地震影響鲸睛,放射性物質(zhì)發(fā)生泄漏娜饵。R本人自食惡果不足惜,卻給世界環(huán)境...
    茶點故事閱讀 41,364評論 3 330
  • 文/蒙蒙 一官辈、第九天 我趴在偏房一處隱蔽的房頂上張望箱舞。 院中可真熱鬧,春花似錦拳亿、人聲如沸晴股。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,944評論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽队魏。三九已至公般,卻和暖如春万搔,著一層夾襖步出監(jiān)牢的瞬間,已是汗流浹背官帘。 一陣腳步聲響...
    開封第一講書人閱讀 33,060評論 1 270
  • 我被黑心中介騙來泰國打工瞬雹, 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留,地道東北人刽虹。 一個月前我還...
    沈念sama閱讀 48,247評論 3 371
  • 正文 我出身青樓酗捌,卻偏偏與公主長得像,于是被迫代替她去往敵國和親。 傳聞我的和親對象是個殘疾皇子胖缤,可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,979評論 2 355