Analysis of suspect and abandon Operations of tomcat jdbc Connection Pool

  springboot

Connection has been marked suspect

Connection has been marked suspect, possibly abandoned PooledConnection[org.postgresql.jdbc.PgConnection@c07ac94][65091 ms.]:java.lang.Exception
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1102)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:807)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:651)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:132)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:230)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:237)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:214)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:52)
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1512)
    at org.hibernate.jpa.internal.TransactionImpl.begin(TransactionImpl.java:45)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:189)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:380)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:447)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)

PoolCleaner

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/ConnectionPool.java

protected static class PoolCleaner extends TimerTask {
        protected WeakReference<ConnectionPool> pool;
        protected long sleepTime;

        PoolCleaner(ConnectionPool pool, long sleepTime) {
            this.pool = new WeakReference<>(pool);
            this.sleepTime = sleepTime;
            if (sleepTime <= 0) {
                log.warn("Database connection pool evicter thread interval is set to 0, defaulting to 30 seconds");
                this.sleepTime = 1000 * 30;
            } else if (sleepTime < 1000) {
                log.warn("Database connection pool evicter thread interval is set to lower than 1 second.");
            }
        }

        @Override
        public void run() {
            ConnectionPool pool = this.pool.get();
            if (pool == null) {
                stopRunning();
            } else if (!pool.isClosed()) {
                try {
                    if (pool.getPoolProperties().isRemoveAbandoned()
                            || pool.getPoolProperties().getSuspectTimeout() > 0)
                        pool.checkAbandoned();
                    if (pool.getPoolProperties().getMinIdle() < pool.idle
                            .size())
                        pool.checkIdle();
                    if (pool.getPoolProperties().isTestWhileIdle())
                        pool.testAllIdle();
                } catch (Exception x) {
                    log.error("", x);
                }
            }
        }

        public void start() {
            registerCleaner(this);
        }

        public void stopRunning() {
            unregisterCleaner(this);
        }
    }

checkAbandoned

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/ConnectionPool.java

/**
     * Iterates through all the busy connections and checks for connections that have timed out
     */
    public void checkAbandoned() {
        try {
            if (busy.size()==0) return;
            Iterator<PooledConnection> locked = busy.iterator();
            int sto = getPoolProperties().getSuspectTimeout();
            while (locked.hasNext()) {
                PooledConnection con = locked.next();
                boolean setToNull = false;
                try {
                    con.lock();
                    //the con has been returned to the pool or released
                    //ignore it
                    if (idle.contains(con) || con.isReleased())
                        continue;
                    long time = con.getTimestamp();
                    long now = System.currentTimeMillis();
                    if (shouldAbandon() && (now - time) > con.getAbandonTimeout()) {
                        busy.remove(con);
                        abandon(con);
                        setToNull = true;
                    } else if (sto > 0 && (now - time) > (sto * 1000L)) {
                        suspect(con);
                    } else {
                        //do nothing
                    } //end if
                } finally {
                    con.unlock();
                    if (setToNull)
                        con = null;
                }
            } //while
        } catch (ConcurrentModificationException e) {
            log.debug("checkAbandoned failed." ,e);
        } catch (Exception e) {
            log.warn("checkAbandoned failed, it will be retried.",e);
        }
    }

suspect

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/ConnectionPool.java

/**
     * Thread safe way to suspect a connection. Similar to
     * {@link #abandon(PooledConnection)}, but instead of actually abandoning
     * the connection, this will log a warning and set the suspect flag on the
     * {@link PooledConnection} if logAbandoned=true
     *
     * @param con PooledConnection
     */
    protected void suspect(PooledConnection con) {
        if (con == null)
            return;
        if (con.isSuspect())
            return;
        try {
            con.lock();
            String trace = con.getStackTrace();
            if (getPoolProperties().isLogAbandoned()) {
                log.warn("Connection has been marked suspect, possibly abandoned " + con + "["+(System.currentTimeMillis()-con.getTimestamp())+" ms.]:" + trace);
            }
            if (jmxPool!=null) {
                jmxPool.notify(org.apache.tomcat.jdbc.pool.jmx.ConnectionPool.SUSPECT_ABANDONED_NOTIFICATION, trace);
            }
            con.setSuspect(true);
        } finally {
            con.unlock();
        }
    }

abandon

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/ConnectionPool.java

/**
     * thread safe way to abandon a connection
     * signals a connection to be abandoned.
     * this will disconnect the connection, and log the stack trace if logAbandoned=true
     * @param con PooledConnection
     */
    protected void abandon(PooledConnection con) {
        if (con == null)
            return;
        try {
            con.lock();
            String trace = con.getStackTrace();
            if (getPoolProperties().isLogAbandoned()) {
                log.warn("Connection has been abandoned " + con + ":" + trace);
            }
            if (jmxPool!=null) {
                jmxPool.notify(org.apache.tomcat.jdbc.pool.jmx.ConnectionPool.NOTIFY_ABANDON, trace);
            }
            //release the connection
            removeAbandonedCount.incrementAndGet();
            release(con);
        } finally {
            con.unlock();
        }
    }

release

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/ConnectionPool.java

/**
     * thread safe way to release a connection
     * @param con PooledConnection
     */
    protected void release(PooledConnection con) {
        if (con == null)
            return;
        try {
            con.lock();
            if (con.release()) {
                //counter only decremented once
                size.addAndGet(-1);
                con.setHandler(null);
            }
            releasedCount.incrementAndGet();
        } finally {
            con.unlock();
        }
        // we've asynchronously reduced the number of connections
        // we could have threads stuck in idle.poll(timeout) that will never be
        // notified
        if (waitcount.get() > 0) {
            idle.offer(create(true));
        }
    }

tomcat-jdbc-8.5.13-sources.jar! /org/apache/tomcat/jdbc/pool/PooledConnection.java

/**
     * This method is called if (Now - timeCheckedIn &gt; getReleaseTime())
     * This method disconnects the connection, logs an error in debug mode if it happens
     * then sets the {@link #released} flag to false. Any attempts to connect this cached object again
     * will fail per {@link #connect()}
     * The connection pool uses the atomic return value to decrement the pool size counter.
     * @return true if this is the first time this method has been called. false if this method has been called before.
     */
    public boolean release() {
        try {
            disconnect(true);
        } catch (Exception x) {
            if (log.isDebugEnabled()) {
                log.debug("Unable to close SQL connection",x);
            }
        }
        return released.compareAndSet(false, true);

    }

disconnect

/**
     * Disconnects the connection. All exceptions are logged using debug level.
     * @param finalize if set to true, a call to {@link ConnectionPool#finalize(PooledConnection)} is called.
     */
    private void disconnect(boolean finalize) {
        if (isDiscarded() && connection == null) {
            return;
        }
        setDiscarded(true);
        if (connection != null) {
            try {
                parent.disconnectEvent(this, finalize);
                if (xaConnection == null) {
                    connection.close();
                } else {
                    xaConnection.close();
                }
            }catch (Exception ignore) {
                if (log.isDebugEnabled()) {
                    log.debug("Unable to close underlying SQL connection",ignore);
                }
            }
        }
        connection = null;
        xaConnection = null;
        lastConnected = -1;
        if (finalize) parent.finalize(this);
    }