通過(guò)Carte服務(wù)對(duì)kettle轉(zhuǎn)換進(jìn)行壓力測(cè)試，以20并發(fā)為基準(zhǔn)，通過(guò)不斷的優(yōu)化，對(duì)比測(cè)試結(jié)果如下：

20并發(fā)測(cè)試結(jié)果(持續(xù)7分鐘)	無(wú)Redis	加Redis	優(yōu)化Carte內(nèi)存 使用配置	加CPU和內(nèi)存 （壓15小時(shí)）
Total Throughput (bytes) 總吞吐量	5,079,582	111,814,589	703,321,332	?
Average Throughput (bytes/second) 吞吐率	11,624	264,963	1,798,776	?
Total Hits?總點(diǎn)擊量	1,458	7,245	17,615	?
Average Hits per Second 點(diǎn)擊率	3.336	17.168	45.051	?
Average Response Time 平均響應(yīng)時(shí)間	22.608秒	4.366秒	1.645秒	1.378秒
90 Percent Response Time 90%請(qǐng)求響應(yīng)時(shí)間	35.614秒	22.959秒	3.828秒	2.351秒
executeTrans Transaction Pass 交換事務(wù)處理量（事務(wù)吞吐量）	290	1449	3523	?
Carte服務(wù)器平均CPU使用率	5.7% (Carte參數(shù)優(yōu)化前為90%)	10~30%	85%~90% （壓力過(guò)大）	45%~70%
Carte服務(wù)器內(nèi)存使用率	70~80% （飽和）	70~80% （飽和）	70~80% （飽和）	50%~60%
MySql?平均CPU使用率	60% (MySql緩存優(yōu)化前為100%)	40%	2% （MySql無(wú)壓力）	2%

以上測(cè)試結(jié)果包括的具體優(yōu)化過(guò)程有：Mysql開啟查詢緩存、Carte日志緩存時(shí)間配置、加Redes、優(yōu)化Carte內(nèi)存使用配置（將max_log_timeout_minutes和Object_timeout_minutes都縮小配置為1分鐘）、加CPU和加內(nèi)存、優(yōu)化配置JVM配置調(diào)優(yōu)（根據(jù)內(nèi)存大小重新將spoon.sh文件中的JVM堆內(nèi)存參數(shù)-Xms -Xmx優(yōu)化設(shè)置）。

確認(rèn)優(yōu)化結(jié)果有效后（能夠穩(wěn)定運(yùn)行15小時(shí)），再以20并發(fā)進(jìn)行更長(zhǎng)時(shí)間穩(wěn)定性測(cè)試，持續(xù)壓力測(cè)試到20天后出現(xiàn)崩潰，由于崩潰的時(shí)間點(diǎn)和引起崩潰原因一時(shí)難以定位，重新改變壓力測(cè)試的策略（測(cè)試前開發(fā)人員再做一些優(yōu)化，主要是解除和排除日志中出現(xiàn)的一些異常錯(cuò)誤，如轉(zhuǎn)換過(guò)程拋出的異常；并同時(shí)開啟轉(zhuǎn)換使用唯一連接），然后進(jìn)行100并發(fā)持續(xù)壓力測(cè)試（加大并發(fā)數(shù)可以實(shí)現(xiàn)空間換時(shí)間，縮短壓測(cè)時(shí)間，以便盡快定位影響穩(wěn)定性問(wèn)題的原因），同時(shí)開啟jvm監(jiān)控，開啟所有服務(wù)和數(shù)據(jù)庫(kù)監(jiān)控。

測(cè)試腳本日夜不間斷跑測(cè)，到第二天早上看監(jiān)控結(jié)果，就發(fā)現(xiàn)系統(tǒng)真的崩潰了。

一、通過(guò)Loadrunner能夠看到運(yùn)行13個(gè)小時(shí)后出現(xiàn)異常崩潰

二、通過(guò)Carte服務(wù)的CPU監(jiān)控，能夠看到早上7點(diǎn)鐘前出現(xiàn)壓力突然上升，并且無(wú)法降低

