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

mellymeng · 2019年09月19日 · 最后由 yimingtech 回复于 2020年11月28日 · 3593 次阅读

问题描述

环境： 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 个处理器核心数量！！！！