Обсуждение: Hung thread

Any update on the below thread.

---

From: dhavallj@hotmail.com
To: pgsql-jdbc@postgresql.org
Subject: Hung thread
Date: Thu, 23 Oct 2014 15:05:30 +0530

This question might some one has asked but did not get the proper resolution in any thread.  Henceforth posting.

I am facing the issue of the hung thread initiated from tomcat (application server tomcat 6.0) to the database (postgresql 9.0). Using JDBC driver 9.0.

From the logs of the application server found it happened some time only. Following is the thread dump taken at the time of hung thread.  Moreover, there is no query stuck at the database level.  In one of the forum i saw it might be because of the JDBC driver. Please share your thoughts on this issue. I checked there is no network level interruption.       

 java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
        - locked <0x00002aaaf6282d00> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
        at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
        at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
        at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
        at com.eos.hotels.viahotel.manager.ViaHotelDatabaseManager.getConnection(ViaHotelDatabaseManager.java:74)
        at com.eos.hotels.viahotel.manager.ViaHotelDatabaseManager.getConnection(ViaHotelDatabaseManager.java:59)
        at com.eos.marketplace.data.MarketPlaceHotel.getHotelById(MarketPlaceHotel.java:749)
        at com.eos.hotels.apis.gta.GTAHotelBookingData.populateOrderItem(GTAHotelBookingData.java:334)
        at com.eos.hotels.viahotel.data.book.ViaAPIHotelBookingData.createOrder(ViaAPIHotelBookingData.java:531)
        at com.eos.hotels.apis.gta.GTAHotelBookingData.process(GTAHotelBookingData.java:407)
        at com.eos.b2c.beans.SkuBean.skuHotelBooking(SkuBean.java:902)
        at com.eos.b2c.beans.SkuBean.skuHotelBooking(SkuBean.java:873)
        at com.eos.b2c.ui.ResellerNavigation.doGet(ResellerNavigation.java:2237)
        at com.eos.b2c.ui.ResellerNavigation.doPost(ResellerNavigation.java:579)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at com.eos.accounts.UserManagerFilter.doFilter(UserManagerFilter.java:584)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        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:175)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
        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)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
        at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:856)
        at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:565)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1509)
        at java.lang.Thread.run(Thread.java:619)

Following is the JDBC connection. 


        <Resource name="jdbc/DB" auth="Container" type="javax.sql.DataSource"
        driverClassName="org.postgresql.Driver" url="jdbc:postgresql://IP:PORT/DB_NAME"
        username="" password=""
        maxActive="100" maxIdle="30" maxWait="30000"
        validationQuery="select 1" testOnBorrow="true"
        removeAbandoned="true" removeAbandonedTimeout="120" logAbandoned="true" />


There is nothing reflecting in the result of the pg_stat_activity.

There is no relevant logs found in pg_logs too.

Thread is not only stuck at the time of get connection. Some times at the time of query execution.


java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.read(SocketInputStream.java:129)
 org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
 org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
 org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
 org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
 org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660)
 org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:273)
 com.eos.accounts.data.OrderAuthorization.loadOrderAuthorization(OrderAuthorization.java:102)
 com.eos.tally.reports.data.TallyOrder.getOrdersForTallyReport(TallyOrder.java:88)
 com.eos.tally.reports.SaleReport.setData(SaleReport.java:71)
 com.eos.tally.reports.AgentSaleReport.generateMap(AgentSaleReport.java:25)
 com.eos.tally.reports.AbstractTallyReport.generateTallyReport(AbstractTallyReport.java:171)
 com.eos.tally.reports.TallyReport.generateReport(TallyReport.java:112)
 com.eos.b2c.beans.callcenter.AccountingBean.downloadTallyAgentSalesReport(AccountingBean.java:602)
 com.eos.b2c.ui.B2cCallcenterNavigation.doGet(B2cCallcenterNavigation.java:1117)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) 


TCP_KEEP_ALIVE is 2 hours at the server level. 

> Date: Tue, 28 Oct 2014 07:28:16 -0700
> From: kgrittn@ymail.com
> Subject: Re: [JDBC] Hung thread
> To: pg@fastcrypt.com; dhavallj@hotmail.com
> CC: pgsql-jdbc@postgresql.org

>
> Dave Cramer <pg@fastcrypt.com> wrote:
> > On 28 October 2014 07:34, dhaval jaiswal <dhavallj@hotmail.com> wrote:
>
> >> java.lang.Thread.State: RUNNABLE
> >> at java.net.SocketInputStream.socketRead0(Native Method)
> >> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> >> at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
> >> at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
> >> at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
> >> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
> >> at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660)
> >> at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
> >> - locked <0x00002aaaf6282d00> (a org.postgresql.core.v3.QueryExecutorImpl)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
> >> at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
> >> at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
> >> at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
> >> at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
> >> at com.eos.hotels.viahotel.manager.ViaHotelDatabaseManager.getConnection(ViaHotelDatabaseManager.java:74)
> [ snip ]
>
> > Given the little bit of information available my guess would be
> > that since this is using dbcp, and the connections are never really
> > closed.
>
> The stack trace shows that the getConnection() method of dbcp is
> trying to re-use a connection in the pool, and is first testing the
> connection by invoking our JDBC driver's executeQuery() method.
>
> > I believe once a connection is made we are always listening
> > on the socket.
>
> I don't follow that; it is listening for the response to a query.
> What thread would be "always listening", anyway? The driver is not
> multi-threaded.
>
> > However I will say I haven't really spent much time on this. Either
> > way we would need much more information in order to be able to help
> > you.
>
> It would be interesting to know what query dbcp is using to test
> whether the connection is still alive. Also, if the client port
> can be discovered, looking for it in the pg_stat_activity view
> would be interesting.
>
> I can think of one halfway plausible explanation, though. A
> firewall between the machine running dbcp and the database server
> might be blocking traffic after some idle timeout, possibly
> resulting in a hang like this when the pooler eventually tries to
> use the connection again. You might want to try configuring TCP
> timeouts on both the client and the server. It wouldn't hurt to
> closely review the network path between the machines.
>
> Logging connections and disconnections and closely reviewing the
> server logs could provide insights.
>
> --
> Kevin Grittner
> EDB: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company

