Carte+kettle+mysql效能問題定位分析記錄

阿新 • • 發佈：2019-02-01

通過Carte服務對kettle轉換進行壓力測試，以20併發為基準，通過不斷的優化，對比測試結果如下：

20併發測試結果(持續7分鐘)	無Redis	加Redis	優化Carte記憶體使用配置	加CPU和記憶體（壓15小時）
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 總點選量	1,458	7,245	17,615
Average Hits per Second 點選率	3.336	17.168	45.051
Average Response Time 平均響應時間	22.608秒	4.366秒	1.645秒	1.378秒
90 Percent Response Time 90%請求響應時間	35.614秒	22.959秒	3.828秒	2.351秒
executeTrans Transaction Pass 交換事務處理量（事務吞吐量）	290	1449	3523
Carte伺服器平均CPU使用率	5.7% (Carte引數優化前為90%)	10~30%	85%~90% （壓力過大）	45%~70%
Carte伺服器記憶體使用率	70~80% （飽和）	70~80% （飽和）	70~80% （飽和）	50%~60%
MySql 平均CPU使用率	60% (MySql快取優化前為100%)	40%	2% （MySql無壓力）	2%

以上測試結果包括的具體優化過程有：Mysql開啟查詢快取、Carte日誌快取時間配置、加Redes、優化Carte記憶體使用配置（將max_log_timeout_minutes和Object_timeout_minutes都縮小配置為1分鐘）、加CPU和加記憶體、優化配置JVM配置調優（根據記憶體大小重新將spoon.sh檔案中的JVM堆記憶體引數-Xms -Xmx優化設定）。

確認優化結果有效後（能夠穩定執行15小時），再以20併發進行更長時間穩定性測試，持續壓力測試到20天后出現崩潰，由於崩潰的時間點和引起崩潰原因一時難以定位，重新改變壓力測試的策略（測試前開發人員再做一些優化，主要是解除和排除日誌中出現的一些異常錯誤，如轉換過程丟擲的異常；並同時開啟轉換使用唯一連線

），然後進行100併發持續壓力測試（加大併發數可以實現空間換時間，縮短壓測時間，以便儘快定位影響穩定性問題的原因），同時開啟jvm監控，開啟所有服務和資料庫監控。

測試指令碼日夜不間斷跑測，到第二天早上看監控結果，就發現系統真的崩潰了。

一、通過Loadrunner能夠看到執行13個小時後出現異常崩潰

二、通過Carte服務的CPU監控，能夠看到早上7點鐘前出現壓力突然上升，並且無法降低

三、獲取JVM監控的歷史報告（JVM監控已異常斷開連線），從連線時間、執行緒數、堆記憶體（無法回收記憶體）的變化情況，也能看出7點左右出現反常情況

四、通過監控MySQL（有兩個mysql，一個是資源庫，一切正常，一個是交換庫出現異常），發現7點左右出現大量斷開的連線

五、對交換庫的監控，發現快到7點時，壓力突然降低，這與上面的異常相符合

六、日誌定位問題

通過上面的監控，可以判斷，系統在7點前15分鐘左右，應該出現故障，這就需要通過日誌定位這個時段，以找到具體原因

最後在Carte服務的日誌中找到答案，第一次出現連線錯誤的時間點是06:44:50.273，報的是Too many connections

然後錯誤越來越頻繁，最後導致 jvm記憶體溢位而崩潰，

從上面日誌能明顯看到導致jvm效率下降和記憶體問題的一個間接原因是轉換步驟中對轉換資料庫的連線異常：
Error connecting to database: (using class org.gjt.mm.mysql.Driver)
Data source rejected establishment of connection, message from server: "Too many connections " Error...........

大量異常需要消耗效率和記憶體，所以之前併發數是20的時候，這個效率下降是緩慢的，現在換成100併發就很快出現問題了。所以即使carte不崩潰，轉換也已經不能正常執行，因為db的瓶頸，轉換中的sql指令碼以及表輸入或表輸出等操作已經不能連線db 。七、優化資料連線

1、開啟kettle轉換的資料庫連線池

