Hi Mark, > -----Original Message----- > From: Mark Thomas <ma...@apache.org> > Sent: Tuesday, May 28, 2024 3:42 AM > To: users@tomcat.apache.org > Subject: Re: Database Connection Requests Initiated but Not Sent on the Wire > (Some, Not All) > > Hi Eric, > > I have a some follow-up questions in-line. I have also read the other > messages in > this thread and added a couple of additional questions based on what I read in > those threads. > > > On 26/05/2024 02:58, Eric Robinson wrote: > > One of our hosting customers is a medical practice using a commercial EMR > running on tomcat+mysql. It has operated well for over a year, but users have > suddenly begun experiencing slowness for about an hour at the same time > every day. > > What time does this problem start? >
It typically starts around 9:15 am EDT and goes until around 10:30 am. > Does it occur every day of the week including weekends? > Most weekdays. There have been 1 or 2 weekdays when it seems that symptom inexplicably did not appear. I'm not sure about weekends, as the medical practice does not work on those days. > How does the slowness correlate to: > - request volume > - requests to any particular URL(s)? > - requests from any particular client IP? > - any other attribute of the request? > > (I'm trying to see if there is something about the requests that triggers the > issue.) > We have not seen anything stand out. There are no apparent spikes in request volume. The slowness appears to impact all parts of the system (meaning all URLs). It manifests for the customer, but we have also seen it when we connect to the app internally, behind the firewall and reverse proxy, directly to the tomcat server from a workstation connected to the same switch. > > During the slow times, we've done all the usual troubleshooting to catch the > problem in the act. The servers have plenty of power and are not overworked. > There are no slow database queries. Network connectivity is solid. Tomcat has > plenty of memory. The numbers of database connections, threads, questions, > queries, etc., remain steady, without spikes. There is no unusual disk > latency. > We have not found any maintenance tasks running during that timeframe. > > I would usually suggest taking three thread dumps approximately 5s apart and > then diffing them to try and spot "slow moving" threads. > > I see you have scripted trigger a thread dump when the slowness hits. If you > haven't already, please configure it to capture (at least) 3 dumps > ~5 seconds apart. > > (If we can spot the slow moving threads we might be able to identify what it > is > that makes them slow moving.) > We finished and implemented the script yesterday, so today will be the first day that it produces results. It watches the catalina.out file for stuck thread detection warnings. When the number of stuck threads exceeds a threshold, then it starts doing thread dumps every 60 seconds until the counts drops back down below the threshold. The users typically do not complain of slowness until the stuck thread count exceeds 20, and during that time the threads often take up to a minute or more to complete. It's too late today to change the timings, but if it does not produce any actionable intel, we can adjust them tonight. > > The customer has another load-balanced tomcat instance on a different > physical server, and the problem happens on that one, too. The servers were > upgraded with a new kernel and packages on 4/5/24, but the issue did not > appear until 5/6/24. The vendor enabled a new feature in the customer's > software, and the problem appeared the next day, but they subsequently > disabled the feature, and (reportedly) the problem did not go away. > > Have you confirmed that the feature really is disabled? Or was it just hidden? > The vendor claims that the feature uses a different server and does not send requests to the slow ones, so it has been re-enabled at the customer's request. We may ask them to disable it again until we get this issue resolved. > Has this feature been enabled for any other customers? If yes, have they > experienced similar issues? > > (It is suspicious that the issue occurred after the feature was disabled. I > wonder > if some elements of that change (e.g. a database > change) are still in place and causing issues.) > We agree that it is suspicious, but at this point we are forced to give it the side-eye. We're not aware of other customers being impacted, but (a) it's a new AI-based feature, so not many other customers have it, (b) it is enabled by the vendor directly, so we are not in the notification loop, and (c) the problem customer is large, with about 800 staff, whereas most other customers are much and might not trigger the symptom. Bottom line, we're not *sure*, but we think the feature is unrelated, but we'll ask them to disable it anyway. > > It is worth mentioning that the servers are multi-tenanted, with other > customers running the same medical application, but the others do not > experience the slowdowns, even though they are on the same servers. > > How does this customer compare, in terms of volume of requests, to other > customers that are not experiencing this issue. > This customer sends about 1.5 million requests to each load-balanced server during a typical production day. Most other customers send much less, often only a fraction of that. However, at least one customer sends about 2 million to the same server, and they don't see the problem. (I will check if they have the AI feature enabled.) > Is there anything unique or special about the customer experiencing the issue? > Do they have some custom settings no-one else uses? > > (I am trying to figure out if the issue is load related, customer specific or > something else). > Fair question, but it's a big application with thousands of internal configuration settings that could conceivably differ from other practices. There's no way for us to know. What we do know is that they are a medical office, so most of the settings would be close to those of other practices with the same medical specialties, and the app worked fine for them for a year. > > There are no unusual errors in the tomcat or database server logs, > > EXCEPT this one: Java.sql.DriverManager.getConnection > > Can we see the full stack trace please. > Here's one example. 24-May-2024 09:24:40.006 WARNING [Catalina-utility-1] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread [http-nio-3791-exec-19] (id=[10164]) has been active for [12,656] milliseconds (since [5/24/24 9:24 AM]) to serve the same request for [http://site791-rmu4adhn.chartwire.com/mobiledoc/jsp/webemr/scheduling/getEncountersJson.jsp?sessionDID=708281&TrUserId=708281&Device=webemr&ecwappprocessid=0&rnd2=0.058659668828765055×tamp=1716557066746&clientTimezone=America/New_York&pd=4cd7382a70a8a6888c39684b1ac372c676ef5893d0c4062ff2203ca695a1678d] and may be stuck (configured threshold for this StuckThreadDetectionValve is [5] seconds). There is/are [9] thread(s) in total that are monitored by this Valve and may be stuck. java.lang.Throwable at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1252) at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1220) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:348) at java.sql.DriverManager.isDriverAllowed(DriverManager.java:556) at java.sql.DriverManager.getConnection(DriverManager.java:661) at java.sql.DriverManager.getConnection(DriverManager.java:247) at com.ecw.dao.ECWDataSource.fetchConnection(ECWDataSource.java:112) at com.ecw.dao.ECWDataSource.getConnection(ECWDataSource.java:52) at catalog.Root.initConnection(Root.java:106) at catalog.Root.createDbConnection(Root.java:604) at com.ecw.scheduling.AppointmentSlotConfig.getDentalProceduresDescription(AppointmentSlotConfig.java:392) at com.ecw.scheduling.AppointmentSlotConfig.getApptDescription(AppointmentSlotConfig.java:185) at catalog.GetEventsForView.addEncounter(GetEventsForView.java:538) at catalog.GetEventsForView.addEncounters(GetEventsForView.java:494) at catalog.GetEventsForView.getEvents(GetEventsForView.java:191) at webemr.ResourceScheduleDAO.getEncounters(ResourceScheduleDAO.java:590) at org.apache.jsp.jsp.webemr.scheduling.getEncountersJson_jsp._jspService(getEncountersJson_jsp.java:233) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) at javax.servlet.http.HttpServlet.service(HttpServlet.java:623) at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:466) at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:379) at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:327) at javax.servlet.http.HttpServlet.service(HttpServlet.java:623) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:209) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at webemr.login.springsecurity.filters.RequestContextFilter.doFilter(RequestContextFilter.java:33) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at webemr.login.springsecurity.filters.ClientErrorMessageFilter.doFilter(ClientErrorMessageFilter.java:31) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at com.opensymphony.sitemesh.webapp.SiteMeshFilter.obtainContent(SiteMeshFilter.java:129) at com.opensymphony.sitemesh.webapp.SiteMeshFilter.doFilter(SiteMeshFilter.java:77) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at servlet.AccessController.doFilter(AccessController.java:393) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at servlet.EcwSession.validUserRequest(EcwSession.java:815) at servlet.EcwSession.validUserRequest(EcwSession.java:847) at servlet.EcwSession.doFilter(EcwSession.java:467) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:223) at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:217) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:223) at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:217) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:132) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.header.HeaderWriterFilter.doHeadersBefore(HeaderWriterFilter.java:82) at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:72) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:112) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) at webemr.login.springsecurity.filters.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:190) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at webemr.login.springsecurity.filters.CookieFilter.doFilter(CookieFilter.java:56) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at webemr.login.springsecurity.filters.ChecksumValidationFilter.doFilter(ChecksumValidationFilter.java:85) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) at org.apache.catalina.valves.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:185) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:670) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:926) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1790) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:750) > > During the periods of slowness, we see lots of those errors along with a > > large > spike in the number of stuck tomcat threads (from 1 or 2 to as high as 100). > It > seems obvious that the threads are stuck because tomcat is waiting on a > connection to the database. However, tcpdump shows that connectivity to the > database is perfect at the network and application layers. There are no > unanswered SYNs, no retransmissions, no half-open connections, no failures to > allocate TCP ports, no conntrack messages, and no other indications of system > resource exhaustion. Every time tomcat requests a connection to the DB, it > completes in less than 1 ms. Ten thousand connection attempts completed > successfully in about 15 seconds, with zero failures. > > It sounds like things might be getting stuck somewhere in or near the JDBC > driver. > > Can you provide the exact version of the JDBC driver you are using? > mysql-connector-java-5.1.49.jar > Can you provide the full database configuration from context.xml (or wherever > it is configured). Please redact sensitive information such as passwords. > The app has DB connection details in two places. First, it uses a database connection string in a .properties file, as follows. This string handles most connections to the DB. mobiledoc.DBUrl=jdbc:mysql://ha52a:5791 mobiledoc.DBName=mobiledoc_791?useSSL=false&zeroDateTimeBehavior=round&jdbcCompliantTruncation=false&cacheServerConfiguration=true&dumpQueriesOnException=true&tinyInt1isBit=false&useOldAliasMetadataBehavior=true&dontTrackOpenResources=true mobiledoc.DBUser=<redacted> mobiledoc.DBPassword=<redacted> It also has second DB config specifically for a drug database. <MediSpan> <!-- Log settings --> <Logging enabled="false"> <SQLQuery enabled="true" /> <ConstructorCall enabled="false" /> <FunctionCall enabled="false" /> <CustomLogFileLocation>c:\out.log</CustomLogFileLocation> </Logging> <!-- Medispan Content definitions --> <DataSource id="ecw" DataBase="medispan" /> <!-- DataSources --> <DataBase id="medispan"> <JNDIEnabled enabled="false" /> <INITIAL_CONTEXT_FACTORY>INSERT_CONTEXT_FACTORY</INITIAL_CONTEXT_FACTORY> <JNDI_URL>INSERT_JNDI_URL</JNDI_URL> <JNDI_USER_NAME>INSERT_USER_NAME</JNDI_USER_NAME> <JNDI_PASSWORD>INSERT_PASSWORD</JNDI_PASSWORD> <LOOKUP_NAME>INSERT_LOOKUP_NAME</LOOKUP_NAME> <DRIVER>com.mysql.jdbc.Driver</DRIVER> <URL>jdbc:mysql://dbclust54:5791/medispan?sessionVariables=wait_timeout=28800,interactive_timeout=28800</URL> <USER_NAME>redacted</USER_NAME> <PASSWORD>redacted</PASSWORD> <POOLSIZE>10</POOLSIZE> <TIMEOUT>5000</TIMEOUT> </DataBase> <XMLContent id="DIB310" dir="INSERT_CONTENT_DIR" /> <Images id="DIB310" dir="INSERT_IMAGE_DIR" /> <Cache> <Enabled>true</Enabled> <SecondsTillStale>0</SecondsTillStale> <LastUpdateInterval>1800</LastUpdateInterval> </Cache> </MediSpan> > > We are forced to conclude that some database connection requests are being > initiated but are not being sent on the wire. The problem seems to be in the > interaction between tomcat and the database driver, or in the driver itself. > > I agree. > > > Unfortunately, the application vendor is taking the "it's your > > infrastructure" position without providing any evidence or offering > > suggestions for configuration changes, > > I'm sorry to hear that. We'll do what we can to help. > We appreciate it. For the record, I'm not saying the problem isn't our infrastructure, but so far, we have not captured indications of that. I might have missed something. It wouldn't be the first time, so we'll keep looking. On the other hand, this would also not be the first time (or second, or third) the vendor made an unsupported claim about the infrastructure, but the problem turned out to be their code, and it was fixed in a later release. > > other than to deploy more tomcat instances, which is just shooting in the > dark. They don't know why the software is throwing > java.sql.DriverManager.getConnection errors (even though it's their code), and > they've relegated the investigation to us. > > I'd have to say that the evidence is pointing towards some sort of application > issue at this point. That said, just because the questions are currently > heading in > that direction we aren't blind to the possibility that the root cause might > be in > Tomcat. If the evidence starts pointing that way then that is where we will > look. > > When we have answers to the questions above, we might have enough evidence > to start asking more pointed questions of the application vendor. > > > Any advice from the community would be greatly appreciated. > > > > RHEL 8.9, kernel 4.18.0-513.18.1.el8_9.x86_64 Apache Tomcat/9.0.80, > > JVM 1.8.0_372-b07 > > Is that Tomcat 9.0.80 as provided by the ASF? If so, there are a number of > known > security vulnerabilities you should be (and probably are) aware of. There are > steps you can take to mitigate those without an upgrade - just wanted to make > sure they are on your radar. > We're aware. Unfortunately, we are faced with vendor constraints. They only officially support certain tomcat versions, so we address the issues the best we can with compensating controls. > > (The tomcat and JVM versions are the ones recommended by the vendor.) > > > > We're standing by to provide whatever other information the community may > need. > > Finally, if you consider any of the debugging information too sensitive to > share > on the public list, I am happy for you to send to directly to me and I can > share it > with any interested Tomcat committers. If you do need to do that, I'd > encourage > to to share a redacted version with the list if you can. There are lots of > very > experienced folks on the users list who can help who aren't Tomcat committers. > Will do, if it comes to that! > Mark > > > > > Thanks tons! > > > > -Eric > > > > > > > > Disclaimer : This email and any files transmitted with it are confidential > > and > intended solely for intended recipients. If you are not the named addressee > you > should not disseminate, distribute, copy or alter this email. Any views or > opinions presented in this email are solely those of the author and might not > represent those of Physician Select Management. Warning: Although Physician > Select Management has taken reasonable precautions to ensure no viruses are > present in this email, the company cannot accept responsibility for any loss > or > damage arising from the use of this email or attachments. > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org Disclaimer : This email and any files transmitted with it are confidential and intended solely for intended recipients. If you are not the named addressee you should not disseminate, distribute, copy or alter this email. Any views or opinions presented in this email are solely those of the author and might not represent those of Physician Select Management. Warning: Although Physician Select Management has taken reasonable precautions to ensure no viruses are present in this email, the company cannot accept responsibility for any loss or damage arising from the use of this email or attachments. --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
