问题描述
公司中的一个项目用的ebean框架,有一次在程序的JAR包关闭过程中发现了如下错误
[Thread-2] INFO com.bigdata.datacenter.datasync.server.mysql.MysqlSubjectServer - 扫描程序关闭中...
[Thread-2] ERROR com.avaje.ebeaninternal.server.transaction.TransactionManager - NotifyOfCommit failed. L2 Cache potentially not notified.
java.util.concurrent.RejectedExecutionException: Task com.avaje.ebeaninternal.server.transaction.PostCommitProcessing$$Lambda$2/1368391951@6edfcc61 rejected from java.util.concurrent.ThreadPoolExecutor@31956fb3[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 16969]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2047)
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)
at com.avaje.ebeaninternal.server.lib.DaemonExecutorService.execute(DaemonExecutorService.java:41)
at com.avaje.ebeaninternal.server.core.DefaultBackgroundExecutor.execute(DefaultBackgroundExecutor.java:30)
at com.avaje.ebeaninternal.server.transaction.TransactionManager.notifyOfCommit(TransactionManager.java:313)
at com.avaje.ebeaninternal.server.transaction.JdbcTransaction.notifyCommit(JdbcTransaction.java:882)
at com.avaje.ebeaninternal.server.transaction.JdbcTransaction.flushCommitAndNotify(JdbcTransaction.java:925)
at com.avaje.ebeaninternal.server.transaction.JdbcTransaction.commit(JdbcTransaction.java:972)
at com.avaje.ebeaninternal.server.core.BeanRequest.commitTransIfRequired(BeanRequest.java:61)
at com.avaje.ebeaninternal.server.persist.DefaultPersister.executeOrQueue(DefaultPersister.java:113)
at com.avaje.ebeaninternal.server.persist.DefaultPersister.executeSqlUpdate(DefaultPersister.java:127)
at com.avaje.ebeaninternal.server.core.DefaultServer.execute(DefaultServer.java:1839)
at com.avaje.ebeaninternal.server.core.DefaultServer.execute(DefaultServer.java:1846)
at com.avaje.ebeaninternal.server.core.DefaultSqlUpdate.execute(DefaultSqlUpdate.java:98)
at com.avaje.ebean.SqlUpdate$execute.call(Unknown Source)
at com.bigdata.datacenter.datasync.service.impl.mysql.MysqlScanMonitorServiceImpl.updateCurrentAllDsState(MysqlScanMonitorServiceImpl.groovy:389)
at com.bigdata.datacenter.datasync.service.ScanMonitorService$updateCurrentAllDsState$0.call(Unknown Source)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:141)
at com.bigdata.datacenter.datasync.server.mysql.MysqlSubjectServer$MysqlSubjectShutdownThread.run(MysqlSubjectServer.groovy:169)
错误分析过程
通过报错日志,可以分析出上面的错误信息是一个JAVA线程池中最常见的一个错误,由于线程池关闭而拒绝了新的任务导致的异常。
在通过查看DaemonExecutorService类的源码后,发现是由此方法抛出的异常。
/**
* Execute the Runnable.
*/
public void execute(Runnable runnable) {
service.execute(runnable);
}
即ebean的service在执行某一个SQL任务时执行报错了。
DaemonExecutorService类源码:
package com.avaje.ebeaninternal.server.lib; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; /** * A "CachedThreadPool" based on Daemon threads. * <p> * The Threads are created as needed and once idle live for 60 seconds. */ public final class DaemonExecutorService { private static final Logger logger = LoggerFactory.getLogger(DaemonExecutorService.class); private final String namePrefix; private final int shutdownWaitSeconds; private final ExecutorService service; /** * Construct the DaemonThreadPool. * * @param shutdownWaitSeconds the time in seconds allowed for the pool to shutdown nicely. After * this the pool is forced to shutdown. */ public DaemonExecutorService(int shutdownWaitSeconds, String namePrefix) { this.service = Executors.newCachedThreadPool(new DaemonThreadFactory(namePrefix)); this.shutdownWaitSeconds = shutdownWaitSeconds; this.namePrefix = namePrefix; } /** * Execute the Runnable. */ public void execute(Runnable runnable) { service.execute(runnable); } /** * Shutdown this thread pool nicely if possible. * <p> * This will wait a maximum of 20 seconds before terminating any threads still * working. * </p> */ public void shutdown() { synchronized (this) { if (service.isShutdown()) { logger.debug("DaemonExecutorService[{}] already shut down", namePrefix); return; } try { logger.debug("DaemonExecutorService[{}] shutting down...", namePrefix); service.shutdown(); if (!service.awaitTermination(shutdownWaitSeconds, TimeUnit.SECONDS)) { logger.info("DaemonExecutorService[{}] shut down timeout exceeded. Terminating running threads.", namePrefix); service.shutdownNow(); } } catch (Exception e) { logger.error("Error during shutdown of DaemonThreadPool[" + namePrefix + "]", e); e.printStackTrace(); } } } }
在查看DaemonExecutorService类的所有代码后,可知上面的service是新建的一个cached类型的线程池,而在生产环境中报错的时间点又是在JAR包关闭时报错的,故可以锁定是由shutdown方法导致的。由此可以猜测是在jar包关闭过程中,ebean添加了一个shutdownHook的钩子函数,函数中执行了DaemonExecutorService类中的shutdown方法。而代码 s ervice.awaitTermination(shutdownWaitSeconds, TimeUnit.SECONDS)中的shutdownWaitSeconds值在这里就起了很重要的作用了,在等待shutdownWaitSeconds秒后就将线程池中的所有线程释放掉,并且不再接收任何其他的新任务了。所以如果在等待shutdownWaitSeconds秒后还有新的任务要去执行,线程池已经为空了,所以就会抛出拒绝任务的异常,即:
java.util.concurrent.RejectedExecutionException: Task com.avaje.ebeaninternal.server.transaction.PostCommitProcessing$$Lambda$2/1368391951@6edfcc61 rejected from java.util.concurrent.ThreadPoolExecutor@31956fb3[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 16969]
为了进一步验证此种臆想,通过IDEA的工具可查询到调用此shutdown的具体类在哪里。
通过查询shutdown方法调用层可以看到是在ShutdownManager.shutdown()这个方法中有主动调用的。而具体的为ShutdownHook.run()这个方法。
再进一步查看ShutdownManager的具体源码:
package com.avaje.ebeaninternal.server.lib; import com.avaje.ebean.common.SpiContainer; import com.avaje.ebeaninternal.api.ClassUtil; import com.avaje.ebeaninternal.api.SpiEbeanServer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import java.sql.Driver; import java.sql.DriverManager; import java.sql.SQLException; import java.util.ArrayList; import java.util.Enumeration; import java.util.List; /** * Manages the shutdown of the JVM Runtime. * <p> * Makes sure all the resources are shutdown properly and in order. * </p> */ public final class ShutdownManager { private static final Logger logger = LoggerFactory.getLogger(ShutdownManager.class); static final List<SpiEbeanServer> servers = new ArrayList<>(); static final ShutdownHook shutdownHook = new ShutdownHook(); static boolean stopping; static SpiContainer container; static { // Register the Shutdown hook registerShutdownHook(); } /** * Disallow construction. */ private ShutdownManager() { } public static void registerContainer(SpiContainer ebeanContainer) { container = ebeanContainer; } /** * Make sure the ShutdownManager is activated. */ public static void touch() { // Do nothing } /** * Return true if the system is in the process of stopping. */ public static boolean isStopping() { synchronized (servers) { return stopping; } } /** * Deregister the Shutdown hook. * <p> * In calling this method it is expected that application code will invoke * the shutdown() method. * </p> * <p> * For running in a Servlet Container a redeploy will cause a shutdown, and * for that case we need to make sure the shutdown hook is deregistered. * </p> */ public static void deregisterShutdownHook() { synchronized (servers) { try { Runtime.getRuntime().removeShutdownHook(shutdownHook); } catch (IllegalStateException ex) { if (!ex.getMessage().equals("Shutdown in progress")) { throw ex; } } } } /** * Register the shutdown hook with the Runtime. */ protected static void registerShutdownHook() { synchronized (servers) { try { String value = System.getProperty("ebean.registerShutdownHook"); if (value == null || !value.trim().equalsIgnoreCase("false")) { Runtime.getRuntime().addShutdownHook(shutdownHook); } } catch (IllegalStateException ex) { if (!ex.getMessage().equals("Shutdown in progress")) { throw ex; } } } } /** * Shutdown gracefully cleaning up any resources as required. * <p> * This is typically invoked via JVM shutdown hook. * </p> */ public static void shutdown() { synchronized (servers) { if (stopping) { // Already run shutdown... return; } if (logger.isDebugEnabled()) { logger.debug("Shutting down"); } stopping = true; deregisterShutdownHook(); String shutdownRunner = System.getProperty("ebean.shutdown.runnable"); if (shutdownRunner != null) { try { // A custom runnable executed at the start of shutdown Runnable r = (Runnable) ClassUtil.newInstance(shutdownRunner); r.run(); } catch (Exception e) { logger.error("Error running custom shutdown runnable", e); } } if (container != null) { // shutdown cluster networking if active container.shutdown(); } // shutdown any registered servers that have not // already been shutdown manually for (SpiEbeanServer server : servers) { try { server.shutdownManaged(); } catch (Exception ex) { logger.error("Error executing shutdown runnable", ex); ex.printStackTrace(); } } if ("true".equalsIgnoreCase(System.getProperty("ebean.datasource.deregisterAllDrivers", "false"))) { deregisterAllJdbcDrivers(); } } } private static void deregisterAllJdbcDrivers() { // This manually deregisters all JDBC drivers Enumeration<Driver> drivers = DriverManager.getDrivers(); while (drivers.hasMoreElements()) { Driver driver = drivers.nextElement(); try { logger.info("Deregistering jdbc driver: " + driver); DriverManager.deregisterDriver(driver); } catch (SQLException e) { logger.error("Error deregistering driver " + driver, e); } } } /** * Register an ebeanServer to be shutdown when the JVM is shutdown. */ public static void registerEbeanServer(SpiEbeanServer server) { synchronized (servers) { servers.add(server); } } /** * Deregister an ebeanServer. * <p> * This is done when the ebeanServer is shutdown manually. * </p> */ public static void unregisterEbeanServer(SpiEbeanServer server) { synchronized (servers) { servers.remove(server); } } }
package com.avaje.ebeaninternal.server.lib; /** * This is the ShutdownHook that gets added to Runtime. * It will try to shutdown the system cleanly when the JVM exits. * It is best to add your own shutdown hooks to StartStop. */ class ShutdownHook extends Thread { ShutdownHook() { } /** * Fired by the JVM Runtime on shutdown. */ public void run() { ShutdownManager.shutdown(); } }
由此可以确定,在ebean框架启动的时候绑定了一个shutdownHook函数,由它来处理ebean关闭时的一些操作。
通过上面的分析,如果要解决本文头的报错,需要将ebean关闭时的等待时间设长一点就好了,也就是DaemonExecutorService 类中的shutdownWaitSeconds的值,那么这个值又在哪里设的呢?
在通过进一步查询源码后,发现是在ServerConfig这个类中配置的,并且关闭时的默认等待时间为30秒
private int backgroundExecutorShutdownSecs = 30;
/**
* Return the Background executor shutdown seconds. This is the time allowed for the pool to shutdown nicely
* before it is forced shutdown.
*/
public int getBackgroundExecutorShutdownSecs() {
return backgroundExecutorShutdownSecs;
}
/**
* Set the Background executor shutdown seconds. This is the time allowed for the pool to shutdown nicely
* before it is forced shutdown.
*/
public void setBackgroundExecutorShutdownSecs(int backgroundExecutorShutdownSecs) {
this.backgroundExecutorShutdownSecs = backgroundExecutorShutdownSecs;
}
解决办法
于是解决办法就有了:根据项目的功能需要,配置对应的关闭等待时间即可。
如果是在ebean是在spring的xml中配置,可以这样配置(将关闭时间修改为10分钟,即60*10秒):
<bean id="serverConfig-mysql" class="com.avaje.ebean.config.ServerConfig">
<property name="name" value="test"/>
<property name="dataSource" ref="dataSourceFromMysql"/>
<property name="ddlGenerate" value="false"/>
<property name="ddlRun" value="false"/>
<!--关闭时线程数-->
<property name="backgroundExecutorSchedulePoolSize" value="1"/>
<!--关闭时线程等待时间-->
<property name="backgroundExecutorShutdownSecs" value="600"/>
<property name="externalTransactionManager">
<bean class="com.avaje.ebean.springsupport.txn.SpringAwareJdbcTransactionManager"/>
</property>
<property name="namingConvention">
<bean class="com.avaje.ebean.config.UnderscoreNamingConvention"/>
</property>
</bean>