ebean报错：NotifyOfCommit failed. L2 Cache potentially not notified解决办法

问题描述

公司中的一个项目用的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>