服務(wù)假死問題解決過程實(shí)記（二）——C3P0 數(shù)據(jù)庫連接池配置引發(fā)的血案

接上文《服務(wù)假死問題解決過程實(shí)記（一）——問題發(fā)現(xiàn)篇》

三围详、03.30 Tomcat 假死后續(xù)——C3P0 連接池參數(shù)配置問題

昨晚上正在看有關(guān) B+Tree 相關(guān)的內(nèi)容浪册，收到業(yè)務(wù)組的微信消息：

最帥氣的大龍龍：現(xiàn)場數(shù)據(jù)庫連接不上燎斩，他們排查問題，懷疑與連接池或者日志有關(guān)系绊袋，最后發(fā)現(xiàn)從昨天下午到現(xiàn)在產(chǎn)生 30 萬條日志涤久，其中我們就有 22 萬條，明天查一下我們服務(wù) @琦小蝦

好吧趁冈，那就和師父一起查問題好了歼争。第二天早上拜马，果然數(shù)據(jù)庫組的同事過來和我們說了說情況，說現(xiàn)場傳來的具體情況：現(xiàn)場忽然之間所有業(yè)務(wù)都不能連接 Oracle沐绒，后來查詢了下原因俩莽，看到 Oracle 的監(jiān)聽日志過大，導(dǎo)致所有業(yè)務(wù)不能連接數(shù)據(jù)庫乔遮。后來通過某些手段打開 Oracle 監(jiān)聽日志 (listener.log)扮超，發(fā)現(xiàn)總共產(chǎn)生了 30 萬條日志，我們業(yè)務(wù)組相關(guān)的日志占了 20+ 萬條蹋肮。所以建議我們檢查一下數(shù)據(jù)庫連接池相關(guān)的參數(shù)出刷。

注：Oracle 監(jiān)聽日志文件過大導(dǎo)致無法數(shù)據(jù)庫無法連接的相關(guān)問題參考連接：
《ORACLE的監(jiān)聽日志太大，客戶端無法連接 BUG:9879101》
《ORACLE清理坯辩、截?cái)啾O(jiān)聽日志文件（listener.log）》

數(shù)據(jù)庫組老大專門來我師父的機(jī)器上的 C3P0 的數(shù)據(jù)庫連接池相關(guān)參數(shù)馁龟，大佬感覺沒什么問題（然而是個小坑）。那是為什么呢漆魔？最好的方法還是調(diào)過來開發(fā)環(huán)境的 Oracle 監(jiān)聽日志看看吧坷檩。
經(jīng)過我一番猛如虎的操作，我們把日志分析的準(zhǔn)備工作做好了：

  1. 安裝 XShell 用 sftp 連接 Oracle 所在的 CentOS 服務(wù)器改抡，把數(shù)據(jù)庫監(jiān)聽日志 listener.log 宕到本機(jī)矢炼；
  2. 監(jiān)聽日志記錄了兩個月的日志信息，大小大概有 5 個多 G雀摘；記事本與 NotePad 都不能打開這么大的日志文件；
  3. 由于不能連接外網(wǎng)下載第三方工具八拱，我在網(wǎng)上找了個 Java 方法阵赠，用 NIO 的方法把 5G 的日志文件分成了 200 個文件，這樣就可以進(jìn)行分析了肌稻。
public static void splitFile(String filePath, int fileCount) throws IOException {
    FileInputStream fis = new FileInputStream(filePath);
    FileChannel inputChannel = fis.getChannel();
    final long fileSize = inputChannel.size();
    long average = fileSize / fileCount;//平均值
    long bufferSize = 200; //緩存塊大小清蚀，自行調(diào)整
    ByteBuffer byteBuffer = ByteBuffer.allocate(Integer.valueOf(bufferSize + "")); // 申請一個緩存區(qū)
    long startPosition = 0; //子文件開始位置
    long endPosition = average < bufferSize ? 0 : average - bufferSize;//子文件結(jié)束位置
    for (int i = 0; i < fileCount; i++) {
        if (i + 1 != fileCount) {
            int read = inputChannel.read(byteBuffer, endPosition);// 讀取數(shù)據(jù)
            readW:
            while (read != -1) {
                byteBuffer.flip();//切換讀模式
                byte[] array = byteBuffer.array();
                for (int j = 0; j < array.length; j++) {
                    byte b = array[j];
                    if (b == 10 || b == 13) { //判斷\n\r
                        endPosition += j;
                        break readW;
                    }
                }
                endPosition += bufferSize;
                byteBuffer.clear(); //重置緩存塊指針
                read = inputChannel.read(byteBuffer, endPosition);
            }
        }else{
            endPosition = fileSize; //最后一個文件直接指向文件末尾
        }

        FileOutputStream fos = new FileOutputStream(filePath + (i + 1));
        FileChannel outputChannel = fos.getChannel();
        inputChannel.transferTo(startPosition, endPosition - startPosition, outputChannel);//通道傳輸文件數(shù)據(jù)
        outputChannel.close();
        fos.close();
        startPosition = endPosition + 1;
        endPosition += average;
    }
    inputChannel.close();
    fis.close();

}

