3

Environment details - Amazon RDS running PostgreSQL 9.3.14, db.r3.xlarge, IOPS 2000, 500 GB

Issue - Numerous java.sql.SQLTimeoutException: Timeout after 30000ms of waiting for a connection and java.lang.RuntimeException: Failed to get a database connection errors, rendering the app useless for our clients.

The backend uses hickaricp for connection pooling.

RDS logs shows that all queries take ~1 to 3 seconds, sometimes some queries do take ~10 seconds. No errors in the RDS logs.

Our homepage makes ~18 DB calls a minute (more like 3 DB calls every 5 seconds - auto refreshing). There are ~300 devices active at any given moment, hence ~6K DB calls per minute. Could this be the reason why we have so many outages? The app is in production from almost 1.5 to 2 years, with no major changes in the immediate past (the last major change was in Oct 2016). The app was in Maintenance mode for almost 6 months now, I am unable to understand what changed to have such severe issues now.

I know that there are a couple of long-running queries, but I need ot understand why we are facing this issue after all these months.

Also, how do I debug and get to the bottom of this. Any help would be appreciated.

Here are the stack Traces (basically any and all endpoint throws this error at random intervals)

[ERROR] [ajp-bio-8009-exec-13] [2017-03-01 15:09:24] [JSP] [java.lang.RuntimeException: Failed to get a database connection]

*** Request Details ***
{
  "ipAddress": "22.33.44.56.123",
  "url": "https://someclient.somecompany.net/face/getUpdates.jsp",
  "queryString": "_\u003d1488380850504",
  "referrer": "https://someclient.somecompany.net/face/locations",
  "userAgent": "Mozilla/5.0 (iPad; CPU OS 10_2_1 like Mac OS X) AppleWebKit/602.4.6 (KHTML, like Gecko) Mobile/14D27",
  "sessionData": {
    "data": {
      "javax.servlet.jsp.jstl.fmt.request.charset": "UTF-8",
      "__SESSION_LOCK__": {},
      "lastAccessedByUser": "2017-03-01 15:07:26.653+0000",
      "userContext": {
        "ssoSessionId": "as-d1342f-24werw2321-1dbc021d3e97",
        "username": "Jfallon",
        "fullName": "Jimmy Fallon",
        "employeeNumber": "42524",        
        "active": true,
        "passwordExpired": false,
        "securityGroups": [],
        "someclientUser": true,
      },
      "someclientSessionLastRefreshAt": [
        "2017-03-01 14:47:59.292+0000",
        "2017-03-01 14:47:59.615+0000",
        "2017-03-01 15:03:00.175+0000"
      ]
    },
    "id": "02F569117D8DB6DCD7DBFD7997421866",
    "lastAccessed": "2017-03-01 15:08:51.825+0000",
    "creationTime": "2017-03-01 14:47:59.292+0000"
  }
}
org.apache.jasper.JasperException: java.lang.RuntimeException: Failed to get a database connection
        at org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:549)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:470)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.Log4jMdcFilter.doFilter(Log4jMdcFilter.java:43)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.CacheFilter.doFilter(CacheFilter.java:58)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.SessionTimeoutFilter.doFilter(SessionTimeoutFilter.java:112)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
        at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:193)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Failed to get a database connection
        at net.somecompany.commons.db.ConnectionManager.getConnection(ConnectionManager.java:63)
        at net.somecompany.someclient.db.clubpulse.someclientNotifications.getUpdates(someclientClubNotifications.java:106)
        at org.apache.jsp.secure.jsp.getUpdates_jsp._jspService(getUpdates_jsp.java:76)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
        ... 28 more

Timeout error

[ERROR] [ajp-bio-8009-exec-13] [2017-03-01 15:09:24] [db.ConnectionManager] [Unexpected exception while getting a new connection]

*** Request Details ***
{
  "ipAddress": "22.33.44.56.123",
  "url": "https://someclient.somecompany.net/face/getUpdates.jsp",
  "queryString": "_\u003d1488380850504",
  "referrer": "https://someclient.somecompany.net/face/locations",
  "userAgent": "Mozilla/5.0 (iPad; CPU OS 10_2_1 like Mac OS X) AppleWebKit/602.4.6 (KHTML, like Gecko) Mobile/14D27",
  "attributes": {
    "jsCssCacheVersion": "1488171162647"
  },
  "parameters": {
    "_": "1488380850504"
  },
  "sessionData": {
    "data": {
      "javax.servlet.jsp.jstl.fmt.request.charset": "UTF-8",
      "__SESSION_LOCK__": {},
      "lastAccessedByUser": "2017-03-01 15:07:26.653+0000",
      "userContext": {
        "ssoSessionId": "425ce-8c21d378-44dbc0ef22-9fd75-18e797",
        "username": "JFallon",
        "fullName": "Jimmy Fallon Alberga",
       "fullName": "Jimmy Fallon",
            "employeeNumber": "42524",        
            "active": true,
            "passwordExpired": false,
            "securityGroups": [],
            "someclientUser": true,
          },
          "someclientSessionLastRefreshAt": [
            "2017-03-01 14:47:59.292+0000",
            "2017-03-01 14:47:59.615+0000",
            "2017-03-01 15:03:00.175+0000"
          ]
        },
        "id": "02F569117D8DB6DCD7DBFD7997421866",
        "lastAccessed": "2017-03-01 15:08:51.825+0000",
        "creationTime": "2017-03-01 14:47:59.292+0000"
      }
}
java.sql.SQLTimeoutException: Timeout after 30000ms of waiting for a connection.
        at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:228)
        at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:183)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:91)
        at net.somecompany.commons.db.ConnectionManager.getConnection(ConnectionManager.java:59)
        at net.somecompany.someclient.someclientClubNotifications.getInfo(someclientClubNotifications.java:106)
        at org.apache.jsp.secure.jsp.getUpdates_jsp._jspService(getUpdates_jsp.java:76)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.Log4jMdcFilter.doFilter(Log4jMdcFilter.java:43)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.CacheFilter.doFilter(CacheFilter.java:58)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at net.somecompany.someclient.servlets.SessionTimeoutFilter.doFilter(SessionTimeoutFilter.java:112)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
        at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:193)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)

EDIT 1 - I am aware of the AWS outage in US-EAST-1, but this problem persisted before the outage and even now, so it was not because of the AWS outage.

I have also verified that all our connections are closed properly.

1

When you say "~300 devices active at any given moment" I'm wondering if you are hitting connection limits.

What does "SELECT COUNT(*) FROM pg_stat_activity" return in a period where you are seeing this issue?

In addition, I'd look into I/O statistics, in particular I/O wait can be interesting. You can see this when enabling "Enhanced Monitoring" for your RDS instance.

It might also be useful to get some more statistics on the slow queries and their plans. You can look into using log_min_duration_statement or pg_stat_statements to retrieve details on slow queries.

Disclaimer: I'm the author of pganalyze, a PostgreSQL performance monitoring tool which might also help you in this scenario (we support fetching statistics from Postgres and Amazon RDS in particular to help you debug such issues).

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.