對每個測試的轉換，將其ＤＢ連線全都勾選“使用連線池” （初始大小5，最大25）。

2、加大MySQL最大連線數，由預設100改為1000（max_connections）

再次測試，這時候壓了15分鐘就崩潰，通過日誌檢視，發現不存在資料庫數異常的問題了，而且通過監控發現數據庫連線正常，達到最大併發連線後沒有出現中斷連線

但是這次出現了新的現象，通過JVM監控發現有2千多個活動執行緒（正常峰值也就兩百多），包括轉換的執行緒（大部分處於監視狀態）。

補充說明：關於五種狀態的執行緒說明

執行(Running)：我們最喜歡的狀態。說明該執行緒正在執行程式碼，沒有問題。
休眠(Sleeping)：呼叫了Thread.sleep後的狀態，說明執行緒正停在某個Thread.sleep處
等待(Wait)：手動呼叫了wait方法，或者某些IO操作，在阻塞中等待資料。
駐留(Resident)：常駐執行緒，相當於守護執行緒。
監視(Monitor)：這裡就是我想找的問題了。它表示執行緒想執行一段synchronized中的程式碼，但是發現已經有其它執行緒正在執行，自己被block了，只能無奈地等待。如果這種狀態多，說明程式需要好好優化。

重現一下測試過程，發現到崩潰前，執行緒活動數突然間大量增長，如下所示：

通過threaddump分析，發現jetty 服務出現問題，有大量的執行緒死鎖，經過開發人員的分析，是因為連線池出現大量爭用，最後導致死鎖，如下：

"qtp1238013097-258267 - /kettle/executeTrans/" - Thread [email protected]
   java.lang.Thread.State: WAITING
	at 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 [email protected]
   java.lang.Thread.State: BLOCKED
	at 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)" [email protected]
	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 dim_film_actor_bridge.0 (Thread-245353)" - Thread [email protected]
   java.lang.Thread.State: BLOCKED
	at 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)" [email protected]
	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 Lookup dim_actor.0 (Thread-245351)" - Thread [email protected]
   java.lang.Thread.State: BLOCKED
	at 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)" [email protected]
	at 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 [email protected]
   java.lang.Thread.State: BLOCKED
	at 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)" [email protected]
	at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None

猜測可能是由於轉換勾選了“使用唯一連線”

開發給的解釋為：這個問題是由於死鎖造成的，jetty執行緒的鎖是表面現象，實際是轉換步驟執行緒死鎖，每個轉換使用唯一連線的情況下，當每個轉換的步驟往下進行時，不斷索取連線資源。如果有時刻T剛好所有轉換都在進行，並且剛好每個轉換下面還有步驟需要獲取連線，（這種情況不難出現），執行緒X佔用連線B，但索要連線A, 執行緒Y佔用連線A, 但要連線B，（可以想象多個執行緒是互相交叉的）就會等待對方執行緒釋放資源，就出現死鎖狀態，jetty伺服器於是出現阻塞。
如果轉換中出現連線兩個資料庫時，還需要研究一下怎麼才能使得資源最大化。

這個問題必須後續分析和解決（這也說明前面的優化跟最後的開啟連線池優化存在衝突），這個問題留到下週來進行驗證。

八、優化失敗回滾部分設定

按照上週開發的解釋，將轉換中的“使用唯一連線”勾選去掉，再次執行100併發，這次發現不到100使用者時（大概80多併發時）點選率就直線下降，到100併發時直接崩潰，效能比上週的結果還差。對比了一下使用唯一連線和不使用唯一連線的執行緒數分佈情況如下：

圖8.1 轉換使用唯一連線後測試崩潰統計的執行緒數

圖8.2 轉換不使用唯一連線後測試崩潰統計的執行緒數

可以發現使用唯一連線後匯流排程要多的多（因為執行的時間比後者長），而且大部分的活動執行緒是被阻塞的，這與不使用唯一連線的測試結果不一樣（不使用唯一連線後大部分的活動程序處在等待中，極少部分是被阻塞，而且系統只運行了8分鐘後就崩潰了，這比前者還早了7分鐘，可以看出不勾選“使用唯一連線”效果更差）。