三、獲取JVM監(jiān)控的歷史報(bào)告（JVM監(jiān)控已異常斷開連接），從連接時(shí)間、線程數(shù)、堆內(nèi)存（無(wú)法回收內(nèi)存）的變化情況，也能看出7點(diǎn)左右出現(xiàn)反常情況

四、通過(guò)監(jiān)控MySQL（有兩個(gè)mysql，一個(gè)是資源庫(kù)，一切正常，一個(gè)是交換庫(kù)出現(xiàn)異常），發(fā)現(xiàn)7點(diǎn)左右出現(xiàn)大量斷開的連接

五、對(duì)交換庫(kù)的監(jiān)控，發(fā)現(xiàn)快到7點(diǎn)時(shí)，壓力突然降低，這與上面的異常相符合

六、日志定位問(wèn)題

通過(guò)上面的監(jiān)控，可以判斷，系統(tǒng)在7點(diǎn)前15分鐘左右，應(yīng)該出現(xiàn)故障，這就需要通過(guò)日志定位這個(gè)時(shí)段，以找到具體原因

最后在Carte服務(wù)的日志中找到答案，第一次出現(xiàn)連接錯(cuò)誤的時(shí)間點(diǎn)是06:44:50.273，報(bào)的是Too many connections

然后錯(cuò)誤越來(lái)越頻繁，最后導(dǎo)致 jvm內(nèi)存溢出而崩潰， ?

從上面日志能明顯看到導(dǎo)致jvm效率下降和內(nèi)存問(wèn)題的一個(gè)間接原因是?轉(zhuǎn)換步驟中對(duì)轉(zhuǎn)換數(shù)據(jù)庫(kù)的連接異常：
Error?connecting?to?database:?(using?class?org.gjt.mm.mysql.Driver)
Data?source?rejected?establishment?of?connection,??message?from?server:?"Too?many?connections?"?Error...........

大量異常需要消耗效率和內(nèi)存，所以之前并發(fā)數(shù)是20的時(shí)候，這個(gè)效率下降是緩慢的，現(xiàn)在換成100并發(fā)就很快出現(xiàn)問(wèn)題了。所以即使carte不崩潰，轉(zhuǎn)換也已經(jīng)不能正常運(yùn)行，因?yàn)閐b的瓶頸，轉(zhuǎn)換中的sql腳本以及表輸入或表輸出等操作已經(jīng)不能連接db?。?
七、優(yōu)化數(shù)據(jù)連接

1、開啟kettle轉(zhuǎn)換的數(shù)據(jù)庫(kù)連接池

對(duì)每個(gè)測(cè)試的轉(zhuǎn)換，將其ＤＢ連接全都勾選“使用連接池” （初始大小5，最大25） 。

2、加大MySQL最大連接數(shù)，由默認(rèn)100改為1000（max_connections）

再次測(cè)試，這時(shí)候壓了15分鐘就崩潰，通過(guò)日志查看，發(fā)現(xiàn)不存在數(shù)據(jù)庫(kù)數(shù)異常的問(wèn)題了，而且通過(guò)監(jiān)控發(fā)現(xiàn)數(shù)據(jù)庫(kù)連接正常，達(dá)到最大并發(fā)連接后沒(méi)有出現(xiàn)中斷連接

但是這次出現(xiàn)了新的現(xiàn)象，通過(guò)JVM監(jiān)控發(fā)現(xiàn)有2千多個(gè)活動(dòng)線程（正常峰值也就兩百多），包括轉(zhuǎn)換的線程（大部分處于監(jiān)視狀態(tài)）。

補(bǔ)充說(shuō)明：關(guān)于五種狀態(tài)的線程說(shuō)明