Kevin/Dave,

I would really appreciate if you can help me to solve this issue. I have checked at network end and there is no idle session timeout policy between two segment (from tomcat to the db server).

Adding to that it happens some time only.

DB end i found below logs, however not sure whether it is reflecting for which connection.

could not receive data from client: Connection reset by peer
unexpected EOF on client connection

---

From: dhavallj@hotmail.com
To: pg@fastcrypt.com
CC: kgrittn@ymail.com; pgsql-jdbc@postgresql.org
Subject: RE: [JDBC] Hung thread
Date: Wed, 29 Oct 2014 14:24:04 +0530

maxWait="30000" ms

---

From: pg@fastcrypt.com
Date: Tue, 28 Oct 2014 13:47:25 -0400
Subject: Re: [JDBC] Hung thread
To: dhavallj@hotmail.com
CC: kgrittn@ymail.com; pgsql-jdbc@postgresql.org

So it is possible that as Kevin said the test on borrow statement referred to a connection that was still in the TCP stack but had not timed out yet.

How long did you wait ?

Dave Cramer

dave.cramer(at)credativ(dot)ca
http://www.credativ.ca

On 28 October 2014 13:44, dhaval jaiswal <dhavallj@hotmail.com> wrote:

Following is the JDBC connection. 


        <Resource name="jdbc/DB" auth="Container" type="javax.sql.DataSource"
        driverClassName="org.postgresql.Driver" url="jdbc:postgresql://IP:PORT/DB_NAME"
        username="" password=""
        maxActive="100" maxIdle="30" maxWait="30000"
        validationQuery="select 1" testOnBorrow="true"
        removeAbandoned="true" removeAbandonedTimeout="120" logAbandoned="true" />


There is nothing reflecting in the result of the pg_stat_activity.

There is no relevant logs found in pg_logs too.

Thread is not only stuck at the time of get connection. Some times at the time of query execution.


java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.read(SocketInputStream.java:129)
 org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
 org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
 org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
 org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
 org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660)
 org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
 org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
 org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
 org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:273)
 com.eos.accounts.data.OrderAuthorization.loadOrderAuthorization(OrderAuthorization.java:102)
 com.eos.tally.reports.data.TallyOrder.getOrdersForTallyReport(TallyOrder.java:88)
 com.eos.tally.reports.SaleReport.setData(SaleReport.java:71)
 com.eos.tally.reports.AgentSaleReport.generateMap(AgentSaleReport.java:25)
 com.eos.tally.reports.AbstractTallyReport.generateTallyReport(AbstractTallyReport.java:171)
 com.eos.tally.reports.TallyReport.generateReport(TallyReport.java:112)
 com.eos.b2c.beans.callcenter.AccountingBean.downloadTallyAgentSalesReport(AccountingBean.java:602)
 com.eos.b2c.ui.B2cCallcenterNavigation.doGet(B2cCallcenterNavigation.java:1117)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) 


TCP_KEEP_ALIVE is 2 hours at the server level. 

> Date: Tue, 28 Oct 2014 07:28:16 -0700
> From: kgrittn@ymail.com
> Subject: Re: [JDBC] Hung thread
> To: pg@fastcrypt.com; dhavallj@hotmail.com
> CC: pgsql-jdbc@postgresql.org

>
> Dave Cramer <pg@fastcrypt.com> wrote:
> > On 28 October 2014 07:34, dhaval jaiswal <dhavallj@hotmail.com> wrote:
>
> >> java.lang.Thread.State: RUNNABLE
> >> at java.net.SocketInputStream.socketRead0(Native Method)
> >> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> >> at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
> >> at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
> >> at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
> >> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
> >> at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660)
> >> at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
> >> - locked <0x00002aaaf6282d00> (a org.postgresql.core.v3.QueryExecutorImpl)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
> >> at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
> >> at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
> >> at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
> >> at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
> >> at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
> >> at com.eos.hotels.viahotel.manager.ViaHotelDatabaseManager.getConnection(ViaHotelDatabaseManager.java:74)
> [ snip ]
>
> > Given the little bit of information available my guess would be
> > that since this is using dbcp, and the connections are never really
> > closed.
>
> The stack trace shows that the getConnection() method of dbcp is
> trying to re-use a connection in the pool, and is first testing the
> connection by invoking our JDBC driver's executeQuery() method.
>
> > I believe once a connection is made we are always listening
> > on the socket.
>
> I don't follow that; it is listening for the response to a query.
> What thread would be "always listening", anyway? The driver is not
> multi-threaded.
>
> > However I will say I haven't really spent much time on this. Either
> > way we would need much more information in order to be able to help
> > you.
>
> It would be interesting to know what query dbcp is using to test
> whether the connection is still alive. Also, if the client port
> can be discovered, looking for it in the pg_stat_activity view
> would be interesting.
>
> I can think of one halfway plausible explanation, though. A
> firewall between the machine running dbcp and the database server
> might be blocking traffic after some idle timeout, possibly
> resulting in a hang like this when the pooler eventually tries to
> use the connection again. You might want to try configuring TCP
> timeouts on both the client and the server. It wouldn't hurt to
> closely review the network path between the machines.
>
> Logging connections and disconnections and closely reviewing the
> server logs could provide insights.
>
> --
> Kevin Grittner
> EDB: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company