背景
一台机器上部署了三个canal实例. CPU占用很高, 但是数据量不是很多. 虽然这里是针对canal的例子, 但是排除问题的方法也可以通用在其他应用上.
排查
找到具体的进程
从下面的图片中看, 这三个Java程序(都是Canal的实例)占用的CPU比较高。top命令查看这三个实例, 每个实例都稳定地使用了大约100%的CPU资源. 这个现象不正常, 所以开始了下面的排查之路。
image.png
一、GC问题导致?
1. 使用JDK自带的jstat 工具分析GC情况
jstat -gcutil 29204 2000 200 , 解释一下, 29204就是上面截图里的pid. 2000代表每隔2000毫秒检查一次, 200代表检查两百次, 200也可以省略, 表示不限次数.
通过这个命令, 发现gc也不是很频繁, 内存情况看起来还好, 不会因为这个导致CPU占用如此高.
$ jstat -gcutil 29204 2000 200
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 13.12 50.21 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 51.53 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 53.68 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 54.10 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 55.92 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 57.35 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 57.62 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 58.22 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 59.71 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 61.76 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 62.52 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 64.04 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 65.61 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 69.53 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 71.71 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 73.40 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 75.60 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 77.96 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 80.36 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
0.00 13.12 83.80 16.11 98.33 97.98 3333 51.509 2 0.098 51.607
.......
二、代码层面?
基本上排除了gc导致的问题后, 再看看代码层面.
1. 看看是哪些线程占用比较高
这里就用PID为29204的进程为例分析. top -Hp 29204
H代表显示线程信息
p用来指定进程id
image.png
2. 查看具体线程信息
从上图可以很明显的看出, 第一个PID为29205的线程使用的CPU最多, 达到了99.9%!, 其他线程只占用到了非常少的资源. 所以重点看下这个线程的信息.
由于查看线程(栈)信息需要用到jstack工具, 而这里显示的线程id是16进制形式的, 所以需要将我们已知的线程ID转成16进制形式.
$ printf %x 29205
7215
$
$ jstack 29204 | grep -A 200 7215
"main" #1 prio=5 os_prio=0 tid=0x00007f537800b950 nid=0x7215 runnable [0x00007f537fae7000]
java.lang.Thread.State: RUNNABLE
at com.alibaba.otter.canal.deployer.CanalLauncher.main(CanalLauncher.java:81)
"VM Thread" os_prio=0 tid=0x00007f53780c29c0 nid=0x721b runnable
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f537801c160 nid=0x7216 runnable
"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007f537801d6d0 nid=0x7217 runnable
"Gang worker#2 (Parallel GC Threads)" os_prio=0 tid=0x00007f537801ec40 nid=0x7218 runnable
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f53780201b0 nid=0x7219 runnable
"Concurrent Mark-Sweep GC Thread" os_prio=0 tid=0x00007f5378062730 nid=0x721a runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f53781116b0 nid=0x7224 waiting on condition
JNI global references: 255
3. 检查代码
3.1 1.1.3 alpha-2 版本的代码
这个版本的代码有个while()循环语句. 它就是消耗大量CPU资源的罪魁祸首. 在1.1.3的稳定版中, 这部分的代码已经被优化了. 下面是两个代码的对比.
public class CanalLauncher {
private static final String CLASSPATH_URL_PREFIX = "classpath:";
private static final Logger logger = LoggerFactory.getLogger(CanalLauncher.class);
public static volatile boolean running = false;
public static void main(String[] args) {
try {
running = true;
logger.info("## set default uncaught exception handler");
setGlobalUncaughtExceptionHandler();
// !!!!!!!!!!!!!!!!!!!! 节约篇幅省略代码 !!!!!!!!!!!!!!!!!!!!
if (managerDbConfigMonitor != null) {
managerDbConfigMonitor.start(new ManagerRemoteConfigMonitor.Listener<Properties>() {
@Override
public void onChange(Properties properties) {
try {
// 远程配置canal.properties修改重新加载整个应用
canalStater.destroy();
canalStater.start(properties);
} catch (Throwable throwable) {
logger.error(throwable.getMessage(), throwable);
}
}
});
}
while (running)
; // !!!!!!!!!!!!!!!!!注意这里的while循环!!!!!!!!!!!!!!!!!!
if (managerDbConfigMonitor != null) {
managerDbConfigMonitor.destroy();
}
} catch (Throwable e) {
logger.error("## Something goes wrong when starting up the canal Server:", e);
}
}
}
3.2 1.1.3版 代码
注意代码中的while循环加入了Thread.sleep(1000);的代码.
public class CanalLauncher {
private static final String CLASSPATH_URL_PREFIX = "classpath:";
private static final Logger logger = LoggerFactory.getLogger(CanalLauncher.class);
public static volatile boolean running = false;
public static void main(String[] args) {
try {
running = true;
logger.info("## set default uncaught exception handler");
// ........ 省略代码 .............
if (remoteConfigLoader != null) {
remoteConfigLoader.startMonitor(new RemoteCanalConfigMonitor() {
@Override
public void onChange(Properties properties) {
try {
// 远程配置canal.properties修改重新加载整个应用
canalStater.destroy();
canalStater.start(properties);
} catch (Throwable throwable) {
logger.error(throwable.getMessage(), throwable);
}
}
});
}
while (running) {
Thread.sleep(1000); // !!注意这里!!, 新的稳定版加入了这个代码.
}
if (remoteConfigLoader != null) {
remoteConfigLoader.destroy();
}
} catch (Throwable e) {
logger.error("## Something goes wrong when starting up the canal Server:", e);
}
}
}
解决
替换原来的jar包为1.1.3版本的jar包. 替换之后如下图, CPU占用率只有不到1%.
替换后的资源使用情况(图中红线框处, 替换的是三个canal实例中的一个):
image.png
网友评论