Carte+kettle+mysql性能问题定位分析记录

通过Carte服务对kettle转换进行压力测试&＃xff0c;以20并发为基准&＃xff0c;通过不断的优化&＃xff0c;对比测试结果如下&＃xff1a;

以上测试结果包括的具体优化过程有&＃xff1a;Mysql开启查询缓存、Carte日志缓存时间配置、加Redes、优化Carte内存使用配置&＃xff08;将max_log_timeout_minutes和Object_timeout_minutes都缩小配置为1分钟&＃xff09;、加CPU和加内存、优化配置JVM配置调优&＃xff08;根据内存大小重新将spoon.sh文件中的JVM堆内存参数-Xms -Xmx优化设置&＃xff09;。

确认优化结果有效后&＃xff08;能够稳定运行15小时&＃xff09;&＃xff0c;再以20并发进行更长时间稳定性测试&＃xff0c;持续压力测试到20天后出现崩溃&＃xff0c;由于崩溃的时间点和引起崩溃原因一时难以定位&＃xff0c;重新改变压力测试的策略&＃xff08;测试前开发人员再做一些优化&＃xff0c;主要是解除和排除日志中出现的一些异常错误&＃xff0c;如转换过程抛出的异常&＃xff1b;并同时开启转换使用唯一连接&＃xff09;&＃xff0c;然后进行100并发持续压力测试&＃xff08;加大并发数可以实现空间换时间&＃xff0c;缩短压测时间&＃xff0c;以便尽快定位影响稳定性问题的原因&＃xff09;&＃xff0c;同时开启jvm监控&＃xff0c;开启所有服务和数据库监控。

测试脚本日夜不间断跑测&＃xff0c;到第二天早上看监控结果&＃xff0c;就发现系统真的崩溃了。

一、通过Loadrunner能够看到运行13个小时后出现异常崩溃

二、通过Carte服务的CPU监控&＃xff0c;能够看到早上7点钟前出现压力突然上升&＃xff0c;并且无法降低

三、获取JVM监控的历史报告&＃xff08;JVM监控已异常断开连接&＃xff09;&＃xff0c;从连接时间、线程数、堆内存&＃xff08;无法回收内存&＃xff09;的变化情况&＃xff0c;也能看出7点左右出现反常情况

四、通过监控MySQL&＃xff08;有两个mysql&＃xff0c;一个是资源库&＃xff0c;一切正常&＃xff0c;一个是交换库出现异常&＃xff09;&＃xff0c;发现7点左右出现大量断开的连接

五、对交换库的监控&＃xff0c;发现快到7点时&＃xff0c;压力突然降低&＃xff0c;这与上面的异常相符合

六、日志定位问题

通过上面的监控&＃xff0c;可以判断&＃xff0c;系统在7点前15分钟左右&＃xff0c;应该出现故障&＃xff0c;这就需要通过日志定位这个时段&＃xff0c;以找到具体原因

最后在Carte服务的日志中找到答案&＃xff0c;第一次出现连接错误的时间点是06:44:50.273&＃xff0c;报的是Too many connections

然后错误越来越频繁&＃xff0c;最后导致 jvm内存溢出而崩溃&＃xff0c;  

1、开启kettle转换的数据库连接池

对每个测试的转换&＃xff0c;将其&＃xff24;&＃xff22;连接全都勾选“使用连接池” &＃xff08;初始大小5&＃xff0c;最大25&＃xff09; 。

2、加大MySQL最大连接数&＃xff0c;由默认100改为1000&＃xff08;max_connections&＃xff09;

再次测试&＃xff0c;这时候压了15分钟就崩溃&＃xff0c;通过日志查看&＃xff0c;发现不存在数据库数异常的问题了&＃xff0c;而且通过监控发现数据库连接正常&＃xff0c;达到最大并发连接后没有出现中断连接

但是这次出现了新的现象&＃xff0c;通过JVM监控发现有2千多个活动线程&＃xff08;正常峰值也就两百多&＃xff09;&＃xff0c;包括转换的线程&＃xff08;大部分处于监视状态&＃xff09;。

补充说明&＃xff1a;关于五种状态的线程说明

