背景

由于項(xiàng)目要求99.9%可用性，而此次事故導(dǎo)致宕機(jī)了五個(gè)小時(shí)，以后每個(gè)季度只能有一個(gè)小時(shí)的不可用時(shí)間。正好問(wèn)題的排查一直都屬于程序員的寶貴經(jīng)驗(yàn)，因此就在這記錄下來(lái)。

發(fā)生的現(xiàn)象：
上午10點(diǎn)鐘左右，開(kāi)始出現(xiàn)頁(yè)面訪問(wèn)異常情況，檢查發(fā)現(xiàn)某個(gè)服務(wù)每間隔一段時(shí)間就會(huì)重啟一會(huì)。后續(xù)觀察是每固定20分鐘就會(huì)被k8s重啟一次。
出現(xiàn)了異常重啟的情況，首先就要查明異常的原因，直接原因比如CPU、內(nèi)存等原因，間接原因就是看是哪里引起的每20分鐘重啟。

排查過(guò)程

1、Grafana監(jiān)控報(bào)表

在Grafana上看到，基本在重啟前的邊緣上的情況：

1. CPU比較正常，一直都是處于較低的使用率水平。
2. JVM內(nèi)存在有幾次重啟前都接近滿了，可能能夠被回收，但還沒(méi)有觸發(fā)Major GC，是個(gè)值得排查的地方，同時(shí)得去看看日志中有沒(méi)有out of memory的報(bào)錯(cuò)日志。
3. Tomcat連接池的線程數(shù)都滿了，達(dá)到最大的使用數(shù)量了，因?yàn)槲覀冞@里使用的默認(rèn)的配置，200個(gè)就已經(jīng)滿了。這是最大的嫌疑。

在上面三點(diǎn)基本看來(lái)最應(yīng)該排查的就是Tomcat連接池。

2、存活探針相關(guān)Yaml

可能有人會(huì)覺(jué)得，就算連接池滿了，或者JVM發(fā)生out of memory了，都不應(yīng)該會(huì)直接導(dǎo)致服務(wù)的重啟，這里因?yàn)槲覀冇玫氖莐8s，配置了服務(wù)的就緒探針和存活探針，每隔10秒鐘調(diào)用一次服務(wù)的接口來(lái)確保服務(wù)存活。當(dāng)失敗超過(guò)3次以后就會(huì)認(rèn)為這個(gè)服務(wù)已經(jīng)死亡，就會(huì)開(kāi)始重新啟動(dòng)一個(gè)Pod，并remove掉原來(lái)的Pod。所以才出現(xiàn)了這樣的情況。

livenessProbe:
          failureThreshold: 3
          httpGet:
            path: /actuator/health
            port: 9902
            scheme: HTTP
          initialDelaySeconds: 60
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 10

首先我們是先調(diào)大了重啟的服務(wù)的Tomcat并發(fā)連接數(shù)到500，但是發(fā)現(xiàn)了一點(diǎn)，即使連接數(shù)從200上升到了500，服務(wù)依舊在不斷重啟當(dāng)中。

那么就再來(lái)排查是什么占用了如此多的連接數(shù)，每間隔20分鐘出現(xiàn)一次，基本上能夠確定是某個(gè)定時(shí)任務(wù)引起的，再查看Grafana上相關(guān)http請(qǐng)求調(diào)度頻率，最終定位到了問(wèn)題，同時(shí)看到那邊的代碼寫法也是有問(wèn)題的。

3、tomcat線程池與數(shù)據(jù)庫(kù)連接池

本來(lái)是一個(gè)要批量獲取數(shù)據(jù)的功能，由于之前就存在了feignClient的查詢單個(gè)數(shù)據(jù)的接口，于是這里為了圖方便，便直接使用了這個(gè)接口，而不是新增一個(gè)批量查詢數(shù)據(jù)的接口。正好又是因?yàn)槎啻蔚牟樵儽容^慢，所以該同事使用了多線程異步的方式去獲取數(shù)據(jù)，每有一個(gè)id，都會(huì)開(kāi)啟一個(gè)線程去查詢，當(dāng)有幾百上千條數(shù)據(jù)的時(shí)候，就會(huì)有大量的線程同時(shí)請(qǐng)求過(guò)去，從而造成了目標(biāo)服務(wù)的Tomcat連接數(shù)不足的問(wèn)題。
業(yè)務(wù)代碼類似下面示例：

			for (int i = 0; i < list.size(); i++) {
				CompletableFuture<String> future=CompletableFuture.runAsync(()->
				//調(diào)用重啟服務(wù)的接口
				);
			}

