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.