close
文章出處

我們本身是一家互聯網金融公司，公司的主流業務就是p2p，因為各種原因吧，15年底啟動建設眾籌平臺。考慮到前期開發過程中的一些弊端和架構經驗，本次架構引用了dubbo做soa服務的治理，web容器nginx+tomcat，后端語言采用java,框架選擇spring+mybaits,前端模板引擎使用的是btl,app采用原生+h5的模式。這個架構可以參考我之前寫的文章從零到百億互聯網金融架構發展史中的第三代系統架構,之前的文章主要介紹了架構的變遷，本篇文章主要介紹在第三代平臺中遇到的問題以及解決方法。

首先介紹一下眾籌系統的部署架構（如下圖），網站和app請求都是首先到最前端的nginx,如果只是靜態內容的訪問nginx直接處理后返回；動態請求分別轉發到后端的tomcat前端服務層，前端服務層只關注頁面端業務邏輯不涉及數據庫的操作，如果只是頁面框架渲染以及不涉及數據庫的請求，在前端服務層直接處理返回；如果涉及到數據庫操作或者核心業務邏輯，前端服務層通過dubbo調用后端的接入層服務或者核心層服務。

上線在生產測試期間，發現tomcat過一段時間就會莫名奇妙的down掉，特別是后端的tomcat down掉的頻率比較高。后端的tomcat down掉之后對前端的頁面展示沒有影響，會影響后端的交易。


jvm參數配置

查看tomcat業務日志，報錯如下：

2016-04-14 12:01:55,025 - org.jboss.netty.channel.DefaultChannelPipeline -59679839 [New I/O worker #29] WARN  null -  [DUBBO] An exception was thrown by a user handler while handling an exception event ([id: 0x5f980c11, /xxx:55386 => /xxx:6666] EXCEPTION: com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process received event .), dubbo version: 2.8.4, current host: xxx
com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process caught event .
    at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:67)
    at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
    at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
    at com.alibaba.dubbo.remoting.transport.AbstractPeer.caught(AbstractPeer.java:127)
    at com.alibaba.dubbo.remoting.transport.netty.NettyHandler.exceptionCaught(NettyHandler.java:112)
    at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.exceptionCaught(NettyCodecAdapter.java:165)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525)
    at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:48)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
    at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.messageReceived(NettyCodecAdapter.java:148)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
    at java.lang.Thread.start0(Native Method)
    at java.lang.Thread.start(Thread.java:714)
    at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:949)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1360)
    at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:65)
    ... 19 more

查看output日志，發現其中有這么一句。

SEVERE: The web application [/xxx] appears to have started a thread named [DubboResponseTimeoutScanTimer] but has failed to stop it. This is very likely to create a memory leak.

根據日志提示貌似有內存泄露，以前確實還沒有碰到過這個錯誤，一片迷茫。重新啟動后，先用命令jstat -gc xxx 1000 30查看java 進程的gc情況，發現在30秒的世界內minor gc了n次，隨懷疑年輕代內存配置少了，查看個區域內存的配置參數如下：

-Xms10g -Xmx10g -XX:PermSize=1g -XX:MaxPermSize=2g -Xshare:off -Xmn1024m

按照年輕代為堆內存為百分之三的原則修改為-Xmn4g，重新啟動觀察之后mimor gc的頻率確實有所下降，測試大約過了3小時候之后又反饋tomcat down掉了，繼續分析啟動參數配置的時候發現了這么一句-XX:-+DisableExplicitGC,顯示的禁止了System.gc(),但是使用了java.nio的大量框架中使用System.gc()來執行gc期通過full gc來強迫已經無用的DirectByteBuffer對象釋放掉它們關聯的native memory,如果禁用會導致OOM,隨即懷疑是否是這個參數引發的問題，在啟動參數中去掉它。

為了防止再次出現異常的時候能更加詳細的分析堆內存的使用情況，在啟動參數中添加了-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/local/logs/java/，當tomcat down的時候讓輸出堆內存文件，一邊也啟動jvisualvm工具來實時的監控內存各個線程的使用情況。


數據庫連接池

繼續使用壓測工具來壓測，在壓測的過程中發現名為com.mchange.v2.resourcepool.ssync.ThreadPoolAsynchronousRunner$PoolThred-#xxx的線程不斷的增長，并且后臺tomcat報錯如下：

2016-04-13 16:55:15,175 - com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport -83649035 [New I/O worker #27] WARN  -  [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-xxx:6666, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 692 (completed: 492), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://xxx:6666!, dubbo version: 2.8.4, current host: xxx
2016-04-13 16:55:15,176 - com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport -83649036 [New I/O worker #27] WARN  -  [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-xxx:6666, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 692 (completed: 492), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://xxx:6666!, dubbo version: 2.8.4, current host: xxx
2016-04-13 16:55:15,177 - org.jboss.netty.channel.DefaultChannelPipeline -83649037 [New I/O worker #27] WARN  -  [DUBBO] An exception was thrown by a user handler while handling an exception event ([id: 0x2f345d45, /192.168.57.20:36475 => /xxx:6666] EXCEPTION: com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process received event .), dubbo version: 2.8.4, current host: xxx
com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process caught event .
    at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:67)
    at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
    at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
    at com.alibaba.dubbo.remoting.transport.AbstractPeer.caught(AbstractPeer.java:127)
    at com.alibaba.dubbo.remoting.transport.netty.NettyHandler.exceptionCaught(NettyHandler.java:112)
    at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.exceptionCaught(NettyCodecAdapter.java:165)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525)
    at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:48)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
    at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.messageReceived(NettyCodecAdapter.java:148)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.util.concurrent.RejectedExecutionException: Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-xxx:6666, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 692 (completed: 492), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://xxx:6666!
    at com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport.rejectedExecution(AbortPolicyWithReport.java:53)
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
    at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:65)
    ... 19 more

