Re: very slow class loading on initial JSP/servlet request after restart

[Pieter Temmerman <pt...@sadiel.es>]

> Thanks, Juha.  Actually Pieter suggested it a little while ago, and I've been trying to get some information out of 
> strace.  The best I can do is to put strace in front of the java command that's inside catalina.sh.  That's the command 
> that shows with ps -ef when Tomcat is running.  BUT, I get nothing out of strace when I make page requests on a site, it 
> just shows output during Tomcat startup.  So, I've not figured out how to get strace to say what the JVM is during the 
> delay.  

Try this strace command:

strace -f -etrace=\!futex,gettimeofday,clock_gettime -p
PID_OF_TOMCAT_JAVA

where PID_OF_TOMCAT_JAVA is the PID of your Tomcat, duh! :)



---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

[André Warnier <aw...@ice-sa.com>]

Sam Hokin wrote:
> André Warnier wrote:
>> What in this directory path is (are) a symlink(s) ?
>> /home/sites/ims/jcms/webapps/ROOT/WEB-INF/classes/org/apache/jsp/test6_jsp.class 
> 
> 
> There are no symlinks in that path.

Then the question is : why is that thing doing lstat's ?
(I mean in the trace list that you posted)

> 
>> And how is this different from the other 2 systems that work fine ?
> 
> It differs in no known way, other than being different hardware.
One more mystery then.
If on the other systems, you do the same trace, does it show the same 
sequence of lstat,access,stat ... ?


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

[Sam Hokin <sa...@ims.net>]

André Warnier wrote:
> What in this directory path is (are) a symlink(s) ?
> /home/sites/ims/jcms/webapps/ROOT/WEB-INF/classes/org/apache/jsp/test6_jsp.class 

There are no symlinks in that path.

> And how is this different from the other 2 systems that work fine ?

It differs in no known way, other than being different hardware.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request afterrestart

[André Warnier <aw...@ice-sa.com>]

Caldarale, Charles R wrote:
>> From: Sam Hokin [mailto:sam@ims.net]
>> Subject: Re: very slow class loading on initial JSP/servlet
>> request afterrestart
>>
>> http://www.ims.net/media/strace-test6-stall.txt
> 
> So what's going on during the frequent 11-second gaps?  (Was Rosemary Woods here?)

They are not only frequent, they are also totally regular.  Looks like a 
regular gap of 10 s + some fraction, that looks like 10 or 11 just 
because of the logfile stamp resolution.


> 
> Might want to redo the strace with the -T option to show the time spent inside each system call.
> 
>> During the Tomcat stall phase there are thousands
>> and thousands of stat64, access, lstat64 calls to
>> the same class files (and directories above those
>> files) across pages on all four sites.

Actually it is totally regular : stat, access, lstat, stat, then 10.xxx 
delay, then again stat, access, lstat, stat, 10 seconds +.
What in this directory path is (are) a symlink(s) ?
/home/sites/ims/jcms/webapps/ROOT/WEB-INF/classes/org/apache/jsp/test6_jsp.class
and to what does it (they) point ?
And how is this different from the other 2 systems that work fine ?



---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

RE: very slow class loading on initial JSP/servlet request afterrestart

["Caldarale, Charles R" <Ch...@unisys.com>]

> From: Sam Hokin [mailto:sam@ims.net]
> Subject: Re: very slow class loading on initial JSP/servlet
> request afterrestart
>
> http://www.ims.net/media/strace-test6-stall.txt

So what's going on during the frequent 11-second gaps?  (Was Rosemary Woods here?)

Might want to redo the strace with the -T option to show the time spent inside each system call.

> During the Tomcat stall phase there are thousands
> and thousands of stat64, access, lstat64 calls to
> the same class files (and directories above those
> files) across pages on all four sites.

How many is "thousands and thousands"?  3,000 or 100,000?  It's not unusual to see lots of calls to the stat derivates; they should return extremely quickly.

 - Chuck


THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and is thus for use only by the intended recipient. If you received this in error, please contact the sender and delete the e-mail and its attachments from all computers.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

[Sam Hokin <sa...@ims.net>]

Pieter Temmerman wrote:
> Try this strace command:
> 
> strace -f -etrace=\!futex,gettimeofday,clock_gettime -p
> PID_OF_TOMCAT_JAVA
> 
> where PID_OF_TOMCAT_JAVA is the PID of your Tomcat, duh! :)

Thanks! That certainly did the trick.  The first time I ran strace against the Tomcat process, it brought Tomcat to a 
halt.  I had to restart it.

After the restart, it took an absolute eternity for the sites to respond to requests, as usual.  One thing that I 
haven't mentioned, by the way, is that all four sites begin to respond at the SAME TIME.  There appears to be something 
going on server-wide that finally resolves.  (There are currently four Host entries in server.xml, each of which having 
several Context entries, by the way.  Three hosts are on the same IP address, one has its own.)

During the startup stall phase, I requested my simple test JSP page.  strace revealed, as it did for all the other pages 
being requested on the server, repeated calls to stat64 and lstat64 of the SAME class files.  Here are the lines from 
strace while test6.jsp (precompiled into test6_jsp.class) was stalled:

http://www.ims.net/media/strace-test6-stall.txt

After I shut off strace (being convinced that it was hindering the server from getting done with its post-startup 
shenanigans), and the rest of the sites were finally responding to requests, I fired up strace again and requested 
test6.jsp, and got this:

http://www.ims.net/media/strace-test6-ok.txt

along with a successful HTTP response.  So: stat64; access; lstat64; stat64; read; read; read.  The class probably was 
already loaded from the previous stalled request.

During the Tomcat stall phase there are thousands and thousands of stat64, access, lstat64 calls to the same class files 
(and directories above those files) across pages on all four sites.

My next step is to set up a new instance on another port so I (hopefully) stop beating on the production sites with 
these diagnostics, and then do Mark's suggestion to import, one by one, the classes in my Java package to see if there 
is a particular one that is causing the delay.  I've tried that to some extent in the past and felt that the delay just 
increased linearly as I added more classes, but I can do it more methodically.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org