运行(Running)&＃xff1a;我们最喜欢的状态。说明该线程正在执行代码&＃xff0c;没有问题。
休眠(Sleeping)&＃xff1a;调用了Thread.sleep后的状态&＃xff0c;说明线程正停在某个Thread.sleep处
等待(Wait)&＃xff1a;手动调用了wait方法&＃xff0c;或者某些IO操作&＃xff0c;在阻塞中等待数据。
驻留(Resident)&＃xff1a;常驻线程&＃xff0c;相当于守护线程。
监视(Monitor)&＃xff1a;这里就是我想找的问题了。它表示线程想执行一段synchronized中的代码&＃xff0c;但是发现已经有其它线程正在执行&＃xff0c;自己被block了&＃xff0c;只能无奈地等待。如果这种状态多&＃xff0c;说明程序需要好好优化。

重现一下测试过程&＃xff0c;发现到崩溃前&＃xff0c;线程活动数突然间大量增长&＃xff0c;如下所示&＃xff1a;

通过threaddump分析&＃xff0c;发现jetty 服务出现问题&＃xff0c;有大量的线程死锁&＃xff0c;经过开发人员的分析&＃xff0c;是因为连接池出现大量争用&＃xff0c;最后导致死锁&＃xff0c;如下&＃xff1a;

"qtp1238013097-258267 - /kettle/executeTrans/" - Thread t&＃64;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&＃64;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&＃64;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&＃64;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&＃64;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&＃64;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&＃64;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&＃64;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&＃64;258246at org.pentaho.di.trans.step.StepInitThread.run(StepInitThread.java:69)at java.lang.Thread.run(Thread.java:745)Locked ownable synchronizers:- None

猜测可能是由于转换勾选了“使用唯一连接”

开发给的解释为&＃xff1a;这个问题是由于死锁造成的&＃xff0c;jetty线程的锁是表面现象&＃xff0c;实际是转换步骤线程死锁&＃xff0c;每个转换使用唯一连接的情况下&＃xff0c;当每个转换的步骤往下进行时&＃xff0c;不断索取连接资源。如果有时刻T刚好所有转换都在进行&＃xff0c;并且刚好每个转换下面还有步骤需要获取连接&＃xff0c;&＃xff08;这种情况不难出现&＃xff09;&＃xff0c;线程X占用连接B&＃xff0c;但索要连接A, 线程Y占用连接A, 但要连接B&＃xff0c;&＃xff08;可以想象多个线程是互相交叉的&＃xff09;就会等待对方线程释放资源&＃xff0c;就出现死锁状态&＃xff0c;jetty服务器于是出现阻塞。
如果转换中出现连接两个数据库时&＃xff0c;还需要研究一下怎么才能使得资源最大化。

这个问题必须后续分析和解决&＃xff08;这也说明前面的优化跟最后的开启连接池优化存在冲突&＃xff09;&＃xff0c;这个问题留到下周来进行验证。

八、优化失败回滚部分设置

按照上周开发的解释&＃xff0c;将转换中的“使用唯一连接”勾选去掉&＃xff0c;再次执行100并发&＃xff0c;这次发现不到100用户时&＃xff08;大概80多并发时&＃xff09;点击率就直线下降&＃xff0c;到100并发时直接崩溃&＃xff0c;性能比上周的结果还差。对比了一下使用唯一连接和不使用唯一连接的线程数分布情况如下&＃xff1a;

图8.1 转换使用唯一连接后测试崩溃统计的线程数

图8.2 转换不使用唯一连接后测试崩溃统计的线程数

可以发现使用唯一连接后总线程要多的多&＃xff08;因为运行的时间比后者长&＃xff09;&＃xff0c;而且大部分的活动线程是被阻塞的&＃xff0c;这与不使用唯一连接的测试结果不一样&＃xff08;不使用唯一连接后大部分的活动进程 处在等待中&＃xff0c;极少部分是被阻塞&＃xff0c;而且系统只运行了8分钟后就崩溃了&＃xff0c;这比前者还早了7分钟&＃xff0c;可以看出不勾选“使用唯一连接”效果更差&＃xff09;。