public static void main(String[] args) throws Exception {
    long startTime = System.currentTimeMillis();
    splitFile("/Users/yangpeng/Documents/temp/big_file.csv",5);
    long endTime = System.currentTimeMillis();
    System.out.println("耗費(fèi)時間： " + (endTime - startTime) + " ms");
}

好吧，終于可以分析日志了爹谭。

既然所有業(yè)務(wù)組都在和這個 Oracle 連接枷邪，那么就統(tǒng)計(jì)一下幾個流量比較大的服務(wù)的 IP 出現(xiàn)頻率吧。隨手打開分割的 200 個中隨便一個日志 (25M)诺凡，首先用 NotePad 統(tǒng)計(jì)了一下所有業(yè)務(wù)都會訪問的共享數(shù)據(jù) DAO 服務(wù) IP东揣，總共 300+ 的頻率。
我們業(yè)務(wù) DAO 服務(wù)幾個 IP 的頻率呢腹泌？52796 + 140293 + 70802 + 142 = 264033 次……

文件里看到了滿屏熟悉的 IP…… 沒錯嘶卧，這些 IP 就是我們曾經(jīng)以及正在運(yùn)行過 DAO 服務(wù)的四臺主機(jī) IP 地址…… (其中 28.1.25.91 就是區(qū)區(qū)在下臭名昭著的開發(fā)機(jī) IP 地址)

...
22-MAR-2019 13:23:41 * (CONNECT_DATA=(SERVICE_NAME=DBdb)(CID=()(HOST=SC-201707102126)(USER=Administrator))) * (ADDRESS=(PROTOCOL=tcp)(HOST=28.1.25.91)(PORT=53088)) * establish * DBdb * 0
22-MAR-2019 13:23:41 * (CONNECT_DATA=(SERVICE_NAME=DBdb)(CID=()(HOST=SC-201707102126)(USER=Administrator))) * (ADDRESS=(PROTOCOL=tcp)(HOST=28.1.25.91)(PORT=53088)) * establish * DBdb * 0
...

“完了，這次真的要背血鍋了凉袱。哈哈哈哈哈芥吟≌焱”這是我第一反應(yīng)，發(fā)現(xiàn)了服務(wù)的坑钟鸵，我竟然這么興奮哇哈哈哈哈～

隨手選了一個文件就是這樣钉稍，檢查了一下其他分割的日志文件，也全都是這種情況棺耍。但為什么這個日志文件里贡未，我們四個不同的服務(wù)地址總共出現(xiàn)了 26 萬次 IP 地址，其中一個只有 142 次烈掠，和其他三個 IP 頻率差了這么多羞秤？
原來這個 142 次的 IP 是我?guī)煾傅拈_發(fā)機(jī) IP，而且他自己也說不清楚什么時候出于什么思考左敌，把數(shù)據(jù)庫的連接池給改小了（就是數(shù)據(jù)庫組大佬親自檢查后說沒有問題的那組參數(shù)）瘾蛋，然而我和其他小伙伴的 DAO 服務(wù) C3P0 參數(shù)沒有改過，所以只有我們?nèi)_服務(wù)的 IP 地址顯得那么不正常矫限。哈哈哈我?guī)煾腹皇莻€心機(jī) BOY～

注：關(guān)于 C3P0 參數(shù)設(shè)置的相關(guān)內(nèi)容筆者總結(jié)到了另一篇博客里：《C3P0 連接池相關(guān)概念》

之前的 C3P0 參數(shù)是這樣的：

