-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA256 Thone,
On 1/13/15 7:59 PM, Thone Soungpanya wrote: > 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"? See http://tomcat.apache.org/tomcat-7.0-doc/config/host.html and http://tomcat.apache.org/tomcat-7.0-doc/config/host.html#Automatic_Application_Deployment It defaults to true because it's not much overhead and most people want to allow automatic re-deployment of web applications. It's easily disabled. The real question is "why is Tomcat deciding to reload"? The only time Tomcat reloads for us (we run with autoDeploy set to default in production) is when we "touch" the META-INF/context.xml file. You should check the timestamps on your context.xml files (or appname.xml files, if you are placing those into CATALINA_BASE/conf/[engine]/[host]/[appname].xml) and/or your WAR files (or exploded WAR directories) in your appbase (defaults to CATALINA_BASE/webapps) to see if those timestamps are changing for some reason. Timestamps should be retained in ms since the epoch, so DST changes shouldn't have any effect (e.g. in March, your webapps won't automatically reload just because of clock adjustments). But, if the system time changes radically for some reason, it may trigger a reload or if the file dates change for some reason (I dunno... some weird NFS thing?) then you may also get a reload. I wonder if these occasional slow-downs are an artifact of reloading the web application in the middle of a request. - -chris > -----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' > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > -----BEGIN PGP SIGNATURE----- Version: GnuPG v1 Comment: GPGTools - http://gpgtools.org iQIcBAEBCAAGBQJUtq84AAoJEBzwKT+lPKRYU9cP/39kbBQBGgX/9LphqfzvF7z6 0WRGJXjxDrK5CIzjxTxDy30UUnl0lk09pjfe3UJuOaZtPe9UGx9rgdy1utHURurE uIs6Vs1doTX/kNACKJII4Ll/D1E2eFrE1SS/r3Q+kGmMOWI90Uq4OytZmCmZy/CU HG1oQuvzHvwZIjiCpa6ZG/AEddOCYNr+IrSsutjS73pGwn2oO/a2gMjWvFkUYOUg ymEiS9bKLvL9BEJg/CIntuntIvxlRw42pN3GzIE8dmlWf9mGypxmrJ9EyI9GFF49 3sHmlukvYiW20pRK6Mz+CDnDLX/MejhDHRPatT3RZRiK5+JHXW5APz9WokDR2571 SrSO2wCb3BaVYoYYKXLTvqG4/r2o8MeUucuCUe3DuEEUfVVjsSpYDLJHoZZWSF49 sh0Yl8vZnC3RGpNgf6fGkuJpSgSB8fhgnM0wRzluRp/8FOTq9Vi0dbXxQxM1UurU rXq4RcES+bWXy0F5+pXhWfxpA182QEdEMx/8lsAyk2HvunTtGBWQxTpsGiD26qmH z/V4a7Y/FJhAtQSwIdFe3dEhNin7cxBwJZh73fRfPvM8t38JROZwFskHp2CcipCQ rF/yIYWgUkQ3BUVB8VpT5J8Db+v/CZjb6RPP58YJSwOKEBtCKWXfxx6hQe66sPBG C+vIPwka7yy/x5+qpQlM =2Nej -----END PGP SIGNATURE----- --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
