Connection is not available, request timed out after 30000ms

[Deno Vichas]

I've seen this issue a couple times now.    Reducing my pool from 20 to 10 might have made things a little better. It's hard to say...   At 10 the app was able to recover but hiccuped a few times during a 4 hour window.  When this happened at 20 I had reboot the ec2 instances the app in running on.  Could somebody explain what I'm seeing?

spring 4.3.7

spring-data-jpa 1.11.3

hikari - 2.6.2

hikari-jpa 1.0.0

hiberante 5.2.10

running against RDS Mysql 

Caused by: java.sql.SQLTransientConnectionException: DB_POOL - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:602)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:195)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:145)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:115)
     ... 133 common frames omitted

My debug at the time of this exception - 

 

[2017-06-19 18:40:45.663] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:41:15.663] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:41:45.664] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:42:15.664] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:42:45.664] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=10, idle=0, waiting=11)
[2017-06-19 18:42:48.240] [http-nio-8080-exec-236] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=10)
[2017-06-19 18:42:48.243] [http-nio-8080-exec-261] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=9)
[2017-06-19 18:42:48.261] [http-nio-8080-exec-264] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=8)
[2017-06-19 18:42:48.276] [http-nio-8080-exec-256] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=7)
[2017-06-19 18:43:15.665] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:43:45.665] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=1, idle=9, waiting=0)
[2017-06-19 18:44:15.665] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=1, idle=9, waiting=0)
[2017-06-19 18:44:45.666] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:45:15.666] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:45:45.666] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:46:15.667] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:46:45.667] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=10, idle=0, waiting=11)
[2017-06-19 18:47:10.360] [http-nio-8080-exec-250] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=11)
[2017-06-19 18:47:10.372] [http-nio-8080-exec-214] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=10)
[2017-06-19 18:47:10.373] [http-nio-8080-exec-259] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Timeout failure stats (total=10, active=10, idle=0, waiting=9)
[2017-06-19 18:47:15.668] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:47:45.668] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=1, idle=9, waiting=0)
[2017-06-19 18:48:15.668] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=0, idle=10, waiting=0)
[2017-06-19 18:48:45.669] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:390 - DB_POOL - Pool stats (total=10, active=1, idle=9, waiting=0)

My Config -

import com.zaxxer.hikari.HikariConfig;

import com.zaxxer.hikari.HikariDataSource;

import org.flywaydb.core.Flyway;

import org.magic.config.annotation.DisableForTesting;

import org.magic.config.annotation.Testing;

import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

import org.springframework.context.annotation.Bean;

import org.springframework.context.annotation.Configuration;

import org.springframework.context.annotation.Primary;

import org.springframework.core.env.Environment;

import javax.annotation.Resource;

import javax.sql.DataSource;

@Configuration

public class DataSourceConfig {

    public static final int THREE_MINS = 60 * 3 * 1000;

    private final Logger log = LoggerFactory.getLogger(DataSourceConfig.class);

    @Resource

    private Environment _env;

    

    public DataSourceConfig() {

        log.info("loading DataSource config");

    }

    

    @Bean(destroyMethod = "close")

    @Primary

    public DataSource dataSource() {

        return new HikariDataSource(hikariConfig());

    }

    @Bean(destroyMethod = "close")

    @Testing

    public DataSource testDataSource() {

        HikariConfig config = hikariConfig();

        config.setPoolName("TEST_DB_POOL");

        config.setJdbcUrl(_env.getProperty("db.test.url"));

        config.setUsername(_env.getProperty("db.test.user"));

        config.setPassword(_env.getProperty("db.test.pass"));

        return new HikariDataSource(config);

    }

    private HikariConfig hikariConfig() {

        HikariConfig config = new HikariConfig();

        config.setPoolName("DB_POOL");

        config.setDriverClassName(_env.getProperty("db.driver"));

        config.setJdbcUrl(_env.getProperty("db.url"));

        config.setUsername(_env.getProperty("db.user"));

        config.setPassword(_env.getProperty("db.pass"));

        config.setMaximumPoolSize(_env.getProperty("hikari.pool.max.size", Integer.class));

        config.setAutoCommit(true);

        config.setConnectionTestQuery("SELECT 1");

        config.addDataSourceProperty("cachePrepStmts", "true");

        config.addDataSourceProperty("prepStmtCacheSize", "250");

        config.addDataSourceProperty("prepStmtCacheSqlLimit", "2048");

        config.setLeakDetectionThreshold(THREE_MINS);

        // config.addDataSourceProperty("useServerPrepStmts", "true");  // this breaks shit

        return config;

    }

    @DisableForTesting

    @Bean(initMethod = "migrate")

    public Flyway flyway(){

        Flyway flyway = new Flyway();

        flyway.setDataSource(dataSource());

        flyway.setBaselineOnMigrate(true);

        return flyway;

    }

}

import org.hibernate.cfg.AvailableSettings;

import org.hibernate.jpa.HibernatePersistenceProvider;

import org.magic.audit.UsernameAuditorAware;

import org.magic.model.user.User;

