- -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
