压测排查案例-不间断的CPU骤降，堆内存不再增加

问题描述

使用nginx分发两台机器（4G+4G年轻代）进行持续压测，结果发现，出现不间断的CPU骤降，堆内存不再增加。期间服务端不再响应。总体服务器TPS为200左右。

问题描述.png

跟踪问题

通过线程图表分析，发现每次CPU骤降的时候，都会有一个工作线程BLOCK

想到的跟踪方法是，每次CPU骤降的时候，立刻进行手动线程dump，把CPU骤降的时候，线程的状况打印出来

定位问题

分析当时的打印线程dump

根据当时BLOCK的线程号是122，定位到对应的线程日志

"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)

发现该线程状态是TIMED_WAITING

而且获得了锁<64485760>

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

而且发现大量其他线程都堵塞在这个锁上，如

"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)

这个其中，发现程序使用的PooledDataSource，经过查询，这个是Mybatis自己mysql链接池。

经过考虑，我们把数据库链接池更改成druid。

再次测试，问题解决。TPS高达460

案例后记

没有想到链接池对性能的影响这么大。

本案例中，因为mysql的链接用完，使用Mybatis链接池的时候，线程被柱塞，大大影响其性能。

虽然换成druid后，问题解决，但是现在暂时没有深究druid为啥能解决这个问题。