# unit:ms
cpool.checkoutTimeout=60000
cpool.minPoolSize=200
cpool.initialPoolSize=200
cpool.maxPoolSize=500
# unit:s
cpool.maxIdleTime=60
cpool.maxIdleTimeExcessConnections=20
cpool.acquireIncrement=5
cpool.acquireRetryAttempts=3

修改后的 C3P0 參數(shù)是這樣的：

# unit:ms
cpool.checkoutTimeout=5000
cpool.minPoolSize=5
cpool.maxPoolSize=500
cpool.initialPoolSize=5
# unit:s
cpool.maxIdleTime=0
cpool.maxIdleTimeExcessConnections=200
cpool.idleConnectionTestPeriod=60
cpool.acquireIncrement=5
cpool.acquireRetryAttempts=3

04.21 記：cpool.maxIdleTimeExcessConnections=200 依舊是個大坑哺哼，后續(xù)解析。

可以看出來叼风，差距最大的幾個參數(shù)是：

  • cpool.checkoutTimeout: 60000 -> 5000 (單位 ms)
  • cpool.minPoolSize: 200 -> 5
  • cpool.initialPoolSize: 200 -> 5
  • cpool.maxIdleTime: 60 -> 0 (單位 s)

所以取董，可以總結(jié)現(xiàn)場出現(xiàn)的現(xiàn)象如下：

  1. 我們的 DAO 服務(wù)由于設(shè)置了 initialPoolSize 的值為 200，所以 DAO 服務(wù)在一開始啟動的時候无宿，就已經(jīng)和 Oracle 建立了 200 個連接茵汰；
  2. 由于服務(wù)大部分時間都不會有太多人使用，所以運(yùn)行過程中每超過 maxIdleTime 的時間即 60 秒后孽鸡，沒有被使用到的數(shù)據(jù)庫連接被釋放蹂午。一般釋放的連接數(shù)量大約會在 195 ~ 200 個左右；
  3. 剛剛釋放了大量的數(shù)據(jù)庫連接（數(shù)量計(jì)作 size）彬碱，由于 minPoolSize 設(shè)置為 200豆胸，所以立即又會發(fā)起 size 個數(shù)據(jù)庫連接，使數(shù)據(jù)庫連接數(shù)量保持在 minPoolSize 個巷疼；
  4. 每 60s (maxIdleTime) 重復(fù) 2~3 步驟晚胡；

所以現(xiàn)場的 Oracle 的監(jiān)聽日志也會固定每 60 秒 (maxIdleTime) 添加約 200 條，運(yùn)行了一段時間后嚼沿，就出現(xiàn)了 Oracle 監(jiān)聽日志過大（一般情況下指一個 listener.log 監(jiān)聽文件大于 4G）估盘，Oracle 數(shù)據(jù)庫無法被連接的情況。

所以骡尽，前面三月六日我發(fā)現(xiàn)的大量出現(xiàn) 1521 端口的 TIME_WAIT忿檩，就應(yīng)該是 DAO 服務(wù)端檢測到有 200 個空閑連接，便為這些連接向數(shù)據(jù)庫發(fā)送關(guān)閉請求爆阶，然后這些連接在等待 maxIdleTime 時間的過程中就進(jìn)入了 TIME_WAIT 狀態(tài)燥透。釋放這些連接后由于 minPoolSize 設(shè)置值為 200沙咏，所以又重新發(fā)起了約 200 個新的數(shù)據(jù)庫連接。所以我如果在 cmd 中隨一定時間周期 (每 60s) 輸入 netstat -ano
| findstr "1521" 的指令班套，列出來的與數(shù)據(jù)庫 1521 端口應(yīng)該是變動的肢藐。

TCP 四次分手示意圖

至此，數(shù)據(jù)庫連接池的問題應(yīng)該是解決了吱韭。但我認(rèn)為服務(wù)假死問題應(yīng)該不是出在這里吆豹。目前懷疑的問題，有因?yàn)樘摂M機(jī)開啟了 -XDebug, -Xrunjdwp 參數(shù)理盆，也可能是由于我們使用線程池的方式有誤痘煤。還是需要繼續(xù)進(jìn)一步檢查啊。

四猿规、04.15 100 插入并發(fā)假死問題——C3P0 連接池參數(shù)配置問題

參考地址：
《c3p0 不斷的輸出debug錯誤信息》

