压测问题现象分析及解决复盘
一、
现象：压测过程中接口返回慢、有超时情况，后其中一台容器自动重启，重启后生成了dump目录
分析：猜测是发生了OOM并且容器配置了OOM自动输出dump文件。得到的dump文件有thread dump,gcutil,netstat
解决过程：
(1)
从jstack日志入手，依次根据deadlock、blocked关键字查找， 找到以下处于blocked状态的线程堆栈信息
"asyncExecutor-1093" #9490 prio=5 os_prio=0 tid=0x00007f12b400f800 nid=0x25c7 waiting for monitor entry [0x00007f0d1aa03000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:217)
- waiting to lock <0x000000065804dcc8> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAcceslalaileManager)
at org.apache.logging.log4j.core.appender.RollingRandomAcceslalaileAppender.append(RollingRandomAcceslalaileAppender.java:207)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2011)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1884)
at com.lala.sgs.lalalog.log4j2.Log4j2Logger.error(Log4j2Logger.java:520)
"http-nio-8888-exec-4" #363 daemon prio=5 os_prio=0 tid=0x00007f0f48003000 nid=0x222 waiting for monitor entry [0x00007f11abeb8000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination(TextEncoderHelper.java:61)
- waiting to lock <0x000000065804dcc8> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAcceslalaileManager)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeTextWithCopy(TextEncoderHelper.java:57)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encodeWithThreadLocals(StringBuilderEncoder.java:70)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:63)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:219)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
该线程blocked现象通过引入disruptor框架并配置asyncLogger后没有再出现blocked现象。（参考：https://www.cnblogs.com/waterystone/p/11170540.html ）
（2）解决日志打印性能问题后重新压测，发现在send kafka，redis pool方面也有相应的性能问题。
"http-nio-8888-exec-295" #1570 daemon prio=5 os_prio=0 tid=0x00007f0fa40f6000 nid=0x6d7 waiting for monitor entry [0x00007f0d839e1000]
java.lang.Thread.State: BLOCKED (on object monitor)
at kafka.producer.Producer.send(Producer.scala:72)
- waiting to lock <0x0000000656965bf8> (a java.lang.Object)
at kafka.javaapi.producer.Producer.send(Producer.scala:33)
at com.lala.kafka.api.produce.KafkaProducer.send(KafkaProducer.java:65)
at com.lala.kafka.api.produce.KafkaProducer.sendBytes(KafkaProducer.java:54)
at com.lala.kafka.api.produce.ProducerPool.sendBytes(ProducerPool.java:49)
at com.lala.kafka.api.produce.BaseProducer.sendString(BaseProducer.java:14)
通过增大发送kafka的线程数poolSize得以解决。
"asyncExecutor-253" #1470 prio=5 os_prio=0 tid=0x00007f151000b000 nid=0x672 waiting on condition [0x00007f0d857da000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000659daa5c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:524)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:438)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:361)
at redis.clients.util.Pool.getResource(Pool.java:49)
at redis.clients.jedis.JedisSentinelPool.getResource(JedisSentinelPool.java:209)
at redis.clients.jedis.JedisSentinelPool.getResource(JedisSentinelPool.java:17)
at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:194)
at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:348)
at org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:129)
at org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:92)
at org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:79)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:194)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:169)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:157)
看redis的配置使用的是默认的配置，默认值可从GenericObjectPoolConfig查到。
通过增大maxTotal、maxIdle、minIdle值得以解决。
（3）压测还在进行中
（4）通过gcutil查看gc的情况，发现YGC比较频繁，
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
12.42 0.00 96.21 50.59 90.24 86.46 1770 201.800 8 0.950 202.750
JVM配置是：
-server -Xmx6g -Xms6g -Xmn256m -XX:PermSize=128m -Xss256k -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70
发现年轻代配得太小，于是加大了该项配置。改成如下：
-server -Xmx6g -Xms6g -Xmn3072m -Xss512k -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintClassHistogram -Xloggc:../logs/gc.log
重新压测后gc情况有好转
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
15.07 0.00 77.15 32.25 90.37 86.32 116 24.551 8 6.216 30.767
dump获取方法（转）：
（1）获取thread dump
使用 jstack
jstack 是 JDK 自带的工具，用于 dump 指定进程 ID(PID)的 JVM 的线程堆栈信息。
# 打印堆栈信息到标准输出
jstack PID
# 打印堆栈信息到标准输出，会打印关于锁的信息
jstack -l PID
强制打印堆栈信息到标准输出，如果使用 jstack PID 没有响应的情况下(此时 JVM 进程可能挂起)，加 -F 参数
jstack -F PID
使用 jcmd
jcmd 是 JDK 自带的工具，用于向 JVM 进程发送命令，根据命令的不同，可以代替或部分代替 jstack、jmap 等。可以发送命令 Thread.print 来打印出 JVM 的线程堆栈信息。
# 下面的命令同等于 jstack PID
jcmd PID Thread.print
# 同等于 jstack -l PID
jcmd PID Thread.print -l
使用 kill -3
kill 可以向特定的进程发送信号(SIGNAL)，缺省情况是发送终止(TERM) 的信号 ，即 kill PID 与 kill -15 PID 或 kill -TERM PID 是等价的。JVM 进程会监听 QUIT 信号(其值为 3)，当收到这个信号时，会打印出当时的线程堆栈和堆内存使用概要，相比 jstack，此时多了堆内存的使用概要情况。但 jstack 可以指定 -l 参数，打印锁的信息。
kill -3 PID
# 或
kill -QUIT PID
（2）获取heap dump
# 将 JVM 的堆 dump 到指定文件，如果堆中对象较多，需要的时间会较长，子参数 format 只支持 b，即二进制格式
jmap -dump:format=b,file=FILE_WITH_PATH PID
# 如果 JVM 进程未响应命令，可以加上参数 -F 尝试
jmap -F -dump:format=b,file=FILE_WITH_PATH PID
# 可以只 dump 堆中的存活对象，加上 live 子参数，但使用 -F 时不支持 live
jmap -dump:live,format=b,file=FILE_WITH_PATH PID
（3）获取堆概要信息
# -heap 参数用于查看指定 JVM 进程的堆的信息，包括堆的各个参数的值，堆中新生代、年老代的内存大小、使用率等
jmap -heap PID
# 同样，如果 JVM 进程未响应命令，可以加上参数 -F 尝试
jmap -F -heap PID
(4)gcutil、gccapacity
jstat -gcutil PID
jstat -gccapacity PID