運(yùn)行(Running)：我們最喜歡的狀態(tài)。說(shuō)明該線程正在執(zhí)行代碼，沒(méi)有問(wèn)題。
休眠(Sleeping)：調(diào)用了Thread.sleep后的狀態(tài)，說(shuō)明線程正停在某個(gè)Thread.sleep處
等待(Wait)：手動(dòng)調(diào)用了wait方法，或者某些IO操作，在阻塞中等待數(shù)據(jù)。
駐留(Resident)：常駐線程，相當(dāng)于守護(hù)線程。
監(jiān)視(Monitor)：這里就是我想找的問(wèn)題了。它表示線程想執(zhí)行一段synchronized中的代碼，但是發(fā)現(xiàn)已經(jīng)有其它線程正在執(zhí)行，自己被block了，只能無(wú)奈地等待。如果這種狀態(tài)多，說(shuō)明程序需要好好優(yōu)化。

重現(xiàn)一下測(cè)試過(guò)程，發(fā)現(xiàn)到崩潰前，線程活動(dòng)數(shù)突然間大量增長(zhǎng)，如下所示：

通過(guò)threaddump分析，發(fā)現(xiàn)jetty 服務(wù)出現(xiàn)問(wèn)題，有大量的線程死鎖，經(jīng)過(guò)開發(fā)人員的分析，是因?yàn)檫B接池出現(xiàn)大量爭(zhēng)用，最后導(dǎo)致死鎖，如下：

"qtp1238013097-258267 - /kettle/executeTrans/" - Thread t@258267java.lang.Thread.State: WAITINGat java.lang.Object.wait(Native Method)- waiting on <50979aad> (a java.lang.Thread)at java.lang.Thread.join(Thread.java:1245)at java.lang.Thread.join(Thread.java:1319)at org.pentaho.di.trans.Trans.prepareExecution(Trans.java:1075)at org.pentaho.di.www.ExecuteTransServlet.executeTrans(ExecuteTransServlet.java:447)at org.pentaho.di.www.ExecuteTransServlet.doGet(ExecuteTransServlet.java:354)at org.pentaho.di.www.BaseHttpServlet.doPost(BaseHttpServlet.java:103)at javax.servlet.http.HttpServlet.service(HttpServlet.java:595)at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:522)at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)at org.eclipse.jetty.server.Server.handle(Server.java:366)at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:982)at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1043)at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None"init of Get film categories.0 (Thread-245354)" - Thread t@258266java.lang.Thread.State: BLOCKEDat org.pentaho.di.trans.steps.databasejoin.DatabaseJoin.init(DatabaseJoin.java:216)- waiting to lock <376dc4ad> (a org.pentaho.di.trans.Trans) owned by "init of Film.0 (Thread-245334)" t@258246at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None"init of dim_film_actor_bridge.0 (Thread-245353)" - Thread t@258265java.lang.Thread.State: BLOCKEDat org.pentaho.di.trans.steps.insertupdate.InsertUpdate.init(InsertUpdate.java:476)- waiting to lock <376dc4ad> (a org.pentaho.di.trans.Trans) owned by "init of Film.0 (Thread-245334)" t@258246at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None"init of Lookup dim_actor.0 (Thread-245351)" - Thread t@258263java.lang.Thread.State: BLOCKEDat org.pentaho.di.trans.steps.databaselookup.DatabaseLookup.connectDatabase(DatabaseLookup.java:637)- waiting to lock <376dc4ad> (a org.pentaho.di.trans.Trans) owned by "init of Film.0 (Thread-245334)" t@258246at org.pentaho.di.trans.steps.databaselookup.DatabaseLookup.init(DatabaseLookup.java:577)at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None"init of Get film_actor.0 (Thread-245348)" - Thread t@258260java.lang.Thread.State: BLOCKEDat org.pentaho.di.trans.steps.databasejoin.DatabaseJoin.init(DatabaseJoin.java:216)- waiting to lock <376dc4ad> (a org.pentaho.di.trans.Trans) owned by "init of Film.0 (Thread-245334)" t@258246at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None

猜測(cè)可能是由于轉(zhuǎn)換勾選了“使用唯一連接”

