接口测试 流量录制回放 JVM-Sanbox-Repeater 踩坑记录---repeater 启动初始化线程池失败

mellymeng · September 19, 2019 · Last by 郜志文 replied at October 30, 2019 · 670 hits

问题描述

环境: vmware虚拟机, centos7, JDK1.8
操作:按照通用流量录制回放工具 jvm-sandbox-repeater 尝鲜记录中步骤进行操作
执行完attach sanbox到目标进程,查看repeater日志时发现不对: 没有拉取repeater config, 事件注册失败

repeater日志正常异常对比

本地情况
2019-09-16 16:12:39 INFO initializing logback success. file=/root/.sandbox-module/cfg/repeater-logback.xml;
2019-09-16 16:12:39 INFO module on loaded,id=repeater,version=1.0.0,mode=ATTACH
2019-09-16 16:12:39 INFO onActive
正常情况:
2019-07-07 10:24:14 INFO initializing logback success. file=/Users/hengjiechen/.sandbox-module/cfg/repeater-logback.xml;
2019-07-07 10:24:14 INFO module on loaded,id=repeater,version=1.0.0,mode=ATTACH
2019-07-07 10:24:14 INFO onActive
2019-07-07 10:24:14 INFO pull repeater config success,config=com.alibaba.jvm.sandbox.repeater.plugin.domain.RepeaterConfig@4dddeb36
2019-07-07 10:24:15 INFO enable plugin http success
2019-07-07 10:24:15 INFO add watcher success,type=http,watcherId=1000
2019-07-07 10:24:16 INFO register event bus success in repeat-register

repeater日志出现异常了,那sanbox的日志呢

sanbox的日志

2019-09-16 16:12:39 default INFO  loading module, module=repeater;class=com.alibaba.jvm.sandbox.repeater.module.RepeaterModule;module-jar=/root/.sandbox-module/repeater-module.jar;
2019-09-16 16:12:39 default INFO active module when OnLoad, module=repeater
2019-09-16 16:12:39 default INFO active module, module=repeater;class=com.alibaba.jvm.sandbox.repeater.module.RepeaterModule;module-jar=/root/.sandbox-module/repeater-module.jar;
2019-09-16 16:12:39 default WARN loading module occur error when load-completed. module=repeater;
java.lang.ExceptionInInitializerError: null
at com.alibaba.jvm.sandbox.repeater.module.RepeaterModule.loadCompleted(RepeaterModule.java:122)
at com.alibaba.jvm.sandbox.core.manager.impl.DefaultCoreModuleManager.callAndFireModuleLifeCycle(DefaultCoreModuleManager.java:135)
at com.alibaba.jvm.sandbox.core.manager.impl.DefaultCoreModuleManager.load(DefaultCoreModuleManager.java:189)
at com.alibaba.jvm.sandbox.core.manager.impl.DefaultCoreModuleManager.access$300(DefaultCoreModuleManager.java:36)
at com.alibaba.jvm.sandbox.core.manager.impl.DefaultCoreModuleManager$InnerModuleLoadCallback.onLoad(DefaultCoreModuleManager.java:563)
at com.alibaba.jvm.sandbox.core.manager.impl.ModuleJarLoader.loadingModules(ModuleJarLoader.java:88)
at com.alibaba.jvm.sandbox.core.manager.impl.ModuleJarLoader.load(ModuleJarLoader.java:126)
at com.alibaba.jvm.sandbox.core.manager.impl.ModuleLibLoader.load(ModuleLibLoader.java:76)
at com.alibaba.jvm.sandbox.core.manager.impl.DefaultCoreModuleManager.reset(DefaultCoreModuleManager.java:590)
at com.alibaba.jvm.sandbox.core.server.jetty.JettyCoreServer.bind(JettyCoreServer.java:196)
at com.alibaba.jvm.sandbox.core.server.ProxyCoreServer.bind(ProxyCoreServer.java:39)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.alibaba.jvm.sandbox.agent.AgentLauncher.install(AgentLauncher.java:255)
at com.alibaba.jvm.sandbox.agent.AgentLauncher.agentmain(AgentLauncher.java:108)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386)
at sun.instrument.InstrumentationImpl.loadClassAndCallAgentmain(InstrumentationImpl.java:411)
Caused by: java.lang.IllegalArgumentException: null
at java.util.concurrent.ThreadPoolExecutor.<init>(ThreadPoolExecutor.java:1314)
at com.alibaba.jvm.sandbox.repeater.plugin.core.util.ExecutorInner.<clinit>(ExecutorInner.java:24)
... 23 common frames omitted
2019-09-16 16:12:39 default INFO loaded module-jar completed, loaded 1 module in module-jar=/root/.sandbox-module/repeater-module.jar, modules=[repeater]
2019-09-16 16:12:39 default INFO initialized server. actual bind to 0.0.0.0:12580
2019-09-16 16:12:39 default INFO server[0.0.0.0:12580] bind success.

原来,sanbox进行启动的时候就出了问题,repeater这边拉取配置还没有走到。

定位过程

第一步 根据报错的异常堆栈找到对应的代码出错的位置:ExecutorInner.java:24