但是有一個(gè)問(wèn)題就是，Tomcat并發(fā)連接數(shù)提高到了500了，一個(gè)接口訪問(wèn)不到1秒鐘的時(shí)間，最多也不過(guò)幾百上千的請(qǐng)求次數(shù)，按理來(lái)說(shuō)在幾秒之內(nèi)處理完這些請(qǐng)求，不應(yīng)該會(huì)再出現(xiàn)這樣的情況才對(duì)，然而k8s在連續(xù)的三次存活探測(cè)中依然都直接超時(shí)了。那么除了Tomcat并發(fā)連接數(shù)，還有什么會(huì)拖慢請(qǐng)求呢？

所以就排查到了數(shù)據(jù)庫(kù)最大連接數(shù)，目前數(shù)據(jù)庫(kù)的最大連接數(shù)被設(shè)置成了20，不論你Tomcat連接數(shù)設(shè)置的多大，系統(tǒng)的性能值取決于最短板的地方，而這個(gè)就是數(shù)據(jù)庫(kù)最大連接數(shù)，由于我們的系統(tǒng)是TOB服務(wù)，這個(gè)服務(wù)是查詢和業(yè)務(wù)對(duì)接的，頁(yè)面對(duì)接的信息，并不是處理數(shù)據(jù)的服務(wù)，因此大家之前也沒(méi)有對(duì)這個(gè)服務(wù)的配置有過(guò)太多關(guān)注，才導(dǎo)致了這種情況。那么首先要做的就是提高數(shù)據(jù)庫(kù)連接池最大連接數(shù)到100，同時(shí)將那個(gè)異步多次調(diào)用接口的定時(shí)任務(wù)進(jìn)行優(yōu)化，就解決這個(gè)問(wèn)題了。

4、堆棧信息與Jprofile的使用

除了對(duì)連接池等做了一些排查之外，同時(shí)我們還對(duì)JVM堆內(nèi)存進(jìn)行了分析，排除JVM的問(wèn)題。
其實(shí)一般情況下當(dāng)發(fā)生內(nèi)存無(wú)法正常回收的情況，是能夠直接在服務(wù)日志中看到 java.lang.OutOfMemoryError: Java heap space的對(duì)內(nèi)存溢出的日志的，因此只需要打開(kāi)JVM heap dump on out of memory的參數(shù)即可，那么在發(fā)生堆內(nèi)存溢出時(shí)，就會(huì)將當(dāng)時(shí)的快照保存下來(lái)。

不過(guò)我們那暫時(shí)沒(méi)有出現(xiàn)內(nèi)存溢出的錯(cuò)誤日志。一個(gè)就是考慮到發(fā)生內(nèi)存溢出，我記得是在多少次GC之內(nèi)回收率小于某個(gè)固定閾值之后才會(huì)拋出異常，它并不是一瞬間就會(huì)發(fā)生的，所以那么會(huì)不會(huì)在這之前k8s就將Pod重啟了呢也說(shuō)不準(zhǔn)。

我們選取了POD重啟前夕的情況作為快照手動(dòng)導(dǎo)了出來(lái)進(jìn)行分析。使用JProfiler工具進(jìn)行分析。
基本上只需要看兩個(gè)東西就行了。
一個(gè)是占用內(nèi)存和數(shù)量最多的是哪些類，尤其是關(guān)注其中和我們業(yè)務(wù)相關(guān)的類：

還有一個(gè)就是關(guān)注大對(duì)象，這也是最值得關(guān)注的：

可以看到，上述圖片基本顯示了這些對(duì)象基本沒(méi)有和我們業(yè)務(wù)相關(guān)的類，如果這是heap dump on out of memory拿出來(lái)的快照，而某些業(yè)務(wù)相關(guān)類占了很大內(nèi)存和數(shù)量，那這就是我們極為需要關(guān)注的。

再就是Biggest Objects這張圖，產(chǎn)生內(nèi)存溢出的原因，基本就直接在這里面了，因?yàn)閷?dǎo)致內(nèi)存溢出的直接原因就是因?yàn)橛写蟮膶?duì)象不能夠即使回收，現(xiàn)在基本對(duì)象回收都是可達(dá)性分析法，上面的最大類基本也就是大量對(duì)象的根引用所在，下面掛了一大群因此而不能回收的對(duì)象，我們可以直接點(diǎn)擊一直往下，排查到與業(yè)務(wù)代碼中相關(guān)的原因。

因?yàn)槲疫@里并沒(méi)有發(fā)生內(nèi)存溢出，就拿spring下的DefaultListableBeanFactory簡(jiǎn)單舉個(gè)例子


如DefaultListableBeanFactory下大部分的內(nèi)存占用就是這個(gè)beanDefinitionMap的HashMap所占用的內(nèi)存，這個(gè)Map下又是由他的Node節(jié)點(diǎn)占用了大部分內(nèi)存。

我們可以直接在Jprofiler中點(diǎn)擊+號(hào)一直往下找，就很容易從根節(jié)點(diǎn)一直循著引用鏈找到與我們業(yè)務(wù)代碼相關(guān)的問(wèn)題點(diǎn)在哪了。