壓測(cè)排查案例-不間斷的CPU驟降印颤，堆內(nèi)存不再增加

問題描述

使用nginx分發(fā)兩臺(tái)機(jī)器（4G+4G年輕代）進(jìn)行持續(xù)壓測(cè)请祖，結(jié)果發(fā)現(xiàn)订歪，出現(xiàn)不間斷的CPU驟降，堆內(nèi)存不再增加肆捕。期間服務(wù)端不再響應(yīng)陌粹。總體服務(wù)器TPS為200左右。

問題描述.png

跟蹤問題

通過線程圖表分析掏秩，發(fā)現(xiàn)每次CPU驟降的時(shí)候或舞，都會(huì)有一個(gè)工作線程BLOCK

想到的跟蹤方法是，每次CPU驟降的時(shí)候蒙幻，立刻進(jìn)行手動(dòng)線程dump映凳，把CPU驟降的時(shí)候，線程的狀況打印出來

定位問題

分析當(dāng)時(shí)的打印線程dump

根據(jù)當(dāng)時(shí)BLOCK的線程號(hào)是122邮破，定位到對(duì)應(yīng)的線程日志

"http-nio-8883-exec-122" - Thread t@201
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Thread.sleep(Native Method)
        at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2156)
        at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2090)
        - locked <3406588f> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:795)
        at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:44)
        at sun.reflect.GeneratedConstructorAccessor68.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
        at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:400)
        at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:327)
        at org.apache.ibatis.datasource.unpooled.UnpooledDataSource$DriverProxy.connect(UnpooledDataSource.java:249)
        at java.sql.DriverManager.getConnection(DriverManager.java:664)
        at java.sql.DriverManager.getConnection(DriverManager.java:208)
        at org.apache.ibatis.datasource.unpooled.UnpooledDataSource.doGetConnection(UnpooledDataSource.java:201)
        at org.apache.ibatis.datasource.unpooled.UnpooledDataSource.doGetConnection(UnpooledDataSource.java:196)
        at org.apache.ibatis.datasource.unpooled.UnpooledDataSource.getConnection(UnpooledDataSource.java:93)
        at org.apache.ibatis.datasource.pooled.PooledDataSource.popConnection(PooledDataSource.java:385)
        - locked <64485760> (a org.apache.ibatis.datasource.pooled.PoolState)
        at org.apache.ibatis.datasource.pooled.PooledDataSource.getConnection(PooledDataSource.java:89)
        at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
        at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
        at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:81)
        at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67)
        at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:315)
        at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:75)
        at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:61)
        at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303)
        at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:73)
        at sun.reflect.GeneratedMethodAccessor147.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358)
        at com.sun.proxy.$Proxy35.selectOne(Unknown Source)
        at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:163)
        at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:69)
        at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
        at com.sun.proxy.$Proxy99.select(Unknown Source)
        at com.baioo.ais.app.service.skill.image.SkillImageService.query(SkillImageService.java:20)
        at com.baioo.ais.app.service.skill.image.SkillImageService$$FastClassBySpringCGLIB$$c0fa6361.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
        at com.baioo.ais.common.monitor.AspectHelper.monitorPerformanceProceed(AspectHelper.java:37)
        at com.baioo.ais.common.monitor.MonitorAspect.logPointPerformance(MonitorAspect.java:57)
        at com.baioo.ais.common.monitor.MonitorAspect.springService(MonitorAspect.java:48)
        at sun.reflect.GeneratedMethodAccessor142.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
        at com.baioo.ais.app.service.skill.image.SkillImageService$$EnhancerBySpringCGLIB$$f20c7a4e.query(<generated>)
        at com.baioo.ais.app.service.skills.activity.bdchest.BDChestActionService$ImageTemplateConvert.handleDuerOSTemplateDirective(BDChestActionService.java:140)
        at com.baioo.ais.app.service.skills.activity.bdchest.BDChestActionService.afterActionManagerExecute(BDChestActionService.java:95)
        at com.baioo.ais.app.service.skills.AbstractSkillExecutorService.execute(AbstractSkillExecutorService.java:58)
        at com.baioo.ais.app.service.skills.activity.bdchest.BDChestActionService.execute(BDChestActionService.java:52)
        at com.baioo.ais.app.service.skills.activity.bdchest.BDChestActionService$$FastClassBySpringCGLIB$$f6ac3d7c.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
        at com.baioo.ais.common.monitor.AspectHelper.monitorPerformanceProceed(AspectHelper.java:37)
        at com.baioo.ais.common.monitor.MonitorAspect.logPointPerformance(MonitorAspect.java:57)
        at com.baioo.ais.common.monitor.MonitorAspect.springService(MonitorAspect.java:48)
        at sun.reflect.GeneratedMethodAccessor142.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)

...

   Locked ownable synchronizers:
        - locked <59a51757> (a java.util.concurrent.ThreadPoolExecutor$Worker)

發(fā)現(xiàn)該線程狀態(tài)是TIMED_WAITING

而且獲得了鎖<64485760>

\- locked <64485760> (a org.apache.ibatis.datasource.pooled.PoolState) 

而且發(fā)現(xiàn)大量其他線程都堵塞在這個(gè)鎖上诈豌，如

"http-nio-8883-exec-108" - Thread t@187
   java.lang.Thread.State: BLOCKED
        at org.apache.ibatis.datasource.pooled.PooledDataSource.pushConnection(PooledDataSource.java:330)
        - waiting to lock <64485760> (a org.apache.ibatis.datasource.pooled.PoolState) owned by "http-nio-8883-exec-122" t@201
        at org.apache.ibatis.datasource.pooled.PooledConnection.invoke(PooledConnection.java:236)

這個(gè)其中，發(fā)現(xiàn)程序使用的PooledDataSource抒和，經(jīng)過查詢矫渔，這個(gè)是Mybatis自己mysql鏈接池。

經(jīng)過考慮摧莽，我們把數(shù)據(jù)庫鏈接池更改成druid庙洼。

再次測(cè)試，問題解決镊辕。TPS高達(dá)460

案例后記

沒有想到鏈接池對(duì)性能的影響這么大油够。

本案例中，因?yàn)閙ysql的鏈接用完征懈，使用Mybatis鏈接池的時(shí)候石咬，線程被柱塞，大大影響其性能卖哎。

雖然換成druid后鬼悠，問題解決，但是現(xiàn)在暫時(shí)沒有深究druid為啥能解決這個(gè)問題亏娜。