問題現(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
Old Gen
從上圖可以發(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才能夠回收這批對象
先簡單在線上觀察了一波,排第2的HashMap$Node看起來比較異常赡矢,但是看不出更詳細(xì)的情況了杭朱。最好的辦法還是將內(nèi)存快照dump出來,使用MAT分析一波
使用MAT打開之后吹散,可以發(fā)現(xiàn)很明顯的問題:
這個類占用了80%以上的內(nèi)存弧械,那么這個類是干嘛的呢?看類名就知道空民,應(yīng)該是MySQL Driver中用來清理過期連接的一個線程刃唐。讓我們看一下源碼:
這個類是一個單例,會且僅會開一個線程界轩,用來清理那些沒有被顯式的關(guān)閉的數(shù)據(jù)庫連接画饥。
可以看到這個類里面維護了一個Set
對應(yīng)我們上面看到的內(nèi)存占用率排第二的HashMapNode基本上可以確定大概率是這里存在內(nèi)存泄露了。在MAT上使用list_object確認(rèn)一發(fā):
果然沒錯浊猾,罪魁禍?zhǔn)渍业搅硕陡剩∧敲此锩娲娴氖巧稏|西呢?為什么一直增長且無法被YoungGC回收葫慎?看名字
ConnectionFinalizerPhantomReference 我們可以猜到它里面保存的應(yīng)該是數(shù)據(jù)庫連接的phantom引用
什么是phantom reference? 當(dāng)一個對象只有phantom reference引用時衔彻,則會在虛擬機GC時被回收薇宠,同時會將phantom reference的對象放入一個referenceQueue中。
果然是PhantomReference米奸,里面存放的是創(chuàng)建的MySQL連接昼接,看一下是在哪里被放進(jìn)來的:
可以看到,每次創(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六荒,以下為連接池配置:
可以看到是設(shè)置了keepAlive护姆,且
理論上來說砚亭,連接池是不會頻繁的創(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)的配置啥酱?
果然爹凹,數(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的有效性前标,避免一直重建連接即可坠韩。