这也说明在当前配置情况下&＃xff0c;转换中勾选唯一连接和不勾选唯一连接的结果都一样会让系统很快崩溃&＃xff0c;实质上会有些差别&＃xff08;线程状态数分布不同&＃xff09;&＃xff0c;但这已不重要了&＃xff0c;重要的是步骤七针对数据连接的优化是无效的&＃xff0c;并带来了副作用&＃xff0c;继续优化下去可能进入死胡同&＃xff0c;因此需要进行测试回滚&＃xff08;回到第七步、优化数据连接&＃xff09;&＃xff0c;将优化数据连接的策略做一下更改&＃xff0c;改为只加大MySQL最大连接数&＃xff08;设为1500&＃xff09;&＃xff0c;不再开启转换的连接池&＃xff08;完全依靠mysql自身的连接控制策略&＃xff09;&＃xff0c;同时保留转换使用唯一连接&＃xff08;好处是一个转换过程只开启一个连接&＃xff0c;避免转换中的每个步骤都开启连接&＃xff0c;会导致过快的消耗DB连接数&＃xff09;。

然后进行100并发执行测试&＃xff0c;目前运行良好&＃xff08;各项指标正常&＃xff0c;carte服务器的CPU 30%左右&＃xff0c;内存 69%左右&＃xff1b;交换库CPU 16%~75%&＃xff0c;内存 21%&＃xff09;&＃xff0c;需要继续观察&＃xff08;计划运行30天&＃xff09;。从目前JVM运行情况来看&＃xff0c;比较稳定&＃xff1a;

另外我们可能也需要换个思路来提升该数据交换平台的稳定性和性能了&＃xff0c;留待后续思考。

九、分析网络稳定性问题

经过以上有效调优后&＃xff0c;系统运行一个晚上&＃xff0c;发现Loadrunner还是报出了少量错误&＃xff08;No Route to Host&＃xff09;&＃xff1a;

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 

猜测可能是跟网络延迟有关&＃xff0c;通过优化连接数&＃xff0c;加大Carte的连接超时时间&＃xff0c;以及将loadrunner的超时错误时间放大&＃xff0c;都无法避免这个错误。只能通过监控客户端与服务端的ping丢包情况&＃xff08;通过统制ping.vbs 脚本&＃xff0c;以cscript ping.vbs 172.17.2.89 -t -l 1000 -w 5000>ping89.txt输出ping错误日志&＃xff09;&＃xff0c;结果发现真是由网络中断引起的&＃xff0c;说明测试环境的网络是不稳定的。

说明在网络稳定性方面&＃xff0c;需要做好重连接&＃xff0c;这得由调用carte服务的客户端来决定&＃xff0c;之后这块逻辑可能需要在调度上去考虑。

十、后续思考&＃xff1a;

由于本次测试过程&＃xff0c;已经对mysql进行了优化&＃xff08;加了redis缓存&＃xff0c;提升了读写速度&＃xff0c;减少了IO操作&＃xff09;&＃xff0c;同时对carte和kettle也进行了JVM配置调优&＃xff0c;修改carte配置文件&＃xff08;将max_log_timeout_minutes和Object_timeout_minutes配置为最小值&＃xff0c;及时回收内存&＃xff0c;减少内存溢出的概率&＃xff09;&＃xff0c;同时对转换也进行了优化&＃xff08;使用唯一连接&＃xff0c;减少转换中多步骤的DB连接资源占用&＃xff09;。但这些手段虽然提升了当前数据交换系统的性能和稳定性&＃xff0c;但面对DB本身的瓶颈还是需要后续进一步的优化和性能提升。

下一步就要考虑mysql的集群化部署&＃xff0c;包括通过mycat集群&＃xff08;提升mysql的高可用&＃43;读写分离&＃xff09;应用&＃xff0c;并且在业务层面上&＃xff0c;适当的开展分表分库以减轻mysql的单节点压力&＃xff0c;具体对于mycat的配置和测试参见另一篇文章&＃xff1a;http://blog.csdn.net/smooth00/article/details/71082046

接着就是要考虑部署Carte服务集群&＃xff0c;进一步提升数据交换平台的高可用和高稳定性&＃xff0c;以满足长时间的稳定运行和数据的大批量实时交换要求。