很長一段時間里衷快，在忙一些其他雜事，沒有時間開發(fā)姨俩。終于把雜事忙完之后蘸拔，筆者和師父在修正了 C3P0 參數(shù)之后，開始嘗試測試并發(fā)性能环葵。
用 LoadRunner 寫了一個腳本调窍，同時 50 個用戶并發(fā)插入一條數(shù)據(jù)，無思考時間的插入一分鐘张遭。腳本跑起來之后邓萨，很快服務(wù)就出現(xiàn)了問題。

首先菊卷，DAO 服務(wù)直接完全假死缔恳。而且由于筆者在虛擬機(jī)參數(shù)中添加了 -XX:+PrintGCDetails 參數(shù)，觀察到打印出來的 GC 日志的烁，竟然有一秒鐘三到四次的 FullGC褐耳！而且虛擬機(jī)的舊生代已經(jīng)完全被填滿诈闺，每次 FullGC 幾乎完全沒有任何的釋放渴庆。此外，DAO 服務(wù)也會偶爾報(bào)出 OutofMemoryError雅镊，只是沒有引起虛擬機(jī)崩潰而已襟雷。
當(dāng)然，軟件服務(wù)也由于大量的插入無響應(yīng)仁烹，報(bào)出了大量的 Read Time Out 錯誤耸弄。

開始分析問題的時候，筆者也是一臉懵逼卓缰。打開 JVisualVM 監(jiān)控 Java 堆计呈，反復(fù)試了多次砰诵，依舊是長時間的內(nèi)存不釋放的現(xiàn)象。正當(dāng)有一次對著 JVisualVM 監(jiān)控畫面發(fā)呆捌显，發(fā)呆到執(zhí)行并發(fā)腳本幾分鐘之后茁彭，忽然我看到有一次 FullGC 直接令 Java 堆有了一次斷崖式的下降，堆內(nèi)存直接下降了 80%７鐾帷理肺！
我當(dāng)時就意識到這就是問題的突破點(diǎn)。所以由重新跑了一次并發(fā)腳本復(fù)現(xiàn)問題善镰。再次卡死時妹萨，我用 jmap 指令把堆內(nèi)存 Dump 下來，加載到前幾天準(zhǔn)備好的 Eclipse 插件 Memory Analyse Tool (MAT) 中進(jìn)行分析炫欺。
果然看到了很異常的 HeapDump 餅圖：1.5G 的堆內(nèi)存乎完，有 70%-80% 的容量都在存著一個名為 newPooledConnection 的對象，這種對象的數(shù)量大概有 60 個竣稽，每個對象大小 20M 左右囱怕。這個對象是在 c3p0 的包里，所以用腳指頭想就知道毫别，肯定是我們的 C3P0 配置還有問題娃弓。

查了一下 C3P0 的配置參數(shù)，觀察到有一條信息：

  • maxIdelTimeExcessConnections: 這個配置主要是為了快速減輕連接池的負(fù)載岛宦，比如連接池中連接數(shù)因?yàn)槟炒螖?shù)據(jù)訪問高峰導(dǎo)致創(chuàng)建了很多數(shù)據(jù)連接台丛，但是后面的時間段需要的數(shù)據(jù)庫連接數(shù)很少，需要快速釋放砾肺，必須小于 maxIdleTime挽霉。其實(shí)這個沒必要配置，maxIdleTime 已經(jīng)配置了变汪。

而此時我看了一眼我們的 C3P0 參數(shù)侠坎，有這樣兩個參數(shù)：

cpool.maxIdleTime=0
cpool.maxIdleTimeExcessConnections=200

所以由于 cpool.maxIdleTimeExcessConnections=200 這個參數(shù)，在并發(fā)發(fā)生之后裙盾，C3P0 持續(xù)持有并發(fā)后產(chǎn)生的數(shù)據(jù)庫連接实胸，直到 200s 之內(nèi)沒有再復(fù)用到這些連接，才會將其釋放番官。所以我之前發(fā)呆后忽然的斷崖式內(nèi)存釋放庐完，肯定就是因?yàn)檫@個原因……

果然把 maxIdleTime, maxIdleTimeExcessConnections 都設(shè)置為 0，并發(fā)插入立即變得順滑了很多徘熔。
至此门躯，DAO 服務(wù)最重要的問題找到，對它的優(yōu)化過程基本告一段落酷师。但我們的服務(wù)依舊有很多待優(yōu)化的點(diǎn)讶凉，也有很多業(yè)務(wù)邏輯可以優(yōu)化染乌，這是后面一段時間需要考慮的問題。