Caused by: java.lang.IllegalArgumentException: null
at java.util.concurrent.ThreadPoolExecutor.<init>(ThreadPoolExecutor.java:1314)
at com.alibaba.jvm.sandbox.repeater.plugin.core.util.ExecutorInner.<clinit>(ExecutorInner.java:24)

第二步 查看代码 ExecutorInner

/**
* 通用线程池(非执行单一任务)
* <p>
*
* @author zhaoyb1990
*/

public class ExecutorInner {

private static ExecutorService executor = new ThreadPoolExecutor(8,
4 * Runtime.getRuntime().availableProcessors(),
30L, TimeUnit.SECONDS, new LinkedBlockingDeque<Runnable>(4096),
new BasicThreadFactory.Builder().namingPattern("repeater-common-pool-%d").build(),
new ThreadPoolExecutor.CallerRunsPolicy());

public static void execute(Runnable r) {
executor.execute(r);
}

public static Executor getExecutor() {
return executor;
}

public static <T> Future<T> submit(Callable<T> callable) {
return executor.submit(callable);
}
}

通过看ExecutorInner 代码的24行可以看出是第一句代码执行就失败了

private static ExecutorService executor = new ThreadPoolExecutor(8,
4 * Runtime.getRuntime().availableProcessors(),
30L, TimeUnit.SECONDS, new LinkedBlockingDeque<Runnable>(4096),
new BasicThreadFactory.Builder().namingPattern("repeater-common-pool-%d").build(),
new ThreadPoolExecutor.CallerRunsPolicy());

点击ThreadPoolExecutor 中看一下是什么情况,为什么跑异常

第三步 查看ThreadPoolExecutor

public ThreadPoolExecutor(int corePoolSize,
int maximumPoolSize,
long keepAliveTime,
TimeUnit unit,
BlockingQueue<Runnable> workQueue,
ThreadFactory threadFactory,
RejectedExecutionHandler handler) {
if (corePoolSize < 0 ||
maximumPoolSize <= 0 ||
maximumPoolSize < corePoolSize ||
keepAliveTime < 0)
throw new IllegalArgumentException();
if (workQueue == null || threadFactory == null || handler == null)
throw new NullPointerException();
this.acc = System.getSecurityManager() == null ?
null :
AccessController.getContext();
this.corePoolSize = corePoolSize;
this.maximumPoolSize = maximumPoolSize;
this.workQueue = workQueue;
this.keepAliveTime = unit.toNanos(keepAliveTime);
this.threadFactory = threadFactory;
this.handler = handler;
}

找到了 throw new IllegalArgumentException();的位置了,通过代码可以看出下面的几种情况一个满足就会抛出异常

corePoolSize < 0
maximumPoolSize <= 0
maximumPoolSize < corePoolSize
keepAliveTime < 0

那么我们就来看一下,到底是满足了哪个条件导致抛出的异常呢?

第四步 查看调用参数

private static ExecutorService executor = new ThreadPoolExecutor(8,
4 * Runtime.getRuntime().availableProcessors(),
30L, TimeUnit.SECONDS, new LinkedBlockingDeque<Runnable>(4096),
new BasicThreadFactory.Builder().namingPattern("repeater-common-pool-%d").build(),
new ThreadPoolExecutor.CallerRunsPolicy());

从代码中可以看出:

corePoolSize = 8 那么 corePoolSize < 0 不满足

maximumPoolSize =4 * Runtime.getRuntime().availableProcessors() 具体多少不知道 maximumPoolSize <= 0 不确定
maximumPoolSize < corePoolSize 不确定
keepAliveTime = 30L 那么 keepAliveTime < 0 不满足

现在就一个参数不确定是多少:maximumPoolSize

搜了一下Runtime.getRuntime().availableProcessors() 看到这个方法有一个问题就是并非都能返回你期望的数值
然后我灵机一动,会不会是我用的虚拟机,处理器核心数量有问题!!!!

第五步 查看虚拟机的处理器核心数量

vmware可以在虚拟机点击编辑虚拟机设置, 处理器中查看的可用处理器数量为1

如果你不是vmware你可以通过一个简单的java程序进行验证, HelloWorld.java

public class HelloWorld {
public static void main(String[] args) {
System.out.println(Runtime.getRuntime().availableProcessors());
}
}

然后执行编译和运行,打印出当前的处理器核心数

javac  HelloWorld.java  
java HelloWorld

这里可以知道 maximumPoolSize =4 * Runtime.getRuntime().availableProcessors() =4 那么 maximumPoolSize <= 0 不满足
maximumPoolSize < corePoolSize 满足!
所以这里满足抛出了异常, 原来repeater必须要至少要2个处理器核心数量!!!!

解决办法

所以需要给虚拟机增加处理器的核心数量。系统处理器的核心总数至少为2,我修改为4。 repeater启动正常,可以正常的录制回放了。

共收到 3 条回复 时间 点赞

非常清晰的思路和过程,点赞!

陈恒捷 回复

😊

点赞,我说怎么启动没报错,但是日志就是看着不正确呢

需要 Sign In 后方可回复, 如果你还没有账号请点击这里 Sign Up