一、引言
最近线上出现了java.util.concurrent.ExecutionException: java.lang.NoClassDefFoundError: Could not initialize class com.**.Util,导致详情查询出现问题。
这个问题其实之前也出现过,找了框架的排查没有查到结果,不过之前作者不知道这个事情。
这次一看到这种报错,作者就知道一定是静态变量或者static块导致类加载失败。
二、排查
1、问题堆栈
可以清楚的看到这个类没有被初始化,所以导致了NoClassDefFoundError
2、为什么会类初始化失败
在《深入理解Java虚拟机》中,类的初始化是类加载的最后一个阶段,正常的类加载分为:加载、验证、准备、解析、初始化五个阶段
这时候需要看看类的初始化阶段都做了什么事情,这里可以看到主要是执行<clint>构造器,里面的动作就是执行静态语句块还有为类的成员变量赋值
<clinit>
构造器执行失败(抛出异常),那么这个类的加载过程会被中断,并且这个类将无法被使用。如果其他类依赖于这个类,那么这些类也无法被使用
这时候就要看看Util里面有什么静态语句块和类的成员变量,很明显只有一些静态的成员变量
ENV_STR、clientCache、log这些都不用看
出问题的一定是MapConfig.get("clients.properties",Feature.create().setFailOnNotExists(false).build()) 和 mapConfig.asMap() 这两个静态变量的加载问题
这是开源配置执行qconfig的写法,意思是加载一个文件做map使用
GitHub - qunarcorp/qconfig: Qconfig中心式配置中心,提供高可用的配置托管/动态热更新服务。 具备丰富的格式支持和简单易用的API
public class Util { private static LoggerService log = LoggerServiceFactory.getLoggerService(Util.class); private static MapConfig mapConfig = MapConfig.get("**.properties", Feature.create().setFailOnNotExists(false).build()); private static final String ENV_STR = "env"; private static Map<String, String> configs = mapConfig.asMap(); private static Map<String, ClientBase<?>> clientCache = Maps.newConcurrentMap(); public void listeningConfig() { mapConfig.addListener(conf -> { }); } */ public static <Req, Res> Res call(String title, Req req, Task<Res> task) { } } |
作者起初是怀疑MapConfig.get("clients.properties",这个配置文件没有导致的,但是想想也不太可能,没有配置文件几乎是必现的,不会是现在这么低频
ld也提醒了我他setFailOnNotExists,没有文件也不会拦截
那就是mapConfig.asMap()或者MapConfig.get为之后的asMap埋下了隐患
3、查看QConfig源码
到这一步就必须要看看QConfig的源码了,get操作看起来即使文件不存在也会埋下异步监听器,随时获取这个配置文件
public static MapConfig get(String groupName, String fileName, Feature feature) { return (MapConfig) DATA_LOADER.load(groupName, fileName, feature, GENERATOR); } protected <T> Configuration<T> load(String groupName, String fileName, Feature feature, Generator<T> generator, boolean acceptPlaceholder) { FilenameUtil.checkFilename(fileName); fileName = fileName.toLowerCase(); if (Strings.isNullOrEmpty(groupName)) groupName = GroupNameUtil.getGroupNameIgnoreCorp(); if (feature == null) feature = Feature.DEFAULT; Meta meta = feature instanceof AdvancedFeature ? new Meta(groupName, fileName, ((AdvancedFeature) feature).overrideEnvironment()) : new Meta(groupName, fileName); checkMeta(meta); String key = meta.getKey(); FileStore currentStore = USED_CONFIGS.get(key); if (currentStore != null && (!(currentStore instanceof FileStorePlaceholder) || acceptPlaceholder)) { return currentStore.getConfig(); } FileStore expectedNewStore = acceptPlaceholder ? new FileStorePlaceholder(meta, feature, CONFIG_LOGGER) : new FileStore<>(meta, generator.create(feature, meta), feature, CONFIG_LOGGER); AtomicReference<FileStore> newStoreHolder = new AtomicReference<>(); FileStore latestStore = USED_CONFIGS.compute(key, (k, ov) -> { if (ov != null && (!(ov instanceof FileStorePlaceholder) || acceptPlaceholder)) { return ov; } else { newStoreHolder.set(expectedNewStore); return expectedNewStore; } }); FileStore newStore = newStoreHolder.get(); if (newStore == null) { return latestStore.getConfig(); } else { newStore.init(); } if (newStore.isLoaded()) { return newStore.getConfig(); } Version ver = VERSIONS.get(meta); if (ver != null) { ver.addListener(() -> { ListenableFuture<VersionProfile> future = newStore.initLoad(ver.updated.get(), ver.needCheckUpdateForLocalCache(), CLIENT, EXECUTOR); try { ver.setUpdated(future.get()); } catch (Exception e) { LOGGER.error("[[title=qconfig]]" + "init load config failed", e); } finally { ver.setInSync().setLoaded(); if (LONG_POLLER != null) LONG_POLLER.appendLoading(meta); } }, EXECUTOR); } else { Version old = VERSIONS.putIfAbsent(meta, new Version(VersionProfile.ABSENT)); if (old == null) { ListenableFuture<VersionProfile> future = newStore.initLoad(VersionProfile.ABSENT, true, CLIENT, EXECUTOR); future.addListener(() -> { Version currentVersion = VERSIONS.get(meta); try { currentVersion.setUpdated(future.get()); } catch (Exception e) { LOGGER.error("[[title=qconfig]]" + "init load config failed", e); } finally { currentVersion.setInSync().setLoaded(); if (LONG_POLLER != null) LONG_POLLER.appendLoading(meta); } }, Constants.CURRENT_EXECUTOR); } } return newStore.getConfig(); } |
asMap看起来就是拿到map文件的结果,如果current.get()没有数据,他会直接等异步监听器
public Map<String, String> asMap() { waitFistLoad(); return ref; } protected void waitFistLoad() { if (current.get() != null) return; try { initFuture().get(); } catch (ExecutionException e) { log.debug("[[title=qconfig,app={},dataId={}]]" + "[wait first load FAILURE] {}", appId, this.fileName, this.meta, e); Throwable cause = e.getCause(); if (cause instanceof ResultUnexpectedException) { throw (ResultUnexpectedException) cause; } else { ResultUnexpectedException ex = new ResultUnexpectedException(e.getMessage()); ex.initCause(cause); throw ex; } } catch (Throwable e) { log.warn("[[title=qconfig,app={},dataId={}]]" + "[wait first load FAILURE] {}", appId, this.fileName, this.meta, e); ResultUnexpectedException ex = new ResultUnexpectedException( "First load errored: " + meta.getKey() ); ex.initCause(e); throw ex; } } |
4、查找日志
看了这两个代码之后,作者想到的是QConfig会打warn日志,那么如果是这些原因,在服务刚刚启动的时候就会有证据
果然顺着服务的日志一直往前面划,找到了asMap被中断产生了InterruptedException,而且MapConfig.get找不到配置文件的日志还在他后面,这就说明get生成了子任务,由于网络波动执行查找文件慢了一些,asMap在get的时候执行过久被中断,导致外层收到这个异常,类初始化失败
5、验证猜想
猜想之后还需要验证,作者在本地启动进行测试,然后发现只要作者在MapConfig.get里面打断点,让他执行慢一点,asMap里面的get都会走到中断
应该是LockSupport.park进行挂起等待之后,发现执行过长线程中断,经过反复测试20几次,大概阻塞15s左右(手机计时,3->5->10->15)就会导致asMap中断
6、文件强校验验证猜想
作者又进行了MapConfig.get不允许文件为空的校验,一样会产生打断
get 是发一个异步拉配置请求,asMap会等到get的结果 然后返回,如果get请求没响应 asMap是阻塞的
有没有setFailOnNotExists应该是不影响的,应该都会中断
这样看起来有个问题:谁做了中断,future还是qconfig或者jvm?
jvm应该不会,因为一视同仁,setFailOnNotExists不会影响他去中断谁
public class UtilTest { private static LoggerService log = LoggerServiceFactory.getLoggerService(Util.class); private static MapConfig mapConfig = MapConfig.get("**.properties"); private static final String ENV_STR = "env"; private static Map<String, String> configs = mapConfig.asMap(); private static Map<String, ClientBase<?>> clientCache = Maps.newConcurrentMap(); public void listeningConfig() { mapConfig.addListener(conf -> { }); } public static String test() { return "justTest"; } } |
再接着试,作者发现这都是在线程池当中执行的,我们的线程池会有一个超时时间,超时之后就会future.cancel,中断子线程,测试环境是30s,线上只需要4s就会导致这种问题
正常子线程是不管这个标志位的,但是qconfig使用谷歌的AbstractFuture会查询当前线程是否是中断的,是的话就抛异常,然后就会导致这个类初始化失败
public static <T> T getFuture(Future<T> future, long timeout) { try { return future.get(timeout, TimeUnit.MILLISECONDS); } catch (Exception e) { log.error(TITLE, "future timeout", e); future.cancel(true); return null; } } |
按照这个思路,在一大堆的异常中应该在类初始化失败之前有一些异常,显示子线程取消,果然入参和超时取消有4s,应该是网络波动或者cpu卡顿导致程序这个线程执行停顿,正常都是ms级别
三、解决方案
1、提前初始化
增加这个类的使用进行类加载,如果有异常波动导致get处理耗时,在点火阶段给他卡住,就不会导致后续流量进入引起太多问题
一般是需要使用他的静态变量或者方法,这是比较合适的,但是Util的都是private,那就只能给他new一下的,其他的方法都有点过于侵入
2、修改Util
直接他配置文件的获取放在构造方法里面异常catch住,因为这是一个可有可无的配置文件,不过需要考虑并发还有锁当前class,做好初始化工作
但是改他会影响很多地方,暂时不合适,后续还是应该集中整改
3、切换Util
后续把call方法单独实现一下,然后切换,这个比较平稳
四、总结
这次的排查有三个关键点:
1、深刻理解Java的类加载,这样才能把目光放在静态变量导致类初始化阶段失败,不然不会去看这个工具类的静态变量做了什么初始化
2、阅读QConfig的源码,了解里面map初始化会打印warn日志,这样才会在clog追溯找服务刚刚启动时候的日志,不然找不到静态map加载失败的证明
3、反复试验,复现该场景,并且确认中断场景:线程池+工具类使用QConfig+执行超时future.cancel
最终对我们编码有一个启发,线程池使用的工具类如果使用了一些需要加载外部数据的静态变量,需要考虑这种类初始化失败的情况,这种工具类就太多了,应该扫描处理集中整改