4 Replies Latest reply: Mar 1, 2012 11:10 AM by Clovis Wichoski RSS

JDBC Blocks again when try to get new connections.

Clovis Wichoski
Currently Being Moderated

Hi,

 

again, my tomcat freezes today, and i must stop/start tomcat to get new connections:

 

i checked MaxDB server and a Running thread causes Timer to block.

 

the output of command show t_cnt of the running maxdb thread is:

 

 

--------------------  T270  USER              ( pid =      0 ) ---------------
 remote_node   : 192.168.99.1                          remote_pid    : 0
 dispatcher_cnt: 618065                                command_cnt   : 99418
 exclusive_cnt : 1035660104                            self_susp_cnt : 4
 Resume count 0  total 155        History [ T2 T2 T2 ]
 dev_read_io   : 177                                   dev_read_pg   : 177
 state_vwait   : 0          state_vsleep  : 45         state_vsusp   : 144
 rcv_rpl_count : 99418      rcv_rpl_long  : 0          avg_rcv_rpl_t : 0.0000
 dev_que_len_0 : 177        dev_que_len_1 : 0          dev_que_len>1 : 0
 prio_total    : 2                                     prio_from_oth : 2
-------------------------------------------------------------------------------

 

some of the java blocked thread example is:

 

"http-80-173" daemon prio=10 tid=0x0000000043edd000 nid=0x7ce8 waiting for monitor entry [0x000000005564c000..0x000000005564da90]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:917)
        - waiting to lock <0x00002aaab91895b0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
        at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
        at org.exolab.castor.jdo.engine.DatabaseRegistry.createConnection(DatabaseRegistry.java:399)
        at org.exolab.castor.jdo.engine.TransactionContextImpl.getConnection(TransactionContextImpl.java:203)
        at org.exolab.castor.persist.TransactionContext.query(TransactionContext.java:644)
        - locked <0x00002aab12f5a5d8> (a org.exolab.castor.jdo.engine.TransactionContextImpl)
        at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:458)
        at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:414)
        at com.supridatta.bean.DataPersist.consulta(DataPersist.java:536)
        at com.supridatta.servlet.SupridattaServlet.doConsultarControl(SupridattaServlet.java:730)
        at com.supridatta.servlet.SupridattaServlet$9.resolve(SupridattaServlet.java:294)
        at com.supridatta.servlet.SupridattaServlet.processaOperacao(SupridattaServlet.java:144)
        at com.supridatta.servlet.SupridattaServlet.doAppletControl(SupridattaServlet.java:114)
        at com.supridatta.servlet.SupridattaServlet.service(SupridattaServlet.java:1747)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:183)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:568)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

 

like this exists about 189 java blocked threads all waiting for this one:

 

"Timer-4" daemon prio=10 tid=0x0000000043ae7000 nid=0x51b3 runnable [0x0000000042128000..0x0000000042128b10]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.sap.dbtech.rte.comm.BasicSocketComm.receiveData(BasicSocketComm.java:577)
        at com.sap.dbtech.rte.comm.BasicSocketComm.receive(BasicSocketComm.java:666)
        at com.sap.dbtech.rte.comm.JdbcCommunication.execute(JdbcCommunication.java:41)
        at com.sap.dbtech.jdbc.ConnectionSapDB.execute(ConnectionSapDB.java:536)
        - locked <0x00002aaabce3bc80> (a com.sap.dbtech.jdbc.ConnectionSapDB)
        at com.sap.dbtech.jdbc.ConnectionSapDB.execute(ConnectionSapDB.java:461)
        at com.sap.dbtech.jdbc.ConnectionSapDB.isClosed(ConnectionSapDB.java:746)
        at com.sap.dbtech.jdbc.trace.Connection.isClosed(Connection.java:400)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.isClosed(DelegatingConnection.java:346)
        at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:324)
        at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:312)
        at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.evict(GenericObjectPool.java:1217)
        - locked <0x00002aaab91895b0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool)
        at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Evictor.run(GenericObjectPool.java:1341)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)

   Locked ownable synchronizers:
        - None

 

then seeing all this appears that com.sap.dbtech.jdbc.ConnectionSapDB.isClosed(ConnectionSapDB.java:746) do something that blocks all connections, but i cant understand if T270 is related to this Timer-4 java thread.

 

