Hello Andre, Yes sorry the logs files are not clear. We have so much traffic going through the Tomcat and many clients connecting which it seems to be logging for different sessions at different time. We really have no control to sort this out as the connections are simultaneous.
Our reordering of the logs and the entries listed may be correct. I cannot tell myself if it is linked to the same session. We tried to use Session IDs to add against the entries we make for servlet code but that somehow does not follow in order. As for your comment on web.xml and retriggering the redeployment of the web app folders, yes, I am wondering why this is happening if that is the case. There is a web.xml in each WEB-INF folder however nothing never change. Also, this is all it has in it below where it is just the servlet name and mapping. Can this really retrigger it if it never changes? <web-app xsi:schemaLocation="http://java.sun.com/xml/ns/j2ee http://java.sun.com/xml/ns/j2ee/web-app_2_4.xsd"; version="2.4"> <display-name>Peoplesoft Connector</display-name> <description>PeopleSoft Connector Applications.</description> <servlet> <servlet-name>PSConnectorServlet</servlet-name> <servlet-class>PSConnectorServlet</servlet-class> </servlet> <servlet-mapping> <servlet-name>PSConnectorServlet</servlet-name> <url-pattern>/servlet/PSConnectorServlet</url-pattern> </servlet-mapping> </web-app> Also, yes, autodeploy is equal to "True". I will check with my colleague to see if we can test with false because this will impact all web folders. Do you see any impact if this was "false"? Why is it defaulted to "true"? Thanks, Thone -----Original Message----- From: André Warnier [mailto:a...@ice-sa.com] Sent: Tuesday, January 13, 2015 2:04 PM To: Tomcat Users List Subject: Re: Slow HTTP Rquest via Tomcat Christopher Schultz wrote: > -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA256 > > Thone, > > On 1/13/15 1:05 PM, Thone Soungpanya wrote: >> Hello Andre, >> >> I do not think it is an DNS lookup issue but I'll check on it. >> >> Yes we actually have logs but it does not tell us much. We added >> additional logging in our servlet code to tell us when and what the >> code is doing. I have attached a log for 1 connection which took >> about 1 minute and 23 seconds to complete. I have eliminated all >> sensitive information with "XXXXXXXXXXXXXXXXXXXXXX". During this >> time, there would be other connections too simultaneously. >> >> Some information on the request: 1) HTTP request initiated at >> 16:11:06 to Tomcat. > > This is a very confusing log file... from latest-to-oldest. +10 > > Before #2 happens, Tomcat reloads. Many (all?) web applications were > re-loaded. Was that expected? > >> 2) Connection to Third Party System happened at 16:12:22. You can see >> it on line 38 with following text "2015-01-12 16:12:22,426 INFO >> 06E4074221FF93C2827079EBC2102847; begin request" > > Okay. > >> 3) Response back to Tomcat from Third Party System at 16:12:29 > > This does not appear in the log. > >> So it seems that between point#1 and point #2, there was about a 1 >> minute and 16 seconds delay before connection to the third party. >> Point #2 to Point #3 only took 7 seconds. >> >> Can you or anyone see what may be the issue from the logs? > Maybe if you provide clearer logs, having some real information allowing to distinguish one request processing sequence from another. > Tomcat is reloading in the middle of the request? Right, that's what it looks like. And not only this one time. From the (very difficult) look of it, it seems that this system is spending its time reloading its applications almost continuously. Using some nifty features of Notepad++, I have extracted and re-ordered what I believe are log lines relating to one webapp (and I don't really know for sure if this is one request, or several). See attached if it makes it, it's probably clearer. Otherwise, I have also pasted these log lines below. I have selected lines related to a webapp named "ps_1.5_8.53.10", and re-ordered them in a logical older-to-younger top-down sequence. Examining thse lines, we see : - at 2015-01-12 16:11:07,396 : what appears to be the beginning of a redeployment of that webapp - at 2015-01-12 16:11:08,108 (one second later) : what appears to be the beginning of a request to that webapp - at 2015-01-12 16:11:15,918 (7 seconds later), what seems to be the beginning of yet another redeployment of that webapp - at 2015-01-12 16:11:21,037, another request starting In-between, there are a lot of other lines apparently showing similar (other) webapps redeployments, and maybe other lines related to that same webapp, but all quite difficult to identify because there is no common marker. That logfile is very confusing, and as a result take this with a grain of salt, but I get the funny feeling that this webapp, when it responds to a request, may be modifying something (it's own WEB-INF/web.xml ?) in such a way that it triggers a re-deployment of that same very application by Tomcat, at each request. (And similarly for the other ones) For a start, does the <Host> tag of that Tomcat instance have an autodeploy="true" attribute ? (see in conf/server.xml). And if so, what about setting that attribute to "false", restarting this Tomcat, and looking at the symptoms again ? (and read : http://tomcat.apache.org/tomcat-8.0-doc/config/host.html#Standard_Implementation section : Automatic Application Deployment ) Appendix (also attached but the attachment may be stripped by the list) : Re-ordered selected log line : Line 1099: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10.war Line 1098: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10 Line 1097: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/conf/Catalina/localhost/ps_1.5_8.53.10.xml Line 1096: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/META-INF/context.xml Line 1095: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/conf/context.xml Line 1094: 2015-01-12 16:11:07,396 DEBUG Checking context[/ps_1.5_8.53.10] reload resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/web.xml Line 972: 2015-01-12 16:11:08,108 DEBUG The variable [uriBC] has value [/ps_1.5_8.53.10/servlet/PSConnectorServlet] Line 969: 2015-01-12 16:11:08,108 DEBUG Security checking request GET /ps_1.5_8.53.10/servlet/PSConnectorServlet Line 964: 2015-01-12 16:11:08,109 DEBUG --> Returning 'file:/usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/classes/pscn.properties' Line 963: 2015-01-12 16:11:08,109 DEBUG --> Returning 'file:/usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/classes/pscn.properties' Line 775: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10.war Line 774: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10 Line 773: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/conf/Catalina/localhost/ps_1.5_8.53.10.xml Line 772: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/META-INF/context.xml Line 771: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] redeploy resource /usr/local/tomcat-instance5/conf/context.xml Line 770: 2015-01-12 16:11:15,918 DEBUG Checking context[/ps_1.5_8.53.10] reload resource /usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/web.xml Line 587: 2015-01-12 16:11:21,037 DEBUG The variable [uriBC] has value [/ps_1.5_8.53.10/servlet/PSConnectorServlet] Line 584: 2015-01-12 16:11:21,038 DEBUG Security checking request GET /ps_1.5_8.53.10/servlet/PSConnectorServlet Line 579: 2015-01-12 16:11:21,038 DEBUG --> Returning 'file:/usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/classes/pscn.properties' Line 578: 2015-01-12 16:11:21,038 DEBUG --> Returning 'file:/usr/local/tomcat-instance5/webapps/ps_1.5_8.53.10/WEB-INF/classes/pscn.properties'