import org.magic.repository.jpa.BaseRepositoryImpl;

import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

import org.springframework.context.annotation.Bean;

import org.springframework.context.annotation.Configuration;

import org.springframework.core.env.Environment;

import org.springframework.data.domain.AuditorAware;

import org.springframework.data.jpa.repository.config.EnableJpaAuditing;

import org.springframework.data.jpa.repository.config.EnableJpaRepositories;

import org.springframework.jdbc.core.JdbcTemplate;

import org.springframework.orm.hibernate5.HibernateExceptionTranslator;

import org.springframework.orm.jpa.JpaTransactionManager;

import org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean;

import org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter;

import org.springframework.transaction.PlatformTransactionManager;

import org.springframework.transaction.annotation.EnableTransactionManagement;

import javax.annotation.Resource;

import javax.persistence.EntityManagerFactory;

import javax.sql.DataSource;

import java.util.Arrays;

import java.util.Properties;

import static org.springframework.orm.jpa.vendor.Database.MYSQL;

@Configuration

@EnableJpaAuditing

@EnableJpaRepositories(basePackages = {"org.magic.repository.jpa"}, repositoryBaseClass = BaseRepositoryImpl.class)

@EnableTransactionManagement

public class JpaConfig {

    private final Logger log = LoggerFactory.getLogger(JpaConfig.class);

    private static final boolean SHOW_SQL = false;

    private static final String[] packageToScan = {"org.magic.model", "org.magic.social", "org.magic.audit", "org.magic.security.model"};

    @Resource private Environment _env;

    @Resource private DataSource _dataSource;

    public JpaConfig() {

        log.info("loading JPA config");

    }

    @Bean

    public AuditorAware<User> auditorProvider(){

        return new UsernameAuditorAware();

    }

    @Bean(name="entityManagerFactory")

    @DependsOn("flyway")

    public LocalContainerEntityManagerFactoryBean entityManagerFactory() {

        HibernateJpaVendorAdapter jpaAdapter = new HibernateJpaVendorAdapter();

        jpaAdapter.setDatabase(MYSQL);

        jpaAdapter.setShowSql(SHOW_SQL);

        LocalContainerEntityManagerFactoryBean factory = new LocalContainerEntityManagerFactoryBean();

        factory.setJpaVendorAdapter(jpaAdapter);

        factory.setPersistenceProvider(new HibernatePersistenceProvider());

        factory.setDataSource(_dataSource);

        factory.setPackagesToScan(packageToScan);

        factory.setJpaProperties(jpaProperties());

        factory.afterPropertiesSet();

        return factory;

    }

    @Bean

    public HibernateExceptionTranslator hibernateExceptionTranslator() {

        return new HibernateExceptionTranslator();

    }

    @Bean

    public PlatformTransactionManager transactionManager(EntityManagerFactory entityManagerFactory) {

        JpaTransactionManager txManager = new JpaTransactionManager();

        txManager.setEntityManagerFactory(entityManagerFactory);

        return txManager;

    }

    @Bean

    public JdbcTemplate jdbcTemplate(){

        return new JdbcTemplate(_dataSource);

    }

    private Properties jpaProperties() {

        Properties properties = new Properties();

        if(!Arrays.asList(_env.getActiveProfiles()).contains("testDb")) {

            log.info(" * Validating DDL for {} *", _env.getProperty("db.url"));

            properties.setProperty(AvailableSettings.HBM2DDL_AUTO, "validate");

        }

        properties.put(AvailableSettings.STATEMENT_BATCH_SIZE, "20");

        properties.put(AvailableSettings.IMPLICIT_NAMING_STRATEGY, "org.hibernate.boot.model.naming.ImplicitNamingStrategyLegacyHbmImpl");

        properties.put(AvailableSettings.PHYSICAL_NAMING_STRATEGY, "org.magic.config.util.ImprovedNamingStrategy");

        properties.put(AvailableSettings.SHOW_SQL, SHOW_SQL ? "true" : "false");

        properties.put(AvailableSettings.DIALECT, "org.hibernate.dialect.MySQL55Dialect");

        properties.put(AvailableSettings.CURRENT_SESSION_CONTEXT_CLASS, "org.springframework.orm.hibernate5.SpringSessionContext");

        properties.put(AvailableSettings.ENABLE_LAZY_LOAD_NO_TRANS, "true");  // this should go away and we should load our DTO inside of a @Transaction

        properties.put("org.hibernate.envers.audit_table_suffix", "_history");

        properties.put("org.hibernate.envers.audit_strategy_validity_store_revend_timestamp", "true");

        properties.put("org.hibernate.envers.audit_strategy", "org.magic.audit.MagicValidityAuditStrategy");

        properties.put("org.hibernate.envers.global_with_modified_flag", "true");  // default is false

        // default is false, if false need to use DefaultTrackingModifiedEntitiesRevisionEntity

        // https://docs.jboss.org/hibernate/orm/5.2/userguide/html_single/Hibernate_User_Guide.html#envers

        properties.put("org.hibernate.envers.track_entities_changed_in_revision", "true");

        return properties;

    }

}

thanks!