根據這些信息隨懷疑數據庫連接池有問題，為了更好的監控連接池的使用，因此前期使用c3p0也會出現的一些問題，所以我們決定將數據庫連接池替換成druid，已經在別的項目中使用測試過，因此非常快速的更換投產。投產后繼續用壓測工具來測試，根據druid的后臺監控頁面發現（項目地址/druid/index.html），每次前端掉用一次數據庫連接就加一次,執行完成之后數據庫連接并沒有釋放。如下圖紅色區域，我們將數據庫連接池調整成1000,不一會就占滿了。

根據這些信息判斷出，數據庫執行sql后肯定沒有釋放數據庫連接，導致數據庫連接池用滿后，后續的線程無法執行，檢查代碼之后發現果然有問題,請看下方代碼，我們最先使用的是SqlSessionFactory，如果使用SqlSessionFactory,在執行完sql后必須要執行session.close()來關閉連接，才會被連接池重新回收。

public class SessionFactory {
    @Resource
    private SqlSessionFactory coreSqlSessionFactory;
    protected SqlSession getSession() {
        return coreSqlSessionFactory.openSession();
    }
}
public class BaseDao extends SessionFactory{
    public void add(Entity entity) {
        this.getSession().update(entity.getClass().getSimpleName()+"."+Thread.currentThread().getStackTrace()[2].getMethodName(), entity);
    }
}

但是使用SqlSessionTemplate卻不用手動執行代碼來關閉session,因此我們把上面SessionFactory類中的代碼改成SqlSessionTemplate（如下），此問題便解決了。

public class SessionFactory {
    @Resource  
    public SqlSessionTemplate coreSqlSession;
    protected SqlSessionTemplate getSession() {
        return coreSqlSession;
    }
}


詭異的腳本

做完上面的優化之后，我們感覺問題應該解決了，但過了一段時間后tomcat又詭異的掛了，繼續分析gc情況，分階段使用jmap -dump:live,format=b,file=dump.hprof xxx命令生成堆轉儲快照來對比堆內存使用情況，監控線程使用情況，均發現沒有問題。這個問題困擾了我們好幾天，每天都監控這端口，一但發現tomcat down之后馬上通知運營人員重啟。一方面我們也查閱了各種資料，到網上查找各種tomcat自動down的原因，一一在我們服務器進行了測試、修復均不起作用。

終于在google各種tomcat down原因的時候發現了這么一篇文章Tomcat進程意外退出的問題分析,立刻想起了我們最近使用的一個腳本來，因為我們的tomcat禁止了通過bat文件來關閉，因此為了啟動方便我們寫了一個腳本文件，方便通過腳本來啟動、停止、重啟tomcat文件，這是這個腳本導致tomcat down的原因，不不，不叫原因叫元兇！腳本內容如下：

#!/bin/sh
# eg: tomcat.sh start xxx
#
proc_dir="/usr/local/xxx/tomcat-zc-web/bin"
proc_name=$2
if [ x$proc_name != x ]
then
    proc_dir=${proc_dir//xxx/$proc_name}
fi
#echo $proc_dir
function stop () {
  kill -9 `ps -ef |grep $proc_dir |grep -v grep|awk '{print $2}'`
}

function start () {
  cd $proc_dir
  ./startup.sh
  tail -300f /usr/local/logs/tomcat-business/$proc_name.log
}

case $1 in 
  start)
    start;;
  stop)
    stop;;
  restart)
    stop
    start;;
esac

就是因為tail -300f /usr/local/logs/tomcat-business/$proc_name.log這一句導致的問題，在別的項目使用的時候其實是沒有這一句的，一般在使用的步驟是：

  • 1 執行tomcat.sh start xxx啟動tomcat,
  • 2 執行tail -300f /usr/local/logs/tomcat-business/xxx.log 查看啟動日志是否成功。

在這次投產的時候為了省一步操作，就將執行查看日志的命令，直接加在了啟動命令的后面，當執行tomcat.sh start xxx這個命令的時候，即啟動的tomcat，也自動會打印出tomcat的日志，那時候的想法非常好。

原因是，使用腳本命令啟動后因為使用了tail -300f xxx 命令，tomcat的進程會成為shell腳本的子進程，這樣的話，如過shell腳本停止的話，系統會自動殺掉tomcat進程導致tomcat down掉，在我們的腳本中去掉這條命令tomcat就正常了，更深層次的原因參考Tomcat進程意外退出的問題分析這篇文章，文章的內容還是分析的比較透徹，最后感覺阿里的技術真的很牛X，這篇文章也是出自于阿里的員工。

經歷這么些波折，后續的tomcat服務終于穩定了下來

作者：純潔的微笑
出處：http://www.ityouknow.com/
版權歸作者所有，轉載請注明出處


文章列表


不含病毒。www.avast.com
arrow
arrow
    全站熱搜

    AutoPoster 發表在 痞客邦 留言(0) 人氣()

    E-mail轉寄