開發(fā)給的解釋為：這個(gè)問(wèn)題是由于死鎖造成的，jetty線程的鎖是表面現(xiàn)象，實(shí)際是轉(zhuǎn)換步驟線程死鎖，每個(gè)轉(zhuǎn)換使用唯一連接的情況下，當(dāng)每個(gè)轉(zhuǎn)換的步驟往下進(jìn)行時(shí)，不斷索取連接資源。如果有時(shí)刻T剛好所有轉(zhuǎn)換都在進(jìn)行，并且剛好每個(gè)轉(zhuǎn)換下面還有步驟需要獲取連接，（這種情況不難出現(xiàn)），線程X占用連接B，但索要連接A, 線程Y占用連接A, 但要連接B，（可以想象多個(gè)線程是互相交叉的）就會(huì)等待對(duì)方線程釋放資源，就出現(xiàn)死鎖狀態(tài)，jetty服務(wù)器于是出現(xiàn)阻塞。
如果轉(zhuǎn)換中出現(xiàn)連接兩個(gè)數(shù)據(jù)庫(kù)時(shí)，還需要研究一下怎么才能使得資源最大化。

這個(gè)問(wèn)題必須后續(xù)分析和解決（這也說(shuō)明前面的優(yōu)化跟最后的開啟連接池優(yōu)化存在沖突），這個(gè)問(wèn)題留到下周來(lái)進(jìn)行驗(yàn)證。

八、優(yōu)化失敗回滾部分設(shè)置

按照上周開發(fā)的解釋，將轉(zhuǎn)換中的“使用唯一連接”勾選去掉，再次執(zhí)行100并發(fā)，這次發(fā)現(xiàn)不到100用戶時(shí)（大概80多并發(fā)時(shí)）點(diǎn)擊率就直線下降，到100并發(fā)時(shí)直接崩潰，性能比上周的結(jié)果還差。對(duì)比了一下使用唯一連接和不使用唯一連接的線程數(shù)分布情況如下：

圖8.1 轉(zhuǎn)換使用唯一連接后測(cè)試崩潰統(tǒng)計(jì)的線程數(shù)

圖8.2 轉(zhuǎn)換不使用唯一連接后測(cè)試崩潰統(tǒng)計(jì)的線程數(shù)

可以發(fā)現(xiàn)使用唯一連接后總線程要多的多（因?yàn)檫\(yùn)行的時(shí)間比后者長(zhǎng)），而且大部分的活動(dòng)線程是被阻塞的，這與不使用唯一連接的測(cè)試結(jié)果不一樣（不使用唯一連接后大部分的活動(dòng)進(jìn)程 處在等待中，極少部分是被阻塞，而且系統(tǒng)只運(yùn)行了8分鐘后就崩潰了，這比前者還早了7分鐘，可以看出不勾選“使用唯一連接”效果更差）。

這也說(shuō)明在當(dāng)前配置情況下，轉(zhuǎn)換中勾選唯一連接和不勾選唯一連接的結(jié)果都一樣會(huì)讓系統(tǒng)很快崩潰，實(shí)質(zhì)上會(huì)有些差別（線程狀態(tài)數(shù)分布不同），但這已不重要了，重要的是步驟七針對(duì)數(shù)據(jù)連接的優(yōu)化是無(wú)效的，并帶來(lái)了副作用，繼續(xù)優(yōu)化下去可能進(jìn)入死胡同，因此需要進(jìn)行測(cè)試回滾（回到第七步、優(yōu)化數(shù)據(jù)連接），將優(yōu)化數(shù)據(jù)連接的策略做一下更改，改為只加大MySQL最大連接數(shù)（設(shè)為1500），不再開啟轉(zhuǎn)換的連接池（完全依靠mysql自身的連接控制策略），同時(shí)保留轉(zhuǎn)換使用唯一連接（好處是一個(gè)轉(zhuǎn)換過(guò)程只開啟一個(gè)連接，避免轉(zhuǎn)換中的每個(gè)步驟都開啟連接，會(huì)導(dǎo)致過(guò)快的消耗DB連接數(shù)）。

