0

I am using WAS 7.1 along with c3p0 (v 0.9.2.1) & hibernate (3.2.6ga)

After some hours of usage Websphere hangs and I see this message in the log

[6/24/13 10:57:50:377 CEST] 00000031 ThreadMonitor W   WSVR0605W: Thread "WebContainer : 24" (00000048) has been active for 759356 milliseconds and may be hung.  There is/are 45 thread(s) in total in the server that may be hung.
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:196)
    at com.mchange.v2.resourcepool.BasicResourcePool.awaitAcquire(BasicResourcePool.java:776)
    at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:198)
    at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:170)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:172)
    at com.mchange.v2.c3p0.PoolBackedDataSource.getConnection(PoolBackedDataSource.java:58)
    at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:56)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
    at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
    at com.aaa.in.bbb.effort.daoImpl.GRDAO.getGroupList(GRDAO.java:60)
    at com.aaa.in.bbb.effort.delegate.GRBean.getGroupList(GRBean.java:40)
    at com.aaa.in.bbb.effort.action.GRAction.execute(GRAction.java:74)
    at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:419)
    at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:224)
    at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1194)
    at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:414)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:718)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:831)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1658)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:940)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:503)
    at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:181)
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:3954)
    at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:276)
    at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:942)
    at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1592)
    at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:186)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:453)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:515)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:306)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:277)
    at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)
    at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)
    at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
    at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
    at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
    at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)
    at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
    at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)
    at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
    at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1646)

I have no idea why the session is not closed. Here is the session code

public class HibernateUtil {
    private static final SessionFactory sessionFactory; 
    static {
        try {
            Context ctx = new InitialContext();
            Object obj = ctx.lookup("HibernateSessionFactory");         
            sessionFactory = (SessionFactory) obj;
        } catch (Throwable ex) {

            System.out.println("Initial SessionFactory creation failed: "
                    + ex.getMessage());
            throw new ExceptionInInitializerError(ex);
        }
    }

    public static final ThreadLocal hibernateSession = new ThreadLocal();

    public static Session currentSession() {
        Session s = (Session) sessionFactory.openSession();     
        hibernateSession.set(s); 
        return s;
    }
    public static void closeSession() {
        Session s = (Session) hibernateSession.get();
        try {
            if(s != null)
            {
              hibernateSession.set(null);
              s.close();
              System.out.println("s!=null");              
            }
        } catch (HibernateException e) {            
            e.printStackTrace();
            System.out.println("Error occured in closesession()");
        }
        finally
        {
            s=null;
        }

    }
    public static void closeSession(Session session) {
         try {
            if(session != null)
             {
                session.flush();
                hibernateSession.set(null);
                session.close();
                session=null; 

             }
        } catch (HibernateException e) {            
            e.printStackTrace();
            System.out.println("Error occured in closesession(session)");

        }
    }   
}

I checked the code and the request to close session is there but somehow the session itself is not being released by C3P0

The problem happens only after I introduced connection pooling. The reason I had to introduce connection pooling was to solve the max cursors errors reached in Oracle 11 (see Max cursors reached error in JSP + Hibernate)

has any one faced this errors? Any pointers?

Community
  • 1
  • 1
KK99
  • 1,971
  • 7
  • 31
  • 64

1 Answers1

1

The pool is waiting for Connections. If they never come, then you've likely exhausted it due to a Connection leak.

Please debug the leak using c3p0 config parameters unreturnedConnectionTimeout and debugUnreturnedConnectionStackTraces. See the discussion here.

Steve Waldman
  • 13,689
  • 1
  • 35
  • 45
  • I have these 2 set in the hibernate.cfg.xml .. I have set the log level to "INFO" in my application but I don't see any messages n Log. – KK99 Jun 24 '13 at 11:14
  • do you see messages when the pool initializes, a dump of its config? – Steve Waldman Jun 24 '13 at 12:17
  • I see this message when I start the application `0000001e SystemErr R Initializing c3p0 pool...com.mchange.v2.c3p0.PoolBackedDataSource@65816581 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@1e171e17 [ acquireIncrement -> 1, autoCommitOnClose -> false, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, idleConnectionTestPeriod -> 300, initialPoolSize -> 2, maxIdleTime -> 350, maxPoolSize -> 40, maxStatements -> 0, minPoolSize -> 2, nestedDataSource -> ` – KK99 Jun 24 '13 at 13:02
  • `com.mchange.v2.c3p0.DriverManagerDataSource@6cb56cb5 [ description -> null, driverClass -> null, factoryClassLocation -> null, jdbcUrl -> jdbc:oracle:thin:@oracledb.domain.com:38270:SID_MY, properties -> {user=userid, password=pwd, release_mode=after_statement} ] , propertyCycle -> 300, testConnectionOnCheckout -> false ] , factoryClassLocation -> null, numHelperThreads -> 3 ] `
    I have to split this into 2 comments
    – KK99 Jun 24 '13 at 13:03
  • Yes, that's the config dump. it also looks like a VERY old version of c3p0, there are way too few config params. (It looks like it's logging to std error, which could be because it didn't find a logging lib, or it is old.) Did you see a version banner, something like "Initializing c3p0-0.9.5-pre4 [built 23-May-2013 00:26:47 -0700; debug? true; trace: 10]" or a message about the logging back-end, like "MLog clients using java 1.4+ standard logging."? The Connection leak debugging params don't even exist in your config, probably because of a very old c3p0 in your CLASSPATH somewhere. – Steve Waldman Jun 24 '13 at 20:55
  • I have added these in hibernate.cfg.xml `2403503000160true` – KK99 Jun 25 '13 at 07:05
  • BTW how can I enable the logging for c3p0? – KK99 Jun 25 '13 at 07:11
  • 1
    you have some logging, if you have a config dump. there should have been some logging earlier on with version information. you are apparently using a very old version, though: there is no unreturnedConnectionTimeout or debugUnreturnedConnectionStackTraces in your config dump (unless you have abbreviated it), so those params don't exist to be set. – Steve Waldman Jun 25 '13 at 08:10
  • Update: You are right about version. After reading your comment I checked and found 3 versions of C3P0. I removed all old ones. So far I have no issues. I have enabled the logging in my application's log4j properties.xml as ` ` but this does not log all info to the log file – KK99 Jun 25 '13 at 11:21
  • 1
    there are packages (and analogous loggers) outside of com.mchange.v2.c3p0.* logging com.mchange.* @ INFO (or setting your default log level to INFO) will show you what c3p0 and dependent libs expect you to see. – Steve Waldman Jun 26 '13 at 09:44
  • Thanks Steve. Done that. Unfortunately I could not trace any connection leaks. I will investigate further. Thanks for your help – KK99 Jun 26 '13 at 12:23