這也說明在當前配置情況下，轉換中勾選唯一連線和不勾選唯一連線的結果都一樣會讓系統很快崩潰，實質上會有些差別（執行緒狀態數分佈不同），但這已不重要了，重要的是步驟七針對資料連線的優化是無效的，並帶來了副作用，繼續優化下去可能進入死衚衕，因此需要進行測試回滾（回到第七步、優化資料連線），將優化資料連線的策略做一下更改，改為只加大MySQL最大連線數（設為1500），不再開啟轉換的連線池（完全依靠mysql自身的連線控制策略），同時保留轉換使用唯一連線（好處是一個轉換過程只開啟一個連線，避免轉換中的每個步驟都開啟連線，會導致過快的消耗DB連線數）。

然後進行100併發執行測試，目前執行良好（各項指標正常，carte伺服器的CPU 30%左右，記憶體 69%左右；交換庫CPU 16%~75%，記憶體 21%），需要繼續觀察（計劃執行30天）。從目前JVM執行情況來看，比較穩定：

另外我們可能也需要換個思路來提升該資料交換平臺的穩定性和效能了，留待後續思考。

九、分析網路穩定性問題

經過以上有效調優後，系統執行一個晚上，發現Loadrunner還是報出了少量錯誤（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

猜測可能是跟網路延遲有關，通過優化連線數，加大Carte的連線超時時間，以及將loadrunner的超時錯誤時間放大，都無法避免這個錯誤。只能通過監控客戶端與服務端的ping丟包情況（通過統制ping.vbs 指令碼，以cscript ping.vbs 172.17.2.89 -t -l 1000 -w 5000>ping89.txt輸出ping錯誤日誌），結果發現真是由網路中斷引起的，說明測試環境的網路是不穩定的。

說明在網路穩定性方面，需要做好重連線，這得由呼叫carte服務的客戶端來決定，之後這塊邏輯可能需要在排程上去考慮。

十、後續思考：

由於本次測試過程，已經對mysql進行了優化（加了redis快取，提升了讀寫速度，減少了IO操作），同時對carte和kettle也進行了JVM配置調優，修改carte配置檔案（將max_log_timeout_minutes和Object_timeout_minutes配置為最小值，及時回收記憶體，減少記憶體溢位的概率），同時對轉換也進行了優化（使用唯一連線，減少轉換中多步驟的DB連線資源佔用）。但這些手段雖然提升了當前資料交換系統的效能和穩定性，但面對DB本身的瓶頸還是需要後續進一步的優化和效能提升。

下一步就要考慮mysql的叢集化部署，包括通過mycat叢集（提升mysql的高可用+讀寫分離）應用，並且在業務層面上，適當的開展分表分庫以減輕mysql的單節點壓力，具體對於mycat的配置和測試參見另一篇文章：http://blog.csdn.net/smooth00/article/details/71082046

接著就是要考慮部署Carte服務叢集，進一步提升資料交換平臺的高可用和高穩定性，以滿足長時間的穩定執行和資料的大批量實時交換要求。

Carte+kettle+mysql效能問題定位分析記錄

Carte+kettle+mysql效能問題定位分析記錄

MySQL效能測試分析

mysql資料庫如何定位分析哪些sql語句查詢比較慢

MySQL Insert語句單個批次數量過多導致的CPU效能問題分析

Android 效能分析記錄

MySQL效能分析和優化-part 1

MySQL效能分析之Profile

關聯與下鑽：快速定位MySQL效能瓶頸的制勝手段

mysql效能分析利器 EXPALIN

mysql的sql語句的效能診斷分析

效能調優之MySQL篇三：MySQL配置定位以及優化

效能調優之MySQL篇四：MySQL配置定位以及優化

MySQL伺服器SSD效能問題分析與測試

MySQL 快速定位效能問題

mysql 效能分析Explain使用

MySQL效能瓶頸排查定位

MYSQL——效能瓶頸定位

mysql效能分析show profile/show profiles

MySQL慢查詢日誌記錄和分析

MySQL效能調優——鎖定機制與鎖優化分析

Carte+kettle+mysql效能問題定位分析記錄

相關推薦