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