未完待續(xù)懂讯。下篇《服務(wù)假死問題解決過程實(shí)記（三）——緩存問題優(yōu)化》

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 人面猴
    序言：七十年代末慕匠，一起剝皮案震驚了整個濱河市，隨后出現(xiàn)的幾起案子域醇，更是在濱河造成了極大的恐慌台谊，老刑警劉巖，帶你破解...
    沈念sama閱讀 206,378評論 6贊 481
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件譬挚，死亡現(xiàn)場離奇詭異锅铅，居然都是意外死亡，警方通過查閱死者的電腦和手機(jī)减宣，發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 88,356評論 2贊 382
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進(jìn)店門盐须，熙熙樓的掌柜王于貴愁眉苦臉地迎上來，“玉大人漆腌，你說我怎么就攤上這事贼邓。” “怎么了闷尿？”我有些...
    開封第一講書人閱讀 152,702評論 0贊 342
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵塑径，是天一觀的道長。 經(jīng)常有香客問我填具，道長统舀，這世上最難降的妖魔是什么？ 我笑而不...
    開封第一講書人閱讀 55,259評論 1贊 279
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任劳景，我火速辦了婚禮誉简，結(jié)果婚禮上，老公的妹妹穿的比我還像新娘盟广。我一直安慰自己闷串，他們只是感情好，可當(dāng)我...
    茶點(diǎn)故事閱讀 64,263評論 5贊 371
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布筋量。 她就那樣靜靜地躺著烹吵，像睡著了一般。 火紅的嫁衣襯著肌膚如雪毛甲。 梳的紋絲不亂的頭發(fā)上年叮，一...
    開封第一講書人閱讀 49,036評論 1贊 285
  • 城市分裂傳說
    那天具被，我揣著相機(jī)與錄音玻募，去河邊找鬼。 笑死一姿，一個胖子當(dāng)著我的面吹牛七咧，可吹牛的內(nèi)容都是我干的跃惫。 我是一名探鬼主播，決...
    沈念sama閱讀 38,349評論 3贊 400
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼艾栋，長吁一口氣：“原來是場噩夢啊……” “哼爆存！你這毒婦竟也來了？” 一聲冷哼從身側(cè)響起蝗砾，我...
    開封第一講書人閱讀 36,979評論 0贊 259
  • 萬榮殺人案實(shí)錄
    序言：老撾萬榮一對情侶失蹤先较，失蹤者是張志新（化名）和其女友劉穎，沒想到半個月后悼粮，有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體闲勺，經(jīng)...
    沈念sama閱讀 43,469評論 1贊 300
  • ?護(hù)林員之死
    正文 獨(dú)居荒郊野嶺守林人離奇死亡，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 35,938評論 2贊 323
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年扣猫，在試婚紗的時候發(fā)現(xiàn)自己被綠了菜循。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點(diǎn)故事閱讀 38,059評論 1贊 333
  • 活死人
    序言：一個原本活蹦亂跳的男人離奇死亡申尤，死狀恐怖癌幕，靈堂內(nèi)的尸體忽然破棺而出，到底是詐尸還是另有隱情昧穿，我是刑警寧澤勺远，帶...
    沈念sama閱讀 33,703評論 4贊 323
  • ?日本核電站爆炸內(nèi)幕
    正文 年R本政府宣布，位于F島的核電站时鸵，受9級特大地震影響谚中，放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜寥枝，卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 39,257評論 3贊 307
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一宪塔、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧囊拜，春花似錦某筐、人聲如沸。這莊子的主人今日做“春日...
    開封第一講書人閱讀 30,262評論 0贊 19
  • 一樁弒父案南誊，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽。三九已至蜜托，卻和暖如春抄囚，著一層夾襖步出監(jiān)牢的瞬間，已是汗流浹背橄务。 一陣腳步聲響...
    開封第一講書人閱讀 31,485評論 1贊 262
  • 情欲美人皮
    我被黑心中介騙來泰國打工幔托， 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留，地道東北人。 一個月前我還...
    沈念sama閱讀 45,501評論 2贊 354
  • 代替公主和親
    正文 我出身青樓重挑，卻偏偏與公主長得像嗓化，于是被迫代替她去往敵國和親。 傳聞我的和親對象是個殘疾皇子谬哀，可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 42,792評論 2贊 345