然后進(jìn)行100并發(fā)執(zhí)行測(cè)試，目前運(yùn)行良好（各項(xiàng)指標(biāo)正常，carte服務(wù)器的CPU 30%左右，內(nèi)存 69%左右；交換庫(kù)CPU 16%~75%，內(nèi)存 21%），需要繼續(xù)觀察（計(jì)劃運(yùn)行30天）。從目前JVM運(yùn)行情況來(lái)看，比較穩(wěn)定：

另外我們可能也需要換個(gè)思路來(lái)提升該數(shù)據(jù)交換平臺(tái)的穩(wěn)定性和性能了，留待后續(xù)思考。

九、分析網(wǎng)絡(luò)穩(wěn)定性問(wèn)題

經(jīng)過(guò)以上有效調(diào)優(yōu)后，系統(tǒng)運(yùn)行一個(gè)晚上，發(fā)現(xiàn)Loadrunner還是報(bào)出了少量錯(cuò)誤（No Route to Host）：

Action.c(22): Error -27796: Failed to connect to server "172.17.2.89:8081": [10065] No Route to Host cartekettle Action 22 ? 2017/6/3 2:21:01 3493 CarteKettle_2:310 localhost?

猜測(cè)可能是跟網(wǎng)絡(luò)延遲有關(guān)，通過(guò)優(yōu)化連接數(shù)，加大Carte的連接超時(shí)時(shí)間，以及將loadrunner的超時(shí)錯(cuò)誤時(shí)間放大，都無(wú)法避免這個(gè)錯(cuò)誤。只能通過(guò)監(jiān)控客戶端與服務(wù)端的ping丟包情況（通過(guò)統(tǒng)制ping.vbs 腳本，以cscript ping.vbs 172.17.2.89 -t -l 1000 -w 5000>ping89.txt輸出ping錯(cuò)誤日志），結(jié)果發(fā)現(xiàn)真是由網(wǎng)絡(luò)中斷引起的，說(shuō)明測(cè)試環(huán)境的網(wǎng)絡(luò)是不穩(wěn)定的。

說(shuō)明在網(wǎng)絡(luò)穩(wěn)定性方面，需要做好重連接，這得由調(diào)用carte服務(wù)的客戶端來(lái)決定，之后這塊邏輯可能需要在調(diào)度上去考慮。

十、后續(xù)思考：

由于本次測(cè)試過(guò)程，已經(jīng)對(duì)mysql進(jìn)行了優(yōu)化（加了redis緩存，提升了讀寫速度，減少了IO操作），同時(shí)對(duì)carte和kettle也進(jìn)行了JVM配置調(diào)優(yōu)，修改carte配置文件（將max_log_timeout_minutes和Object_timeout_minutes配置為最小值，及時(shí)回收內(nèi)存，減少內(nèi)存溢出的概率），同時(shí)對(duì)轉(zhuǎn)換也進(jìn)行了優(yōu)化（使用唯一連接，減少轉(zhuǎn)換中多步驟的DB連接資源占用）。但這些手段雖然提升了當(dāng)前數(shù)據(jù)交換系統(tǒng)的性能和穩(wěn)定性，但面對(duì)DB本身的瓶頸還是需要后續(xù)進(jìn)一步的優(yōu)化和性能提升。

下一步就要考慮mysql的集群化部署，包括通過(guò)mycat集群（提升mysql的高可用+讀寫分離）應(yīng)用，并且在業(yè)務(wù)層面上，適當(dāng)?shù)拈_展分表分庫(kù)以減輕mysql的單節(jié)點(diǎn)壓力，具體對(duì)于mycat的配置和測(cè)試參見(jiàn)另一篇文章：http://blog.csdn.net/smooth00/article/details/71082046

接著就是要考慮部署Carte服務(wù)集群，進(jìn)一步提升數(shù)據(jù)交換平臺(tái)的高可用和高穩(wěn)定性，以滿足長(zhǎng)時(shí)間的穩(wěn)定運(yùn)行和數(shù)據(jù)的大批量實(shí)時(shí)交換要求。

總結(jié)

以上是生活随笔為你收集整理的Carte+kettle+mysql性能问题定位分析记录的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。