Carte+kettle+mysql性能问题定位分析记录
通過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轉換的數據庫連接池
對每個測試的轉換,將其DB連接全都勾選“使用連接池” (初始大小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 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猜測可能是由于轉換勾選了“使用唯一連接”
開發給的解釋為:這個問題是由于死鎖造成的,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性能问题定位分析记录的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: python 爬虫餐饮行业 数据分析_P
- 下一篇: AJAX框架简笔画风景简单,好看简单的简