any idea?

  • Re: JDBC Blocks again when try to get new connections.
    Lars Breddemann
    Currently Being Moderated
    Clovis Wichoski wrote:

    >

    > Hi,

    >

    > again, my tomcat freezes today, and i must stop/start tomcat to get new connections:

    >

    > i checked MaxDB server and a Running thread causes Timer to block.

     

    What makes you think that this is the case?

     

    > the output of command show t_cnt of the running maxdb thread is:

    >

    >

    >

    --------------------  T270  USER              ( pid =      0 ) ---------------
    >  remote_node   : 192.168.99.1                          remote_pid    : 0
    >  dispatcher_cnt: 618065                                command_cnt   : 99418
    >  exclusive_cnt : 1035660104                            self_susp_cnt : 4
    >  Resume count 0  total 155        History [ T2 T2 T2 ]
    >  dev_read_io   : 177                                   dev_read_pg   : 177
    >  state_vwait   : 0          state_vsleep  : 45         state_vsusp   : 144
    >  rcv_rpl_count : 99418      rcv_rpl_long  : 0          avg_rcv_rpl_t : 0.0000
    >  dev_que_len_0 : 177        dev_que_len_1 : 0          dev_que_len>1 : 0
    >  prio_total    : 2                                     prio_from_oth : 2
    > -------------------------------------------------------------------------------

     

    What exactly are you referring to in this output?

    What looks suspicious to you?

     

     

     

    >

    "http-80-173" daemon prio=10 tid=0x0000000043edd000 nid=0x7ce8 waiting for monitor entry [0x000000005564c000..0x000000005564da90]
    >    java.lang.Thread.State: BLOCKED (on object monitor)
    >         at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:917)
    >         - waiting to lock <0x00002aaab91895b0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool)
    > 

     

    Ok, so this thread is blocked while waiting for a monitor-synchronization object used in GenericObjectPool.

    This has nothing to do with MaxDB.

     

    > like this exists about 189 java blocked threads all waiting for this one:

    >

    >

    "Timer-4" daemon prio=10 tid=0x0000000043ae7000 nid=0x51b3 runnable [0x0000000042128000..0x0000000042128b10]
    >    java.lang.Thread.State: RUNNABLE
    >         at java.net.SocketInputStream.socketRead0(Native Method)
    >         at java.net.SocketInputStream.read(SocketInputStream.java:129)
    >         at com.sap.dbtech.rte.comm.BasicSocketComm.receiveData(BasicSocketComm.java:577)
    >         at com.sap.dbtech.rte.comm.BasicSocketComm.receive(BasicSocketComm.java:666)
    >         at com.sap.dbtech.rte.comm.JdbcCommunication.execute(JdbcCommunication.java:41)
    >         at com.sap.dbtech.jdbc.ConnectionSapDB.execute(ConnectionSapDB.java:536)
    >         - locked <0x00002aaabce3bc80> (a com.sap.dbtech.jdbc.ConnectionSapDB)
    >

     

    And this one reminds us of the former threads you posted where threads were hanging while reading data from a network socket.

    And sure, the JDBC driver needs to do that because you want to access your database over the network

     

    > then seeing all this appears that com.sap.dbtech.jdbc.ConnectionSapDB.isClosed(ConnectionSapDB.java:746) do something that blocks all connections, but i cant understand if T270 is related to this Timer-4 java thread.

     

    The problem here is, that JDBC threads usually don't reveal their process id to the MaxDB kernel.

    Therefore you don't see the PID = 1234 in the x_cons output.

     

    One way to handle this would be to have your java programm query some session information right after connection time.

    Something like "select * from sessions where own='YES'" and print this into the threads logfile.

    That way you can easily figure out which connection belongs to which MaxDB session.

     

    regards,

    Lars

    • Re: JDBC Blocks again when try to get new connections.
      Clovis Wichoski
      Currently Being Moderated

      Hi, Lars,

       

      in truth i know nothing about this problem, just guessing, i really dont know what i can do to avoid or discover when and why this occurs,since the pool connection control is tomcat dbcp, i post info about T270 because, that was the only MaxDB thread running when the problem occurs, and is common, when i get many BLOCKED threads at java side, exists only one thread at MaxDB running, when i kill this thread, all threads get unblocked, my try with this post is to get more info or insight about this problem as i really dont know how to get information of what command the running thread is, some time in past i activated the command monitor, but for production, that consumes too much temp area, and sometimes, i get thread blocked because command monitor, too strange, but its true.

       

      Today i willl update that database to a newer version as that is a 7.6.03.07 i will update to 7.6.06.10.

       

      best regards

       

      Clóvis

       

      • Re: JDBC Blocks again when try to get new connections.
        Lars Breddemann
        Currently Being Moderated

        HI Clóvis,

         

        I see what kind of situation you're in.

        And I'm sorry to say that I'm not too familiar with analysing JAVA hang situations.

        All I can add here (I think) is that I don't see that this is a MaxDB Kernel problem.

        If you ask me, I'd try to figure out more about what happens between the JAVA threads system call to the network socket and the MaxDB x_server.

        Somewhere in the chain of system components involved with the network communication must be a problem.

         

        To me this would look like this:

         

        JAVA thread -> JAVA VM -> OS Network API -> Network adapter driver -> "Network logic" like adress resolution -> routers -> DB Servers' Network adapter driver -> OS Network API -> X_SERVER

         

        I'm not an expert for most of the components listed, but if would be my problem, I'd try to gain more insight in all of them step-by-step.

         

        Let us know how you proceed with this!

         

        Good luck and best regards,

        Lars

         

        p.s.

        While I do think it's a good idea to install the latest patch, I doubt that this has any effect to the problem.

         

        • Re: JDBC Blocks again when try to get new connections.
          Clovis Wichoski
          Currently Being Moderated

          Hi Lars,

           

          I updated all things, Java, Linux, MaxDB, i discovered that the problem isnt with network, but with some kind of deadlock at database side, for example:

           

          1) user 1 insert something on table A

          2) user 2 starts a long running transaction with poor SQL statement that locks the table A.

          3) user 3 opens a connection to run an SQL statement that queries table A.

          4) all java threads that need a new JDBC connection get blocked because step 3 never returns a new connection, and DBCP synchronization never goes out.

           

          here is the thread of step 2:

           

           

          java.lang.Thread.State: RUNNABLE
                  at java.net.SocketInputStream.socketRead0(Native Method)
                  at java.net.SocketInputStream.read(SocketInputStream.java:129)
                  at com.sap.dbtech.rte.comm.BasicSocketComm.receiveData(BasicSocketComm.java:577)
                  at com.sap.dbtech.rte.comm.BasicSocketComm.receive(BasicSocketComm.java:666)
                  at com.sap.dbtech.rte.comm.JdbcCommunication.execute(JdbcCommunication.java:41)
                  at com.sap.dbtech.jdbc.ConnectionSapDB.execute(ConnectionSapDB.java:536)
                  - locked <0x00002aab1ed9d560> (a com.sap.dbtech.jdbc.ConnectionSapDB)
                  at com.sap.dbtech.jdbc.ConnectionSapDB.execute(ConnectionSapDB.java:461)
                  at com.sap.dbtech.jdbc.ConnectionSapDB.doConnect(ConnectionSapDB.java:398)
                  at com.sap.dbtech.jdbc.ConnectionSapDB.<init>(ConnectionSapDB.java:109)
                  at com.sap.dbtech.jdbc.DriverSapDB.connect(DriverSapDB.java:222)
                  - locked <0x00002aaabc74ade0> (a com.sap.dbtech.jdbc.DriverSapDB)
                  at org.apache.tomcat.dbcp.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
                  at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294)
                  - locked <0x00002aaabc896988> (a org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory)
                  at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:974)
                  at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
                  at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
                  at org.exolab.castor.jdo.engine.DatabaseRegistry.createConnection(DatabaseRegistry.java:399)
                  at org.exolab.castor.jdo.engine.TransactionContextImpl.getConnection(TransactionContextImpl.java:203)
                  at org.exolab.castor.persist.TransactionContext.query(TransactionContext.java:644)
                  - locked <0x00002aab1e8d9348> (a org.exolab.castor.jdo.engine.TransactionContextImpl)
                  at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:458)
                  at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:414)
                  at com.supridatta.bean.DataPersist.consulta(DataPersist.java:536)

           

          and here is the thread at step 3:

          java.lang.Thread.State: BLOCKED (on object monitor)
                  at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294)
                  - waiting to lock <0x00002aaabc896988> (a org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory)
                  at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:974)
                  at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
                  at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
                  at org.exolab.castor.jdo.engine.DatabaseRegistry.createConnection(DatabaseRegistry.java:399)
                  at org.exolab.castor.jdo.engine.TransactionContextImpl.getConnection(TransactionContextImpl.java:203)
                  at org.exolab.castor.persist.TransactionContext.query(TransactionContext.java:644)
                  - locked <0x00002aab1e898f98> (a org.exolab.castor.jdo.engine.TransactionContextImpl)
                  at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:458)
                  at org.exolab.castor.jdo.engine.OQLQueryImpl.execute(OQLQueryImpl.java:414)
                  at com.supridatta.bean.DataPersist.consulta(DataPersist.java:536)

           

          I inspected the database side, still really running, database results comes, but without releasing the connection, and if i wait the time or no user need a new connection, i never get thread blockeds, appears that MaxDB locks all connections if the newly created connection executes some SQL after acquiring that connection.

           

          I see some blocks too at java finalizer, where one thread running is stucked getting a connection.

           

          all this is just guess, maybe I'm wrong, but for now i will end this thread as we need see how this system will perform with all updates made.

           

          best regards.

           

          Clóvis

           

Actions