问题描述:系统上线一段时间后,客户反映接口响应特别慢,甚至没有响应,第一时间依次检查了网络、服务器资源使用情况,发现服务器CPU和内存占用率都非常的高。由于系统上线时间较紧迫,没有经过性能测试,排查初期也对系统各种代码排查。为了能够准确的定位系统出现的bug,于是对系统进行压测,项目中用到了AES加密算法,于是先对加密进行压测,当项目中的加解密开关打开后,压测5分钟过后,发现服务器CPU使用率达到160%~200%左右,内存持续增长,不见释放,导致后续压测接口请求响应速度非常慢,甚至无法响应。
问题排查:于是通过jstat命令查看GC回收统计,查看结果如下图:
从GC采集日志上看,发现FULLGC的次数较多,(O)年老代内存已使用空间100%,已经溢出。
jstat各参数含义如下:
S0 — Heap上的 Survivor space 0 区已使用空间的百分比
S1 — Heap上的 Survivor space 1 区已使用空间的百分比
E — Heap上的 Eden space 区已使用空间的百分比
O — Heap上的 Old space 区已使用空间的百分比
P — Perm space 区已使用空间的百分比
YGC — 从应用程序启动到采样时发生 Young GC 的次数
YGCT– 从应用程序启动到采样时 Young GC 所用的时间(单位秒)
FGC — 从应用程序启动到采样时发生 Full GC 的次数
FGCT– 从应用程序启动到采样时 Full GC 所用的时间(单位秒)
GCT — 从应用程序启动到采样时用于垃圾回收的总时间(单位秒)
其次通过查看进程堆内存使用情况,发现年轻代与年老代的内存已使用完,基本可以定位是频繁的GC导致CPU过高。
定位到是因为频繁的GC导致CPU过高之后,就排查代码,然后发现有一段加密代码频繁创建字符串对象,如下代码:
这段代码解释如下:就是说当AES加密完成后会产生大量的字节数据,上述代码将字节进行循环并将每一个字节数据转换为十六进制字符数据,循环操作中使用了+连接字符串,每次循环都会new一个StringBuilder对象,在这个过程中创建了很多临时的中间对象,最终拼接成一个大字符对象,jvm频繁的GC,而频繁的GC导致CPU过高,将这段代码改掉后问题解决。这次的bug是因为开发中经常会用到String,String使用频率之高,然而如果使用不当也会造成重大的bug。