今天LN现场售后人员反馈一台服务器上的业务办理出现问题,主要是运行缓慢,附带卡顿现象,没办法救急入救火就远程过去查查原因,本文用于记录排查过程并整理一些相关资料,希望对遇到类似问题的小伙伴们有帮助
排查过程:
第一步
先看看服务器情况,使用top命令可以监控linux的系统状况,主要用户查看显示系统中各个进程的资源占用情况,察看信息后发现CPU 占用高达100%+
top命令格式
格式:top [-] [d delay] [q] [c] [S] [s] [i] [n] [b]
- d : 改变显示的更新速度,
- q : 没有任何延迟的显示速度
- c : 切换显示模式,共有两种模式,一是只显示执行档的名称,另一种是显示完整的路径与名称
- S : 累积模式,会将己完成或消失的子进程 ( dead child process ) 的 CPU time 累积起来
- s : 安全模式,将交谈式指令取消, 避免潜在的危机
- i : 不显示任何闲置 (idle) 或无用 (zombie) 的进程
- n : 更新的次数,完成后将会退出 top
- b : 批次档模式,搭配 "n" 参数一起使用,可以用来将 top 的结果输出到档案内
top 列含义
列名 | 含义 |
PID | 进程id |
PR | 优先级 |
NI | nice值。负值表示高优先级,正值表示低优先级 |
VIRT | 进程使用的虚拟内存总量,单位kb。VIRT=SWAP+RES |
RES | 进程使用的、未被换出的物理内存大小,单位kb。RES=CODE+DATA |
SHR | 共享内存大小,单位kb |
S | 进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程 |
%CPU | 上次更新到现在的CPU时间占用百分比 |
%MEM | 进程使用的物理内存百分比 |
TIME+ | 进程使用的CPU时间总计,单位1/100秒 |
COMMAND | Command Name/Line命令名/命令行。 |
第二步
CPU占比高,此问题多数是JVM 因堆内存不足频繁Full GC引起 。垃圾回收是根据可达性分析算法将不在GC Root根的引用链上的对象回收, 计算时会引发JVM 中的STW事件(stop the world),此事件使Java应用程序暂时停顿,被STW中断的应用程序线程会在完成GC之后恢复,这个停顿就让业务出现卡顿现象 ,
所以使用jstat命令查看 Jstat命令查看JVM 信息,出乎我的意料,从信息中发现没有出现频发FGC的情况出现。一般频繁full gc的时候, FGC的次数会很多,GCT的时间会很大, 但我查询信息中FGC的次数并不大,因此这次问题不是 Full GC引起的CPU高负载+卡顿现象
jstat 命令格式
jstat [-命令选项] [vmid] [间隔时间/毫秒] [查询次数]
jstat 列含义
列名 | 含义 |
S0C | 第一个幸存区的大小 |
S1C | 第二个幸存区的大小 |
S0U | 第一个幸存区的使用大小 |
S1U | 第二个幸存区的使用大小 |
EC | 伊甸园区的大小 |
EU | 伊甸园区的使用大小 |
OC | 老年代大小 |
OU | 老年代使用大小 |
YGC | 年轻代垃圾回收次数 |
YGCT | 年轻代垃圾回收消耗时间 |
FGC | 老年代垃圾回收次数 |
FGCT | 老年代垃圾回收消耗时间 |
GCT | 垃圾回收消耗总时间 |
第三步
不是JVM问题那么就只能查看线程栈了 ,所以使用jstack 查询这个线程到底在干嘛,使用top -Hp 进程号命令找到 CPU 消耗最多的线程号,从中发现正在运行的线程十分可疑,其占用CUP很高,将其转换成16进制 再从jstatck栈日志中查看211e的信息,信息如下显示
printf "0%x\n" PID
此应用是一个老系统,老系统使用了ehcache当做缓存,从下发的栈信息发现,ehcache 正在执行OverflowDiskWriteTask任务,这个任务是ehcache超过最大缓存数后将缓存内容写入磁盘的操作,然后查看磁盘上的文件大小仍在增长,
所以本问题是由于ehcache在不停的做写操作占用CPU,让CPU飙升
"daoCache.data" daemon prio=10 tid=0x00007f199d281000 nid=0x211e runnable [0x00007f1a01942000]
java.lang.Thread.State: RUNNABLE
at java.io.ByteArrayOutputStream.<init>(ByteArrayOutputStream.java:77)
at net.sf.ehcache.util.MemoryEfficientByteArrayOutputStream.<init>(MemoryEfficientByteArrayOutputStream.java:50)
at net.sf.ehcache.util.MemoryEfficientByteArrayOutputStream.serialize(MemoryEfficientByteArrayOutputStream.java:89)
at net.sf.ehcache.store.compound.factories.DiskStorageFactory.serializeElement(DiskStorageFactory.java:300)
at net.sf.ehcache.store.compound.factories.DiskStorageFactory.write(DiskStorageFactory.java:280)
at net.sf.ehcache.store.compound.factories.DiskStorageFactory$DiskWriteTask.call(DiskStorageFactory.java:385)
at net.sf.ehcache.store.compound.factories.DiskOverflowStorageFactory$OverflowDiskWriteTask.call(DiskOverflowStorageFactory.java:246)
at net.sf.ehcache.store.compound.factories.DiskOverflowStorageFactory$OverflowDiskWriteTask.call(DiskOverflowStorageFactory.java:235)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
jstack 格式
jstack [-l] pid
- -f 当’jstack [-l] pid’没有相应的时候强制打印栈信息
- -l 长列表. 打印关于锁的附加信息,例如属于java.util.concurrent的ownable synchronizers列表.
- -m 打印java和native c/c++框架的所有栈信息.
- -h 或者 -help 打印帮助信息
- pid 需要被打印配置信息的java进程id
解决方案:
问题是由于ehcache在不停的做写操作占用CPU,让CPU飙升,系统不能重启, 因此临时处理方案是从JBOSS控制台将其缓存清空,清空后问题解决
问题解决后看了下 ehcache.xml中的缓存配置, 配置中缓存的闲置时间timeToIdleSeconds时间为4小时,缓存个数是5W。从配置上分析怀疑是业务代码中存在问题,4小时内缓存了大量命中率低的数据,造成缓存数超过5W后ehcache开启将缓存写入磁盘的操作,所以暂时给售后以下建议
- 建议售后先将闲置时间timeToIdleSeconds修改为1小时, 此处也不敢直接修改的太小,有点儿担心不了系统造成系统其他问题,打算观察一段时间后再来决定设置的值
- 建议将overflowToDisk=true,修改成false禁止将缓存写入磁盘,毕竟缓存是用于提高读取速度。
其实 ehcache 已经很少被使用了,reidis作为缓存是当今主流, 考虑到迁移需要投入的人力成本,迁移问题暂时搁置吧,考虑成本无法把事情做到最好估计也是很多人心中的痛