做网站推广什么好,网站界面结构,良精企业网站系统,广州市专业网站建设问题现象
最近#xff0c;笔者负责测试的某个算法模块机器出现大量报警#xff0c;报警表现为机器CPU持续高占用。该算法模块是一个优化算法#xff0c;本身就是CPU密集型应用#xff0c;一开始怀疑可能是算法在正常运算#xff0c;但很快这种猜测就被推翻#xff1a;同…问题现象
最近笔者负责测试的某个算法模块机器出现大量报警报警表现为机器CPU持续高占用。该算法模块是一个优化算法本身就是CPU密集型应用一开始怀疑可能是算法在正常运算但很快这种猜测就被推翻同算法同学确认后该算法应用只使用了一个核心而报警时一个算法进程占用了服务机器的全部8个核心这显然不是正常计算造成的。
定位步骤
首先按照CPU问题的定位思路进行定位对 Java 调用堆栈进行分析
1、使用top -c 查看 CPU 占用高的进程 从 top 命令的结果看19272 号进程 CPU 占用率最高基本确定问题是该进程引起可以从 Command 栏看到这正是算法模块程序注意图是线下4C机器上复现时的截图。
2、使用 ps -mp pid -o THREAD,tid,time命令定位问题线程。
ps -mp 19272 -o THREAD,tid,time
USER %CPU PRI SCNT WCHAN USER SYSTEM TID TIME
USER 191 - - - - - - 00:36:54
USER 0.0 19 - futex_ - - 19272 00:00:00
USER 68.8 19 - futex_ - - 19273 00:13:18
USER 30.2 19 - - - - 19274 00:05:50
USER 30.2 19 - - - - 19275 00:05:50
USER 30.2 19 - - - - 19276 00:05:50
USER 30.1 19 - - - - 19277 00:05:49
USER 0.4 19 - futex_ - - 19278 00:00:05
USER 0.0 19 - futex_ - - 19279 00:00:00
USER 0.0 19 - futex_ - - 19280 00:00:00
USER 0.0 19 - futex_ - - 19281 00:00:00
USER 0.4 19 - futex_ - - 19282 00:00:04
USER 0.3 19 - futex_ - - 19283 00:00:03
USER 0.0 19 - futex_ - - 19284 00:00:00
USER 0.0 19 - futex_ - - 19285 00:00:00
USER 0.0 19 - futex_ - - 19286 00:00:00
USER 0.0 19 - skb_wa - - 19362 00:00:00
从结果可以看到出现问题的线程主要是 19273-19277。
3、使用jstack查看出现问题的线程堆栈信息。
由于 jstack 使用的线程号是十六进制因此需要先把线程号从十进制转换为十六进制。
$ printf %x\n 19273
4b49
$ jstack 12262 |grep -A 15 4b49
main #1 prio5 os_prio0 tid0x00007f98c404c000 nid0x4b49 runnable [0x00007f98cbc58000]
java.lang.Thread.State: RUNNABLEat java.util.ArrayList.iterator(ArrayList.java:840)at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.updateSolution(MultiSkuDcAssignmentEasyScoreCalculator.java:794)at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.calculateScore(MultiSkuDcAssignmentEasyScoreCalculator.java:80)at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.calculateScore(MultiSkuDcAssignmentEasyScoreCalculator.java:17)at org.optaplanner.core.impl.score.director.easy.EasyScoreDirector.calculateScore(EasyScoreDirector.java:60)at org.optaplanner.core.impl.score.director.AbstractScoreDirector.doAndProcessMove(AbstractScoreDirector.java:188)at org.optaplanner.core.impl.localsearch.decider.LocalSearchDecider.doMove(LocalSearchDecider.java:132)at org.optaplanner.core.impl.localsearch.decider.LocalSearchDecider.decideNextStep(LocalSearchDecider.java:116)at org.optaplanner.core.impl.localsearch.DefaultLocalSearchPhase.solve(DefaultLocalSearchPhase.java:70)at org.optaplanner.core.impl.solver.AbstractSolver.runPhases(AbstractSolver.java:88)at org.optaplanner.core.impl.solver.DefaultSolver.solve(DefaultSolver.java:191)at app.DistributionCenterAssignmentApp.main(DistributionCenterAssignmentApp.java:61)VM Thread os_prio0 tid0x00007f98c419d000 nid0x4b4e runnableGC task thread#0 (ParallelGC) os_prio0 tid0x00007f98c405e800 nid0x4b4a runnableGC task thread#1 (ParallelGC) os_prio0 tid0x00007f98c4060800 nid0x4b4b runnableGC task thread#2 (ParallelGC) os_prio0 tid0x00007f98c4062800 nid0x4b4c runnableGC task thread#3 (ParallelGC) os_prio0 tid0x00007f98c4064000 nid0x4b4d runnableVM Periodic Task Thread os_prio0 tid0x00007f98c4240800 nid0x4b56 waiting on condition
可以看到除了 0x4b49 线程是正常工作线程其它都是 gc 线程。
此时怀疑是频繁 GC 导致的 CPU 被占满。
我们可以使用 jstat 命令查看 GC 统计
$ jstat -gcutil 19272 2000 10
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 0.00 22.71 100.00 97.16 91.53 2122 19.406 282 809.282 828.688
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 283 809.282 828.688
0.00 0.00 92.46 100.00 97.16 91.53 2122 19.406 283 812.730 832.135
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 284 812.730 832.135
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 285 815.965 835.371
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 285 815.965 835.371
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 286 819.492 838.898
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 286 819.492 838.898
0.00 0.00 100.00 100.00 97.16 91.53 2122 19.406 287 822.751 842.157
0.00 0.00 30.78 100.00 97.16 91.53 2122 19.406 287 825.835 845.240
重点关注一下几列YGC年轻代垃圾回收次数YGCT年轻代垃圾回收消耗时间FGC老年代垃圾回收次数FGCT老年代垃圾回收消耗时间GCT垃圾回收消耗总时间 可以看到20s 的时间中进行了 5 次 full GC仅仅耗费在 GC 的时间已经到了 17s。 1、增加启动参数展示详细 GC 过程。通过增加 jvm 参数更快暴露 GC 问题并展示 GC 详细过程java -Xmx1024m -verbose:gc。
[Full GC (Ergonomics) 1046527K-705881K(1047552K), 1.8974837 secs]
[Full GC (Ergonomics) 1046527K-706191K(1047552K), 2.5837756 secs]
[Full GC (Ergonomics) 1046527K-706506K(1047552K), 2.6142270 secs]
[Full GC (Ergonomics) 1046527K-706821K(1047552K), 1.9044987 secs]
[Full GC (Ergonomics) 1046527K-707130K(1047552K), 2.0856625 secs]
[Full GC (Ergonomics) 1046527K-707440K(1047552K), 2.6273944 secs]
[Full GC (Ergonomics) 1046527K-707755K(1047552K), 2.5668877 secs]
[Full GC (Ergonomics) 1046527K-708068K(1047552K), 2.6924427 secs]
[Full GC (Ergonomics) 1046527K-708384K(1047552K), 3.1084132 secs]
[Full GC (Ergonomics) 1046527K-708693K(1047552K), 1.9424100 secs]
[Full GC (Ergonomics) 1046527K-709007K(1047552K), 1.9996261 secs]
[Full GC (Ergonomics) 1046527K-709314K(1047552K), 2.4190958 secs]
[Full GC (Ergonomics) 1046527K-709628K(1047552K), 2.8139132 secs]
[Full GC (Ergonomics) 1046527K-709945K(1047552K), 3.0484079 secs]
[Full GC (Ergonomics) 1046527K-710258K(1047552K), 2.6983539 secs]
[Full GC (Ergonomics) 1046527K-710571K(1047552K), 2.1663274 secs]
至此基本可以确定CPU 高负载的根本原因是内存不足导致频繁 GC。
如何进行定位
以上介绍了一些常见的内存泄漏场景在实际的问题中还需要针对具体的代码进行确定排查。下面结合之前的频繁 GC 问题讲解一下定位的思路以及相关工具的使用方法。
线上定位
对于线上服务如果不能开启 Debug 模式那么可用的工具较少。推荐方式 使用 top -c 命令查询 Java 高内存占用程序的进程 pid。然后使用 jcmd 命令获取进程中对象的计数、内存占用信息。
$ jcmd 24600 GC.class_histogram |head -n 10
24600:num #instances #bytes class name
----------------------------------------------1: 2865351 103154208 [J2: 1432655 45844960 org.optaplanner.core.impl.localsearch.scope.LocalSearchMoveScope3: 1432658 34383792 org.optaplanner.core.api.score.buildin.bendablelong.BendableLongScore4: 1193860 28652640 org.optaplanner.core.impl.heuristic.selector.move.generic.ChangeMove5: 241961 11986056 [Ljava.lang.Object;6: 239984 5759616 java.util.ArrayList
结果中#instances 为对象数量#bytes 为占用内存大小单位是 byteclass name 为对应的类名。 排名第一的是 Java 原生类型实际上是 long 类型。
另外要注意的是结果中的类可能存在包含关系例如一个类中含有多个 long 类型数据那 long 对应的计数也会增加所以我们要排除一些基本类型它们可能是我们程序中使用导致的计数增加重点关注我们程序中的类。
如果仅仅有 jcmd 的结果其实很难直接找到问题的根本原因。如果问题不能在线下复现我们基本上只能针对计数较多的类名跟踪变量的数据流重点关注 new 对象附近的代码逻辑。观察代码逻辑时重点考虑上述几种常见内存泄漏场景。
线下定位
如果内存泄漏问题可以在线下复现那么问题定位的工具就比较丰富了。下面主要推荐的两种工具VisualVM IDEA。
这里主要讲一下IDEA调试定位思路
使用 IDEA 调试器定位内存泄漏问题
如果以上过程依然不能有效的分析出问题的根本原因还可以使用 IDEA 的调试功能进行定位。 配置好程序的运行参数正常复现问题之后对程序打断点并逐步追踪。
重点关注的是程序需要大量运行时间的代码部分我们可以使用调试暂停功能获得一个内存快照。 然后在此运行并暂停这时候在调试的 Memory 视图中可以看到哪些类在快速增加。基本上可以断定问题的原因是两次运行中 new 该对象的语句。
