这是我前段时间在产线排查CPU低,Load高的问题过程整理,内容大纲
- 问题背景
- 排查过程
- 总结
问题背景
基于k8s部署的xxl-job 2.1.X版本,1调度+1执行,job数量100+,容器配额为2核2G(低配节约成本)发布产线后10~15天后必收到预警短信,调度服务无法链接到执行器,即connection exception,导致job无法按时执行,产线事关紧急,只能重启执行器jvm进程,反反复复甚是不心安
排查过程
shell top -H -p x 显示如图
其5,15分钟load 这么高难怪服务器不响应,仔细看CPU不高,内存使用也高,使用 arthas查看gc,堆数据都比较正常(未截图保存),怀疑系统在做无用功,所谓线程上下文切换。随着推测查看日志目录发现有两处疑点其一,GC日志按时间切分文件,如图
-Xloggc:/var/logs/job-execute.service.panli.com/gc%t.log +PrintGCDateStamps +UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=50M
本意是滚动输出10个大小50M的日子文件,但loggc参数路径不知为何gc%t.log 结尾(可能手误)吧,导致只要产生gc时基本都会新建文件,于是径改成gc.log。
疑点其二,xxl-job每次执行任务都会自动生成任务ID(自增)在执行端建立文件(未截图保存),记忆中大概几百个日志文件,如果任务越频繁则频繁创建文件,于是删除代码中日志代码即日志替换为log4j2
//XxlJobExecutor.java -> start
//init logpath
//XxlJobFileAppender.initLogPath(logPath);
//XxlJobLogger.java -> logDetail
// appendlog
//String logFileName = XxlJobFileAppender.contextHolder.get();
//if (logFileName!=null && logFileName.trim().length()>0) {
// XxlJobFileAppender.appendLog(logFileName, formatAppendLog);
//} else {
logger.info(">>>>>>>>>>> {}", formatAppendLog);
//}
第一次排查上线后10~15天后报警不停,跟之前一样还是调度器无法执行器(大量的connection exception),vimstat 查看如图
其cs还很高,还是在切换!,只能从框架代码查起,xxl-job 框架简图(根据代码理解)如下
理想中的设计是调度器管理JOB触发事件,执行器接到任务通知直接执行返回结果,但xxl-job执行器设计还是比较复杂的,类似流水线模式,顺代码查下去,改动如下:
//XxlJobExecutor.java -> initRpcProvider
// 原 ,这里设置线程池大小20,200原因不得而知
// xxlRpcProviderFactory.setCorePoolSize(20);
// xxlRpcProviderFactory.setMaxPoolSize(200);
//
// 改:
xxlRpcProviderFactory.setCorePoolSize(Runtime.getRuntime().availableProcessors());
xxlRpcProviderFactory.setMaxPoolSize(Runtime.getRuntime().availableProcessors());
目的缩小线程池大小,如果有任务堆积则直接扩容即可。
// JobThread.java -> toStop
// 原
// this.toStop = true;
// this.stopReason = stopReason;
//
// 改
TriggerParam triggerParam = new TriggerParam();
triggerParam.setJobId(Integer.MIN_VALUE);
triggerQueue.add(triggerParam);
this.interrupt();
toStop作为业务kill 线程操作,这里加入终止任务是为了run方法跳出循环。
// JobThread.java -> run
// 原
// triggerParam = triggerQueue.poll(3L, TimeUnit.SECONDS);
//
// 改
triggerParam = triggerQueue.take();
// 如果是终止任务则跳出循环
if (Integer.MIN_VALUE == triggerParam.getJobId()) {
break;
}
原代码中每3秒有无任务都会唤醒线程,arthas 统计大概有90+线程,这里我认为是出现大量CS的地方。
改后的代码目的是没有任务则不需要唤醒线程,只有有任务通知才唤醒线程,另外增加是否是终止任务判断,如果是则跳出循环使之结束。
//XxlJobExecutor.java -> registJobThread
// 原
// JobThread newJobThread = new JobThread(jobId, handler);
// newJobThread.start();
// 改
JobThread newJobThread = new JobThread(jobId, handler);
newJobThread.setName("job-"+jobId);
newJobThread.start();
这里只增加线程名,方便排错。
其他改动:
- 移除原繁琐的日志记录改为logger4j2;
- AdminBizImpl npe问题修正;
- 任务异常策略源码中会死循环需要在后台手动kill job线程,这是非常危险的,如果大量任务异常,只会增加系统的负载,最终系统无法正常运行,改为任务执行无论如何都返回结果
重新发布后第10天统计
top - 03:57:29 up 10 days, 19:42, 0 users, load average: 0.03, 0.02, 0.00
系统负载尚可,vmstat统计
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 0 119796 157464 2835828 0 0 0 18 7 4 1 1 98 0 0
0 0 0 119284 157464 2835832 0 0 0 16 1451 1895 18 1 82 0 0
0 0 0 119348 157464 2835836 0 0 0 0 921 1642 1 1 99 0 0
1 0 0 119348 157464 2835836 0 0 0 116 903 1489 4 1 95 0 0
0 0 0 118908 157464 2835840 0 0 0 16 1329 1880 15 1 85 0 0
0 0 0 118908 157464 2835840 0 0 0 0 727 1345 0 0 99 0 0
2 0 0 119340 157464 2835840 0 0 0 0 865 1583 1 1 99 0 0
0 0 0 119728 157464 2835840 0 0 0 0 1043 1742 1 1 99 0 0
0 0 0 119216 157464 2835840 0 0 0 56 889 1603 2 1 98 0 0
0 0 0 119224 157464 2835840 0 0 0 0 953 1737 1 1 99 0 0
这里CS还是有些高,原因在于每个job一个线程及其他jvm线程,如果要彻底更改,则需要改变框架job执行方式,即:即时执行JOB,移除每个job一个线程的设计,改动量比较大或者增加节点(本质上还是会出现大量CS)
总结
- 线程技术利用好是把利器,反之则是凶器
- 系统负载高多数情况是线程在做无用功,排查是否频繁创建文件,线程sleep,是否频繁唤醒线程
- 选择开源框架需要关注官方更新进度
- 反复出现的问题需要有改动代码的心理准备
- 在源码中增加功能需要做适配,以方便升级框架——目前而言我修改了框架源码未做任何兼容处理,不能升级框架,只能替换